coreos / bugs

Issue tracker for CoreOS Container Linux
https://coreos.com/os/eol/
146 stars 30 forks source link

update-engine.service not finding available update (1632.3.0 -> 1688.5.3) #2394

Closed lblackstone closed 6 years ago

lblackstone commented 6 years ago

Issue Report

Bug

Container Linux Version

1632.3.0 / 1688.5.3

Environment

What hardware/cloud provider/hypervisor is being used to run Container Linux? HP ProLiant SE4255e / OpenStack private cloud / KVM

Expected Behavior

update-engine.service should find available update and automatically upgrade.

Actual Behavior

The available update was not detected until running update_engine_client -check_for_update manually.

See below.

Reproduction Steps

???

Other Information

This node was part of a Kubernetes cluster that is running the Container Linux Update Operator v0.5.0

We noticed that one node in the cluster had upgraded successfully, but the other nodes were still running the previous version. I didn't see anything suspicious in the operator/update-agent logs, so I checked the update-engine.service on one of the nodes that had not upgraded.

After manually triggering the update check on that node, it detected the available update, and the upgrade process completed normally. The remaining nodes in the cluster still are not detecting the available update.

``` Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.562868 3253 prefs.cc:51] certificate-report-to-send-update not present in /var/lib/update_engine/prefs Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.563096 3253 prefs.cc:51] certificate-report-to-send-download not present in /var/lib/update_engine/prefs Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.563688 3253 omaha_request_params.cc:59] Current group set to stable Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.564254 3253 update_attempter.cc:483] Already updated boot flags. Skipping. Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.564265 3253 update_attempter.cc:626] Scheduling an action processor start. Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.564330 3253 action_processor.cc:36] ActionProcessor::StartProcessing: OmahaRequestAction Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.564734 3253 omaha_request_action.cc:245] Posting an Omaha request to https://public.update.core-os.net/v1/update/ Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.564744 3253 omaha_request_action.cc:246] Request: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.564788 3253 libcurl_http_fetcher.cc:48] Starting/Resuming transfer Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.565012 3253 libcurl_http_fetcher.cc:164] Setting up curl options for HTTPS Apr 04 19:14:31 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:31.565346 3253 libcurl_http_fetcher.cc:427] Setting up timeout source: 1 seconds. Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.572999 3253 libcurl_http_fetcher.cc:240] HTTP response code: 200 Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575045 3253 libcurl_http_fetcher.cc:297] Transfer completed (200), 267 bytes downloaded Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575078 3253 omaha_request_action.cc:592] Omaha request response: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575574 3253 omaha_request_action.cc:386] No update. Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575616 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished OmahaRequestAction, starting OmahaResponseHandlerAction Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575629 3253 omaha_response_handler_action.cc:36] There are no updates. Aborting. Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575645 3253 action_processor.cc:68] ActionProcessor::ActionComplete: OmahaResponseHandlerAction action failed. Aborting processing. Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575654 3253 action_processor.cc:73] ActionProcessor::ActionComplete: finished last action of type OmahaResponseHandlerAction Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575662 3253 update_attempter.cc:290] Processing Done. Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575697 3253 update_attempter.cc:326] No update. Apr 04 19:14:32 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:14:32.575745 3253 update_check_scheduler.cc:74] Next update check in 45m18s Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.831246 3253 dbus_service.cc:57] Attempting interactive update Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.832885 3253 update_attempter.cc:263] New update check requested Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.834138 3253 omaha_request_params.cc:59] Current group set to stable Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.834656 3253 update_attempter.cc:483] Already updated boot flags. Skipping. Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.834676 3253 update_attempter.cc:626] Scheduling an action processor start. Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.834771 3253 action_processor.cc:36] ActionProcessor::StartProcessing: OmahaRequestAction Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.835038 3253 omaha_request_action.cc:245] Posting an Omaha request to https://public.update.core-os.net/v1/update/ Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.835053 3253 omaha_request_action.cc:246] Request: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.835081 3253 libcurl_http_fetcher.cc:48] Starting/Resuming transfer Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.835300 3253 libcurl_http_fetcher.cc:164] Setting up curl options for HTTPS Apr 04 19:23:07 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:07.835644 3253 libcurl_http_fetcher.cc:427] Setting up timeout source: 1 seconds. Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.547930 3253 libcurl_http_fetcher.cc:240] HTTP response code: 200 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.551518 3253 libcurl_http_fetcher.cc:297] Transfer completed (200), 767 bytes downloaded Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.551563 3253 omaha_request_action.cc:592] Omaha request response: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552021 3253 omaha_request_action.cc:424] Omaha Response manifest version = 1688.5.3 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552050 3253 omaha_request_action.cc:447] Found 1 url(s) Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552083 3253 omaha_request_action.cc:483] Processing first of 1 package(s) Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552091 3253 omaha_request_action.cc:490] Omaha Response package name = update.gz Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552105 3253 omaha_request_action.cc:502] Url0: https://update.release.core-os.net/amd64-usr/1688.5.3/update.gz Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552121 3253 omaha_request_action.cc:514] Payload size = 359881084 bytes Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552146 3253 omaha_request_action.cc:538] Found 1 action(s). Processing the postinstall action. Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552175 3253 payload_state.cc:51] Resetting all persisted state as this is a new response Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552183 3253 payload_state.cc:359] Current Response Signature = Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: NumURLs = 1 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Url0 = https://update.release.core-os.net/amd64-usr/1688.5.3/update.gz Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Payload Size = 359881084 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Payload Sha256 Hash = vzIrXJjRRfjruMCXBjlQFxK/amQ9CSY79rLTkqEgAXM= Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Is Delta Payload = 0 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Max Failure Count Per Url = 10 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: Disable Payload Backoff = 1 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552551 3253 payload_state.cc:380] Payload Attempt Number = 0 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552634 3253 payload_state.cc:403] Current URL Index = 0 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552690 3253 payload_state.cc:424] Current URL (Url0)'s Failure Count = 0 Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552789 3253 payload_state.cc:286] Resetting backoff expiry time as payload backoff is disabled Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552814 3253 payload_state.cc:451] Backoff Expiry Time = 01/01/70 00:00:00 UTC Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552868 3253 payload_state.cc:202] Payload backoff logic is disabled. Can proceed with the download Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552933 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished OmahaRequestAction, starting OmahaResponseHandlerAction Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552943 3253 omaha_response_handler_action.cc:43] Using Url0 as the download url this time Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.552986 3253 prefs.cc:51] update-state-next-operation not present in /var/lib/update_engine/prefs Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: E0404 19:23:09.552999 3253 payload_processor.cc:491] prefs->GetInt64(kPrefsUpdateStateNextOperation, &next_operation) && next_operation != kUpdateStateOperationInvalid && next_operation > 0 failed. Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.553966 3253 omaha_response_handler_action.cc:85] Using this install plan: Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.553987 3253 install_plan.cc:53] InstallPlan: , new_update, url: https://update.release.core-os.net/amd64-usr/1688.5.3/update.gz, payload size: 359881084, payload hash: vzIrXJjRRfjruMCXBjlQFxK/amQ9CSY79rLTkqEgAXM=, partition_path: /dev/vda4, kernel_path: /boot/coreos/vmlinuz-b, pcr_policy_path: /var/lib/update_engine/pcrs-b.zip, old_partition_path: /dev/vda3, old_kernel_path: /boot/coreos/vmlinuz-a Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.554637 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished OmahaResponseHandlerAction, starting FilesystemCopierAction Apr 04 19:23:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:09.554967 3253 filesystem_copier_action.cc:296] Filesystem size: 1073741824 Apr 04 19:23:26 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:26.545949 3253 filesystem_copier_action.cc:274] Hash: cq18k/rzCGZuRu7wuH2JKAQ0P30lavr8Lk+AHAEYgUg= Apr 04 19:23:26 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:26.546234 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished FilesystemCopierAction, starting KernelCopierAction Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:27.245889 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished KernelCopierAction, starting OmahaRequestAction Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:27.246083 3253 omaha_request_action.cc:245] Posting an Omaha request to https://public.update.core-os.net/v1/update/ Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:27.246094 3253 omaha_request_action.cc:246] Request: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:27.246214 3253 libcurl_http_fetcher.cc:48] Starting/Resuming transfer Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:27.280437 3253 libcurl_http_fetcher.cc:164] Setting up curl options for HTTPS Apr 04 19:23:27 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:27.280728 3253 libcurl_http_fetcher.cc:427] Setting up timeout source: 1 seconds. Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.581813 3253 libcurl_http_fetcher.cc:240] HTTP response code: 200 Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.584048 3253 libcurl_http_fetcher.cc:297] Transfer completed (200), 767 bytes downloaded Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.584084 3253 omaha_request_action.cc:592] Omaha request response: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.584110 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished OmahaRequestAction, starting DownloadAction Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.584122 3253 install_plan.cc:53] InstallPlan: , new_update, url: https://update.release.core-os.net/amd64-usr/1688.5.3/update.gz, payload size: 359881084, payload hash: vzIrXJjRRfjruMCXBjlQFxK/amQ9CSY79rLTkqEgAXM=, partition_path: /dev/vda4, kernel_path: /boot/coreos/vmlinuz-b, pcr_policy_path: /var/lib/update_engine/pcrs-b.zip, old_partition_path: /dev/vda3, old_kernel_path: /boot/coreos/vmlinuz-a Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.600407 3253 update_attempter.cc:408] Download status: active Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.600457 3253 multi_range_http_fetcher.cc:30] starting first transfer Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.600476 3253 multi_range_http_fetcher.cc:58] starting transfer of range 0+? Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.600486 3253 libcurl_http_fetcher.cc:48] Starting/Resuming transfer Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.600554 3253 libcurl_http_fetcher.cc:164] Setting up curl options for HTTPS Apr 04 19:23:28 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:28.600711 3253 libcurl_http_fetcher.cc:427] Setting up timeout source: 1 seconds. Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.528442 3253 prefs.cc:51] update-server-cert-1-2 not present in /var/lib/update_engine/prefs Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.529712 3253 prefs.cc:51] update-server-cert-1-1 not present in /var/lib/update_engine/prefs Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.530266 3253 prefs.cc:51] update-server-cert-1-0 not present in /var/lib/update_engine/prefs Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.626036 3253 update_attempter.cc:430] Downloaded 193/359881084 bytes (0%) Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.633975 3253 payload_processor.cc:39] PartitionInfo new_partition_info sha256: DcjJrGHmHFom3H8FzCTS9fMFqw+gVApw4+EoHhltkDI= size: 1073741824 Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.644232 3253 payload_processor.cc:226] Starting to apply update payload operations Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.673853 3253 payload_processor.cc:282] Completed 1/1066 operations (0%) Apr 04 19:23:29 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:23:29.680574 3253 payload_processor.cc:282] Completed 2/1066 operations (0%) ... Apr 04 19:24:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:09.923534 3253 payload_processor.cc:319] Extracted signature data of size 528 at 359818393 Apr 04 19:24:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:09.923696 3253 libcurl_http_fetcher.cc:240] HTTP response code: 200 Apr 04 19:24:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:09.927165 3253 libcurl_http_fetcher.cc:297] Transfer completed (200), 359881084 bytes downloaded Apr 04 19:24:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:09.927289 3253 multi_range_http_fetcher.cc:151] Received transfer complete. Apr 04 19:24:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:09.927367 3253 multi_range_http_fetcher.cc:108] TransferEnded w/ code 200 Apr 04 19:24:09 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:09.927434 3253 multi_range_http_fetcher.cc:142] Done w/ all transfers Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.168239 3253 update_attempter.cc:408] Download status: inactive Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.168325 3253 payload_processor.cc:327] Verifying delta payload using public key: /usr/share/update_engine/update-payload-key.pub.pem Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.184273 3253 payload_signer.cc:254] signature size = 528 Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.199940 3253 payload_state.cc:70] Payload downloaded successfully Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.199975 3253 payload_state.cc:250] Incrementing the payload attempt number Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.199983 3253 payload_state.cc:380] Payload Attempt Number = 1 Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200152 3253 payload_state.cc:286] Resetting backoff expiry time as payload backoff is disabled Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200182 3253 payload_state.cc:451] Backoff Expiry Time = 01/01/70 00:00:00 UTC Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200467 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished DownloadAction, starting OmahaRequestAction Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200546 3253 omaha_request_action.cc:245] Posting an Omaha request to https://public.update.core-os.net/v1/update/ Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200558 3253 omaha_request_action.cc:246] Request: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200570 3253 libcurl_http_fetcher.cc:48] Starting/Resuming transfer Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200680 3253 libcurl_http_fetcher.cc:164] Setting up curl options for HTTPS Apr 04 19:24:10 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:10.200995 3253 libcurl_http_fetcher.cc:427] Setting up timeout source: 1 seconds. Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:11.542888 3253 libcurl_http_fetcher.cc:240] HTTP response code: 200 Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:11.545542 3253 libcurl_http_fetcher.cc:297] Transfer completed (200), 767 bytes downloaded Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:11.545713 3253 omaha_request_action.cc:592] Omaha request response: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:11.546454 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished OmahaRequestAction, starting FilesystemCopierAction Apr 04 19:24:11 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:11.546515 3253 filesystem_copier_action.cc:294] Filesystem size: 1073741824 Apr 04 19:24:20 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:20.979676 3253 filesystem_copier_action.cc:274] Hash: DcjJrGHmHFom3H8FzCTS9fMFqw+gVApw4+EoHhltkDI= Apr 04 19:24:20 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:20.979974 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished FilesystemCopierAction, starting KernelVerifierAction Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.249899 3253 kernel_verifier_action.cc:74] Kernel size: 43288240 Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.249967 3253 kernel_verifier_action.cc:75] Kernel hash: BwMVO2SvZCAgQnc9ZUfxwqWTWV/UAvNJHDp6RYp8KOg= Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.249994 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished KernelVerifierAction, starting PCRPolicyPostAction Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.250015 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished PCRPolicyPostAction, starting PostinstallRunnerAction Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.985020 3253 subprocess.cc:46] Subprocess output: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: start size part contents Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: 2367488 2097152 4 Label: "USR-B" Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Type: Alias for coreos-rootfs Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: UUID: E03DD35C-7C2D-4A47-B3FE-27F15780A57C Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Attr: priority=2 tries=1 successful=0 Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: COREOS_RELEASE_VERSION=1688.5.3 Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: COREOS_RELEASE_BOARD=amd64-usr Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: COREOS_RELEASE_APPID={e96281a6-d1af-4bde-9a0a-97b76e56dc57} Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Setup USR-B (/dev/vda4) for next boot. Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.985069 3253 postinstall_runner_action.cc:83] Postinst command succeeded Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.991796 3253 action_processor.cc:82] ActionProcessor::ActionComplete: finished PostinstallRunnerAction, starting OmahaRequestAction Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.991930 3253 omaha_request_action.cc:245] Posting an Omaha request to https://public.update.core-os.net/v1/update/ Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.991940 3253 omaha_request_action.cc:246] Request: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.991955 3253 libcurl_http_fetcher.cc:48] Starting/Resuming transfer Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.992206 3253 libcurl_http_fetcher.cc:164] Setting up curl options for HTTPS Apr 04 19:24:21 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:21.992465 3253 libcurl_http_fetcher.cc:427] Setting up timeout source: 1 seconds. Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.556664 3253 libcurl_http_fetcher.cc:240] HTTP response code: 200 Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.559065 3253 libcurl_http_fetcher.cc:297] Transfer completed (200), 767 bytes downloaded Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.559105 3253 omaha_request_action.cc:592] Omaha request response: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.559125 3253 action_processor.cc:65] ActionProcessor::ActionComplete: finished last action of type OmahaRequestAction Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.559136 3253 action_processor.cc:73] ActionProcessor::ActionComplete: finished last action of type OmahaRequestAction Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.559150 3253 update_attempter.cc:290] Processing Done. Apr 04 19:24:23 shanec-kubernetes-master-0 update_engine[3253]: I0404 19:24:23.570987 3253 update_attempter.cc:316] Update successfully applied, waiting to reboot. Apr 04 19:25:27 shanec-kubernetes-master-0 systemd[1]: Stopping Update Engine... Apr 04 19:25:27 shanec-kubernetes-master-0 systemd[1]: update-engine.service: Main process exited, code=exited, status=1/FAILURE Apr 04 19:25:27 shanec-kubernetes-master-0 systemd[1]: update-engine.service: Failed with result 'exit-code'. Apr 04 19:25:27 shanec-kubernetes-master-0 systemd[1]: Stopped Update Engine. -- Reboot -- ```
arithx commented 6 years ago

