SC4S Syslog server update fails during download with "context canceled"

[AndrewTilley]

I'm doing an SC4S update from version v3.37.0 to v3.38.1 for my on premises Ubuntu syslog server.

We updated about 4 months ago to 3.37.0 and it went fine, we have a documented procedure for carrying these out.

I've tried updating to 3.38.1 and am having issues with the service not starting, the download seems to fail with very little clue as to why.

I've already checked the release notes and there's nothing special between them.  I've compared the sc4s.service file to see if there's any major changes in 3.38.1 and it looks to be the same as 3.37.0 in documentation.

I'm literally going in sc4s.service and changing the SC4S_IMAGE line to ghcr.io/splunk/splunk-connect-for-syslog/container3:v3.38.1 then restarting services, that's it.

I can see in the journalctl logs that the new image is being pulled down and then when it gets part way through the log says "download complete" and then a generic error of "context canceled" (SIC):

Nov 03 08:31:01 MyServerName systemd[1]: Starting SC4S Container...
Nov 03 08:31:02 MyServerName docker[2604029]: v3.38.1: Pulling from splunk/splunk-connect-for-syslog/container3
Nov 03 08:31:02 MyServerName docker[2604029]: 1f3e46996e29: Already exists
Nov 03 08:31:02 MyServerName docker[2604029]: 43e669825c0d: Already exists
Nov 03 08:31:02 MyServerName docker[2604029]: 0f6a50746658: Already exists
Nov 03 08:31:02 MyServerName docker[2604029]: ffaa003a54cd: Already exists
Nov 03 08:31:02 MyServerName docker[2604029]: 4f4fb700ef54: Already exists
Nov 03 08:31:02 MyServerName docker[2604029]: 7f851dbb2712: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 171f08867219: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 98e96a686927: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 36c3e217ce5c: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: abf9970f46bd: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 7da629cf3ba8: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 36c3e217ce5c: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: abf9970f46bd: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 9b5c2cb70a69: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 9097246a7cbd: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: eaf8d7c2bb31: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 2f9c7657006a: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 7da629cf3ba8: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 9097246a7cbd: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: eaf8d7c2bb31: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 9b5c2cb70a69: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 4f4fb700ef54: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 2f9c7657006a: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 77aa29863de9: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 4f4fb700ef54: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: dcab84c29da0: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 190f6fadb66e: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 9a5b2ff247fa: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: e5d9f5f1d236: Pulling fs layer
Nov 03 08:31:02 MyServerName docker[2604029]: 77aa29863de9: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: dcab84c29da0: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 190f6fadb66e: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 9a5b2ff247fa: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: e5d9f5f1d236: Waiting
Nov 03 08:31:02 MyServerName docker[2604029]: 171f08867219: Verifying Checksum
Nov 03 08:31:02 MyServerName docker[2604029]: 171f08867219: Download complete
Nov 03 08:31:02 MyServerName docker[2604029]: 98e96a686927: Verifying Checksum
Nov 03 08:31:02 MyServerName docker[2604029]: 98e96a686927: Download complete
Nov 03 08:31:02 MyServerName docker[2604029]: abf9970f46bd: Verifying Checksum
Nov 03 08:31:02 MyServerName docker[2604029]: abf9970f46bd: Download complete
Nov 03 08:31:03 MyServerName docker[2604029]: 7da629cf3ba8: Verifying Checksum
Nov 03 08:31:03 MyServerName docker[2604029]: 7da629cf3ba8: Download complete
Nov 03 08:31:03 MyServerName docker[2604029]: 9b5c2cb70a69: Download complete
Nov 03 08:31:03 MyServerName docker[2604029]: 9097246a7cbd: Verifying Checksum
Nov 03 08:31:03 MyServerName docker[2604029]: 9097246a7cbd: Download complete
Nov 03 08:31:03 MyServerName docker[2604029]: eaf8d7c2bb31: Verifying Checksum
Nov 03 08:31:03 MyServerName docker[2604029]: eaf8d7c2bb31: Download complete
Nov 03 08:31:04 MyServerName docker[2604029]: 2f9c7657006a: Verifying Checksum
Nov 03 08:31:04 MyServerName docker[2604029]: 2f9c7657006a: Download complete
Nov 03 08:31:04 MyServerName docker[2604029]: 4f4fb700ef54: Verifying Checksum
Nov 03 08:31:04 MyServerName docker[2604029]: 4f4fb700ef54: Download complete
Nov 03 08:31:04 MyServerName docker[2604029]: 77aa29863de9: Verifying Checksum
Nov 03 08:31:04 MyServerName docker[2604029]: 77aa29863de9: Download complete
Nov 03 08:31:04 MyServerName docker[2604029]: dcab84c29da0: Download complete
Nov 03 08:31:04 MyServerName docker[2604029]: 190f6fadb66e: Verifying Checksum
Nov 03 08:31:04 MyServerName docker[2604029]: 190f6fadb66e: Download complete
Nov 03 08:31:05 MyServerName docker[2604029]: 9a5b2ff247fa: Verifying Checksum
Nov 03 08:31:05 MyServerName docker[2604029]: 9a5b2ff247fa: Download complete
Nov 03 08:31:05 MyServerName docker[2604029]: e5d9f5f1d236: Download complete
Nov 03 08:31:15 MyServerName docker[2604029]: 36c3e217ce5c: Verifying Checksum
Nov 03 08:31:15 MyServerName docker[2604029]: 36c3e217ce5c: Download complete
Nov 03 08:31:15 MyServerName docker[2604029]: 36c3e217ce5c: Verifying Checksum
Nov 03 08:31:15 MyServerName docker[2604029]: 36c3e217ce5c: Download complete
Nov 03 08:32:01 MyServerName docker[2604029]: context canceled
Nov 03 08:32:01 MyServerName systemd[1]: sc4s.service: Control process exited, code=exited, status=1/FAILURE
Nov 03 08:32:01 MyServerName systemd[1]: sc4s.service: Failed with result 'exit-code'.
Nov 03 08:32:01 MyServerName systemd[1]: Stopped SC4S Container.

