PatchKit CDN breaking

[uklans]

PatchKit CDN breaking

[MathewBurnett]

Its not uncommon for various clients to display strange speeds when using lancache as an intermediate. Its worth looking at your firewalls traffic if you have that data to see if its is pulling at full speed. Its also worth downloading something, removing it and then downloading again to see if you can pull a full cached version much faster.

[PeaceDealer]

The issue it it fails about half way.

The game im using to test with gets around half way and then it throws an "unknown error". Only occurs when using the cache.

[MathewBurnett]

the other thing to check is whether it downloads anything over HTTP on port 80 or is it all HTTPS, in which case it wont cache anyway and you are just putting traffic through the SNI Proxy whne you can avoid that.

[PeaceDealer]

I checked with fiddler. They do most over http.

[MathewBurnett]

what does your cache access.log or error.log show? anything?

[PeaceDealer]

Resposnes for
docker exec -it lancache_monolithic_1_c61f954232ab cat /var/log/nginx/access.log
docker exec -it lancache_monolithic_1_c61f954232ab cat /var/log/nginx/error.log
both return empty.

From what I can tell, PathKit's business model is based on bandwidth consumption, so I'm thinking they've actively deployed measures against caching.

[MathewBurnett]

either there is nothing in the log because its all requesting HTTPS or because you have the containers set up wrong. However there don't seem to be any obvious requests in the SNI proxy log you have shown either.

[PeaceDealer]

I just ran the setup guide, following the quick-guide on https://lancache.net/, again.
If i run nslookup cdn.patchkit.net it returns the IP address of my caching server, and as far as i can tell, its caching from steam right.
Is there any debug flag i need to enable for it to write to the logs?

[MathewBurnett]

if you ran the docker compose setup then your logs will appear in ./lancache relative to where you have the start script (unless you cahnged it). In order to get something logged you would have to attempt to download something from the cdn from a machine using the lanacache.

[PeaceDealer]

Okay, I just realized the binding of the logs folders.
Last few lines of access.log

[steam] 10.245.100.164 / - - - [06/Mar/2020:10:10:45 +0000] "GET /depot/731/chunk/b517b3d1785eb57837747b21246736f44fffe43c HTTP/1.1" 200 143168 "-" "Valve/Steam HTTP Client 1.0" "MISS" "cache13-ams1.steamcontent.com" "-"
[steam] 10.245.100.164 / - - - [06/Mar/2020:10:10:45 +0000] "GET /depot/731/chunk/9746abd2ba9e29ba2ebef5bec0d5b96745d7ccb9 HTTP/1.1" 200 864048 "-" "Valve/Steam HTTP Client 1.0" "MISS" "cache16-ams1.steamcontent.com" "-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:02 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=0-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:07 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=1048576-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:12 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=2097152-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:17 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=3145728-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:22 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=4194304-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:27 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=5242880-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:33 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=6291456-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:38 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=7340032-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:43 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=8388608-"
[patchkit] 10.245.100.164 / - - - [06/Mar/2020:10:11:48 +0000] "GET /v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4 HTTP/1.1" 200 1048576 "-" "Mozilla/5.0" "HIT" "cdn.patchkit.net" "bytes=9437184-"

and this is the only line in error.log
2020/03/06 10:00:23 [error] 1358#1358: *17 ipv6check-http.steamcontent.com could not be resolved (3: Host not found), client: 10.245.100.164, server: , request: "GET /server-status HTTP/1.1", host: "ipv6check-http.steamcontent.com"

[MathewBurnett]

The hit indicates that those files are already cached

[PeaceDealer]

So, it is caching the files, but after some time the client throws an error

[PeaceDealer]

I have an output from the client's log.