@lblackstone : Container Linux updates are rolled out over the fleet at a limited rate. Running update_engine_client -check_for_update manually ignores the rate limiting and performs the update immediately.

lblackstone commented 6 years ago

Thanks @arithx!

Are there any public docs that cover the rate limiting? I found https://github.com/coreos/tectonic-forum/issues/150 after your comment, but couldn't find any details on how this is configured (client vs server side, etc).

arithx commented 6 years ago

The rate limiting is set on the CoreUpdate side, here's a doc for the server side https://coreos.com/products/coreupdate/docs/latest/getting-started.html#group.

It's also briefly mentioned in https://coreos.com/os/docs/latest/update-strategies.html#manually-triggering-an-update from the perspective of the client side.

lblackstone commented 6 years ago

Ok, as far as I can tell, we're not running CoreUpdate. These machines aren't part of any managed subscription, and updateservicectl does not appear to be installed.

Is any sort of global rate limiting expected?

Also, I found another cluster exhibiting the same behavior, and noticed that neither one of them updated to 1688.4.0 either. The clusters have been running for several days, and that update has been available since March 27, so I would have expected them to have updated by now.

arithx commented 6 years ago

@lblackstone: CoreUpdate is what we also run for the public update server.

Global rate limiting is expected.

1688.4.0 was only available via the public update server for a small period of time due to the free magic grub issue (more info here: https://groups.google.com/forum/#!topic/coreos-user/5ihE2cKuYck). Updates for 1688.4.0 were paused which did not allow even manual updates and eventually removed from the update server.

bgilbert commented 6 years ago

We're currently rolling out 1688.5.3 at a fairly low rate, so it's not surprising that your machines haven't all updated yet.

lblackstone commented 6 years ago

Great, thanks for clarifying, and the quick responses!

For future reference, is there any way to see current rate limits for the public update server?

arithx commented 6 years ago

Not to my knowledge, cc @sdemos

sdemos commented 6 years ago

that is correct, rate limits are not exposed publically.

lblackstone commented 6 years ago

I think it would be useful to expose that info somehow, but that's probably out of scope for this issue.

Closing since the observed behavior was confirmed to be expected.