Upgrade of flatcar to 3760.2.0 with update-engine fails when behind a proxy #1332
Description
We have a number of flatcar nodes using a proxy to download images. When update-engine tries to upgrade to the latest release the download seems to work fine, but when the PostInstallRunnerAction starts it fails to connect to update.release.flatcar-linux.net.
We have set the dropin config for update-engine:
[Service]
Environment=ALL_PROXY="http://webproxy-nais.nav.no:8088"
We have also tried to set the proxy settings system-wide as described here: https://www.flatcar.org/docs/latest/setup/systemd/environment-variables/#system-wide-environment-variables
The error is still present and we are unable to upgrade any further. Do you have a workaround for this or are we missing some configuration? There have been no notable changes to our setup for quite some time, the issue was probably introduced with 3602.2.3.
/etc/flatcar/update.conf:
GROUP=stable
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624277 4129 payload_state.cc:251] Incrementing the payload attempt number
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624281 4129 payload_state.cc:381] Payload Attempt Number = 2
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624428 4129 payload_state.cc:287] Resetting backoff expiry time as payload backoff is disabled
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624440 4129 payload_state.cc:452] Backoff Expiry Time = 01/01/70 00:00:00 UTC
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624580 4129 action_processor.cc:82] ActionProcessor::ActionComplete: finished DownloadAction, starting OmahaRequestAction
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624611 4129 omaha_request_action.cc:268] Posting an Omaha request to https://public.update.flatcar-linux.net/v1/update/
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624615 4129 omaha_request_action.cc:269] Request: <?xml version="1.0" encoding="UTF-8"?>
Jan 24 22:01:17 hostname update_engine[4129]: <request protocol="3.0" version="update_engine-0.4.10" updaterversion="update_engine-0.4.10" installsource="scheduler" ismachine="1">
Jan 24 22:01:17 hostname update_engine[4129]: <os version="Chateau" platform="CoreOS" sp="3602.2.3_x86_64"></os>
Jan 24 22:01:17 hostname update_engine[4129]: <app appid="{e96281a6-d1af-4bde-9a0a-97b76e56dc57}" version="3602.2.3" track="stable" bootid="{0c288430-2504-4db4-913a-8c3de52afd07}" oem="vmware" oemversion="11.2.5" alephversion="2905.2.3" machineid="dbff85b41ae14f41bde761eefbdafaac" machinealias="" lang="en-US" board="amd64-usr" hardware_class="" delta_okay="false" >
Jan 24 22:01:17 hostname update_engine[4129]: <event eventtype="14" eventresult="1"></event>
Jan 24 22:01:17 hostname update_engine[4129]: </app>
Jan 24 22:01:17 hostname update_engine[4129]: </request>
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624620 4129 libcurl_http_fetcher.cc:47] Starting/Resuming transfer
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624764 4129 libcurl_http_fetcher.cc:174] Setting up curl options for HTTPS
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.624938 4129 libcurl_http_fetcher.cc:449] Setting up timeout source: 1 seconds.
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.769488 4129 libcurl_http_fetcher.cc:263] HTTP response code: 200
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.770923 4129 libcurl_http_fetcher.cc:320] Transfer completed (200), 231 bytes downloaded
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.770946 4129 omaha_request_action.cc:619] Omaha request response: <?xml version="1.0" encoding="UTF-8"?>
Jan 24 22:01:17 hostname update_engine[4129]: <response protocol="3.0" server="nebraska"><daystart elapsed_seconds="0"></daystart><app appid="{e96281a6-d1af-4bde-9a0a-97b76e56dc57}" status="ok"><event status="ok"></event></app></response>
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.770953 4129 action_processor.cc:82] ActionProcessor::ActionComplete: finished OmahaRequestAction, starting FilesystemCopierAction
Jan 24 22:01:17 hostname update_engine[4129]: I0124 22:01:17.770973 4129 filesystem_copier_action.cc:294] Filesystem size: 1073741824
Jan 24 22:01:23 hostname update_engine[4129]: I0124 22:01:23.149430 4129 filesystem_copier_action.cc:274] Hash: ttNJ6YwsqWKlqLt/pcLAhsONp1NWCZHqIMD65c3iM5s=
Jan 24 22:01:23 hostname update_engine[4129]: I0124 22:01:23.149493 4129 action_processor.cc:82] ActionProcessor::ActionComplete: finished FilesystemCopierAction, starting KernelVerifierAction
Jan 24 22:01:23 hostname update_engine[4129]: I0124 22:01:23.401779 4129 kernel_verifier_action.cc:74] Kernel size: 54769888
Jan 24 22:01:23 hostname update_engine[4129]: I0124 22:01:23.401810 4129 kernel_verifier_action.cc:75] Kernel hash: 4IcV6qI5IexEPIv5prcx1+AMz3+VPZ33h2W6oRdJvYk=
Jan 24 22:01:23 hostname update_engine[4129]: I0124 22:01:23.401821 4129 action_processor.cc:82] ActionProcessor::ActionComplete: finished KernelVerifierAction, starting PCRPolicyPostAction
Jan 24 22:01:23 hostname update_engine[4129]: I0124 22:01:23.401835 4129 action_processor.cc:82] ActionProcessor::ActionComplete: finished PCRPolicyPostAction, starting PostinstallRunnerAction
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.762491 4129 subprocess.cc:43] Subprocess status: 1
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.762519 4129 subprocess.cc:46] Subprocess output:
Jan 24 22:02:23 hostname update_engine[4129]: Falling back to release-server for extension 'oem-vmware'
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 6 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 7 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 7 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 0 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 0 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 6 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 0 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 0 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 0 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 0 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 8 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 3 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 5 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 1 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 6 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 2 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: curl: (7) Failed to connect to update.release.flatcar-linux.net port 443 after 4 ms: Couldn't connect to server
Jan 24 22:02:23 hostname update_engine[4129]: Failed to download required OEM update payload
Jan 24 22:02:23 hostname update_engine[4129]: E0124 22:02:23.762545 4129 postinstall_runner_action.cc:94] Postinst command failed with code: 1
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776257 4129 action_processor.cc:68] ActionProcessor::ActionComplete: PostinstallRunnerAction action failed. Aborting processing.
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776275 4129 action_processor.cc:73] ActionProcessor::ActionComplete: finished last action of type PostinstallRunnerAction
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776280 4129 update_attempter.cc:302] Processing Done.
Jan 24 22:02:23 hostname update_engine[4129]: E0124 22:02:23.776726 4129 update_attempter.cc:615] Update failed.
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776748 4129 payload_state.cc:97] Updating payload state for error code: 5 (kActionCodePostinstallRunnerError)
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776753 4129 payload_state.cc:178] Not incrementing URL index or failure count for this error
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776820 4129 action_processor.cc:36] ActionProcessor::StartProcessing: OmahaRequestAction
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776871 4129 omaha_request_action.cc:268] Posting an Omaha request to https://public.update.flatcar-linux.net/v1/update/
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776875 4129 omaha_request_action.cc:269] Request: <?xml version="1.0" encoding="UTF-8"?>
Jan 24 22:02:23 hostname update_engine[4129]: <request protocol="3.0" version="update_engine-0.4.10" updaterversion="update_engine-0.4.10" installsource="scheduler" ismachine="1">
Jan 24 22:02:23 hostname update_engine[4129]: <os version="Chateau" platform="CoreOS" sp="3602.2.3_x86_64"></os>
Jan 24 22:02:23 hostname update_engine[4129]: <app appid="{e96281a6-d1af-4bde-9a0a-97b76e56dc57}" version="3602.2.3" track="stable" bootid="{0c288430-2504-4db4-913a-8c3de52afd07}" oem="vmware" oemversion="11.2.5" alephversion="2905.2.3" machineid="dbff85b41ae14f41bde761eefbdafaac" machinealias="" lang="en-US" board="amd64-usr" hardware_class="" delta_okay="false" >
Jan 24 22:02:23 hostname update_engine[4129]: <event eventtype="3" eventresult="0" errorcode="5"></event>
Jan 24 22:02:23 hostname update_engine[4129]: </app>
Jan 24 22:02:23 hostname update_engine[4129]: </request>
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.776880 4129 libcurl_http_fetcher.cc:47] Starting/Resuming transfer
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.777199 4129 libcurl_http_fetcher.cc:174] Setting up curl options for HTTPS
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.777374 4129 libcurl_http_fetcher.cc:449] Setting up timeout source: 1 seconds.
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.916100 4129 libcurl_http_fetcher.cc:263] HTTP response code: 200
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918339 4129 libcurl_http_fetcher.cc:320] Transfer completed (200), 231 bytes downloaded
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918377 4129 omaha_request_action.cc:619] Omaha request response: <?xml version="1.0" encoding="UTF-8"?>
Jan 24 22:02:23 hostname update_engine[4129]: <response protocol="3.0" server="nebraska"><daystart elapsed_seconds="0"></daystart><app appid="{e96281a6-d1af-4bde-9a0a-97b76e56dc57}" status="ok"><event status="ok"></event></app></response>
Jan 24 22:02:23 hostname update_engine[4129]: E0124 22:02:23.918397 4129 omaha_request_action.cc:626] HTTP reported success but Omaha reports an error.
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918406 4129 action_processor.cc:65] ActionProcessor::ActionComplete: finished last action of type OmahaRequestAction
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918411 4129 action_processor.cc:73] ActionProcessor::ActionComplete: finished last action of type OmahaRequestAction
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918416 4129 update_attempter.cc:302] Processing Done.
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918424 4129 update_attempter.cc:306] Error event sent.
Jan 24 22:02:23 hostname update_engine[4129]: I0124 22:02:23.918437 4129 update_check_scheduler.cc:74] Next update check in 44m17s```