It then repeats exactly  this process of downloading the image and failing, with this error, every minute roughly. I'm unable to complete the update as a result and had to rollback to 3.37.0 to get things running again.

I did my secondary server first last Friday and it took 10 minutes longer than it does normally normal but it worked successfully.  I've pulled the logs for the secondary server to have a look and can see that it actually did the same thing before it successfully verified the download and completed.

It looks like the problem comes at the download for 36c3e217ce5c as I can see the failures come after "download complete" for this.  On the secondary, after 30 minutes of failing here it suddenly does this retry:

Oct 31 09:35:08 MyServerName docker[2415488]: 36c3e217ce5c: Download complete
Oct 31 09:35:33 MyServerName docker[2415488]: 7f851dbb2712: Retrying in 5 seconds
Oct 31 09:35:34 MyServerName docker[2415488]: 7f851dbb2712: Retrying in 4 seconds
Oct 31 09:35:35 MyServerName docker[2415488]: 7f851dbb2712: Retrying in 3 seconds
Oct 31 09:35:36 MyServerName docker[2415488]: 7f851dbb2712: Retrying in 2 seconds
Oct 31 09:35:37 MyServerName docker[2415488]: 7f851dbb2712: Retrying in 1 second
Oct 31 09:35:43 MyServerName docker[2415488]: 7f851dbb2712: Verifying Checksum
Oct 31 09:35:43 MyServerName docker[2415488]: 7f851dbb2712: Download complete
Oct 31 09:35:50 MyServerName docker[2415488]: 7f851dbb2712: Pull complete
Oct 31 09:35:51 MyServerName docker[2415488]: 171f08867219: Pull complete
Oct 31 09:35:51 MyServerName docker[2415488]: 98e96a686927: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 36c3e217ce5c: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: abf9970f46bd: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 7da629cf3ba8: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 9b5c2cb70a69: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 9097246a7cbd: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: eaf8d7c2bb31: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 2f9c7657006a: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 4f4fb700ef54: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 77aa29863de9: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: dcab84c29da0: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 190f6fadb66e: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: 9a5b2ff247fa: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: e5d9f5f1d236: Pull complete
Oct 31 09:35:52 MyServerName docker[2415488]: Digest: sha256:940a908b6bbb1cbcb4198faecebdb63ae75928843bfe4f2c210c037fb223950b
Oct 31 09:35:52 MyServerName docker[2415488]: Status: Downloaded newer image for ghcr.io/splunk/splunk-connect-for-syslog/container3:v3.38.1
Oct 31 09:35:52 MyServerName docker[2415488]: ghcr.io/splunk/splunk-connect-for-syslog/container3:v3.38.1
Oct 31 09:35:53 MyServerName systemd[1]: Started SC4S Container.

I can't just leave the primary server running like this in the hope it works, I already waited an hour.

Anyone seen this or has any ideas?