########## Fri Mar 6 11:15:52 2020 - Log start
[INFO]     Fri Mar 6 11:15:52 2020 - Successful lock on  ".lock"
[INFO]     Fri Mar 6 11:15:52 2020 - Updating the patcher
[INFO]     Fri Mar 6 11:15:52 2020 - Getting the latest app version for app  "9e04617386ce3791f5ad8ff39be86d9f"
[INFO]     Fri Mar 6 11:15:52 2020 - Executing GET  "1/apps/9e04617386ce3791f5ad8ff39be86d9f/versions/latest/id"
[INFO]     Fri Mar 6 11:15:52 2020 - Downloading from  "https://api2.patchkit.net/1/apps/9e04617386ce3791f5ad8ff39be86d9f/versions/latest/id"  with timeout  10000
[INFO]     Fri Mar 6 11:15:53 2020 - Checking whether patcher is installed.
[INFO]     Fri Mar 6 11:15:53 2020 - Installation file doesn't exists -  "C:/Users/jola/Desktop/Phoenix/patcher/install_info"
[INFO]     Fri Mar 6 11:15:53 2020 - Installation not found.
[INFO]     Fri Mar 6 11:15:53 2020 - Getting the content summary for app  "9e04617386ce3791f5ad8ff39be86d9f"  version  55
[INFO]     Fri Mar 6 11:15:53 2020 - Executing GET  "1/apps/9e04617386ce3791f5ad8ff39be86d9f/versions/55/content_summary"
[INFO]     Fri Mar 6 11:15:53 2020 - Downloading from  "https://api2.patchkit.net/1/apps/9e04617386ce3791f5ad8ff39be86d9f/versions/55/content_summary"  with timeout  10000
[INFO]     Fri Mar 6 11:15:54 2020 - Getting the content urls for app  "9e04617386ce3791f5ad8ff39be86d9f"  version  55
[INFO]     Fri Mar 6 11:15:54 2020 - Executing GET  "1/apps/9e04617386ce3791f5ad8ff39be86d9f/versions/55/content_urls"
[INFO]     Fri Mar 6 11:15:54 2020 - Downloading from  "https://api2.patchkit.net/1/apps/9e04617386ce3791f5ad8ff39be86d9f/versions/55/content_urls"  with timeout  10000
[INFO]     Fri Mar 6 11:15:54 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:15:54 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  0 - -1
[WARNING]  Fri Mar 6 11:15:59 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #2 expected hash 8b22607c got d5be6eb8
[INFO]     Fri Mar 6 11:15:59 2020 - Written  2  chunks out of  55
[INFO]     Fri Mar 6 11:15:59 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:15:59 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  1048576 - -1
[WARNING]  Fri Mar 6 11:15:59 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #4 expected hash 8ce3d8fe got d5be6eb8
[INFO]     Fri Mar 6 11:15:59 2020 - Written  4  chunks out of  55
[INFO]     Fri Mar 6 11:15:59 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:15:59 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  2097152 - -1
[WARNING]  Fri Mar 6 11:16:04 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #6 expected hash 52021816 got d5be6eb8
[INFO]     Fri Mar 6 11:16:04 2020 - Written  6  chunks out of  55
[INFO]     Fri Mar 6 11:16:04 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:04 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  3145728 - -1
[WARNING]  Fri Mar 6 11:16:09 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #8 expected hash 92cdfe2c got d5be6eb8
[INFO]     Fri Mar 6 11:16:09 2020 - Written  8  chunks out of  55
[INFO]     Fri Mar 6 11:16:09 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:09 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  4194304 - -1
[WARNING]  Fri Mar 6 11:16:09 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #10 expected hash 3cdedeed got d5be6eb8
[INFO]     Fri Mar 6 11:16:09 2020 - Written  10  chunks out of  55
[INFO]     Fri Mar 6 11:16:09 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:09 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  5242880 - -1
[WARNING]  Fri Mar 6 11:16:14 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #12 expected hash 25a2c14b got d5be6eb8
[INFO]     Fri Mar 6 11:16:14 2020 - Written  12  chunks out of  55
[INFO]     Fri Mar 6 11:16:14 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:14 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  6291456 - -1
[WARNING]  Fri Mar 6 11:16:19 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #14 expected hash 9212dac2 got d5be6eb8
[INFO]     Fri Mar 6 11:16:19 2020 - Written  14  chunks out of  55
[INFO]     Fri Mar 6 11:16:19 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:19 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  7340032 - -1
[WARNING]  Fri Mar 6 11:16:24 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #16 expected hash 77cdddee got d5be6eb8
[INFO]     Fri Mar 6 11:16:24 2020 - Written  16  chunks out of  55
[INFO]     Fri Mar 6 11:16:24 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:24 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  8388608 - -1
[WARNING]  Fri Mar 6 11:16:24 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #18 expected hash ff2d285b got d5be6eb8
[INFO]     Fri Mar 6 11:16:24 2020 - Written  18  chunks out of  55
[INFO]     Fri Mar 6 11:16:24 2020 - Downloading chunked file from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")
[INFO]     Fri Mar 6 11:16:24 2020 - Downloading from  QUrl("http://cdn.patchkit.net/v1/resources/9f654966-c9de-4e89-aa70-17522ad03ad4")  with range  9437184 - -1
[WARNING]  Fri Mar 6 11:16:29 2020 - Invalid chunk:  ChunkVerificationException: Failed to verify chunk #20 expected hash dba84c4a got d5be6eb8
[INFO]     Fri Mar 6 11:16:29 2020 - Written  20  chunks out of  55
[WARNING]  Fri Mar 6 11:16:29 2020 - Chunked download did not succeed
[INFO]     Fri Mar 6 11:16:29 2020 - Unlocking the lock file.
[CRITICAL] Fri Mar 6 11:16:29 2020 - UpdateFailed: Failed to update
[INFO]     Fri Mar 6 11:16:29 2020 - Asking the user to either retry or go into offline mode
[DEBUG]    Fri Mar 6 11:16:29 2020 - Initializing path.
[DEBUG]    Fri Mar 6 11:16:29 2020 - Path set to  "C:/Users/jola/Desktop/Phoenix"
[INFO]     Fri Mar 6 11:16:29 2020 - Checking whether patcher is installed.
[INFO]     Fri Mar 6 11:16:29 2020 - Installation file doesn't exists -  "C:/Users/jola/Desktop/Phoenix/patcher/install_info"
[INFO]     Fri Mar 6 11:16:29 2020 - Asking the user if Launcher should retry.
[INFO]     Fri Mar 6 11:16:29 2020 - Asking if launcher should retry
[INFO]     Fri Mar 6 11:16:31 2020 - Answer was  false
[INFO]     Fri Mar 6 11:16:31 2020 - Close window request.
[INFO]     Fri Mar 6 11:16:31 2020 - Allowing the window to be closed.

[VibroAxe]

Looks like you have a corrupted chunk, or patchkit have changed a file in place. Delete you cache folder in monolithic and try again. See if it makes it all the way through?

[MathewBurnett]

The range requests in your log are very odd. It looks like they are doing something specific with chunk sizes. The lancache solution slices by 1m as a default. My theory could be confirmed if you stop slicing altogether (this isn't ideal as way of caching ). You could then try and increase the slice size above the chunk size by trial and error until it works.

However If the upstream is changing files in place there is a possibility it wont work at all.

[PeaceDealer]

@VibroAxe
I have tried to remove the cache, and the access log now registers as "MISS", but patchkit still fails.

@MathewBurnett
I have set CACHE_SLICE_SIZE=0 in the .env, same errors.

[MathewBurnett]

assuming that the same strange with range 0 - -1 requests are made and the monolithic logs shows byte ranges with only a start number i'm afraid we are out of ideas.

[PeaceDealer]

Yep, the log still ends the rage with -1.
As i mentioned earlier, I think it could be intentional from their side, as their business model seems to be based around bandwidth consumption.

Should we just close it here, and mark as cantfix?

[MathewBurnett]

seems reasonable, if you do learn anything new don't be afraid to come back and tell us about ir