New issue
Advanced search Search tips
Starred by 2 users
Status: Untriaged
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment
-release: RootfsUpdateError: Update failed with unexpected update status: UPDATE_STATUS_IDLE'
Project Member Reported by drinkcat@chromium.org, Nov 28 Back to list
Seen on a few recent -release builds (all updating from R64-10164.0.0 to R64-10166.0.0):
https://luci-milo.appspot.com/buildbot/chromeos/eve-release/1136
https://luci-milo.appspot.com/buildbot/chromeos/gandof-release/1702
https://luci-milo.appspot.com/buildbot/chromeos/glimmer-release/1993
https://luci-milo.appspot.com/buildbot/chromeos/quawks-release/1997
https://luci-milo.appspot.com/buildbot/chromeos/snappy-release/1233
https://luci-milo.appspot.com/buildbot/chromeos/squawks-release/1995
https://luci-milo.appspot.com/buildbot/chromeos/tidus-release/1708
https://luci-milo.appspot.com/buildbot/chromeos/veyron_mighty-release/1713
https://luci-milo.appspot.com/buildbot/chromeos/wizpig-release/1719

e.g. for wizpig:

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/158947191-chromeos-test/chromeos6-row2-rack20-host9

2017/11/27 12:56:00.384 DEBUG|    cros_build_lib:0593| RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /tmp/ssh-tmpAqPLZb/testing_rsa root@chromeos6-row2-rack20-host9 -- update_engine_client --status
2017/11/27 12:56:00.708 DEBUG|    cros_build_lib:0642| (stdout):
LAST_CHECKED_TIME=1511816027
PROGRESS=0.345030
CURRENT_OP=UPDATE_STATUS_DOWNLOADING
NEW_VERSION=999999.0.0
NEW_SIZE=1026024186

2017/11/27 12:56:00.709 DEBUG|    cros_build_lib:0644| (stderr):
Warning: Permanently added 'chromeos6-row2-rack20-host9,100.115.131.39' (ED25519) to the list of known hosts.
Warning: Permanently added 'chromeos6-row2-rack20-host9,100.115.131.39' (ED25519) to the list of known hosts.
[1127/125559:INFO:update_engine_client.cc(508)] Querying Update Engine status...

2017/11/27 12:56:00.709 INFO |      auto_updater:0711| Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.345030
2017/11/27 12:56:10.720 DEBUG|    cros_build_lib:0593| RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /tmp/ssh-tmpAqPLZb/testing_rsa root@chromeos6-row2-rack20-host9 -- update_engine_client --status
2017/11/27 12:56:39.428 ERROR|     remote_access:0961| Error connecting to device chromeos6-row2-rack20-host9
2017/11/27 12:57:59.372 DEBUG|    cros_build_lib:0642| (stdout):
LAST_CHECKED_TIME=0
PROGRESS=0.000000
CURRENT_OP=UPDATE_STATUS_IDLE
NEW_VERSION=0.0.0.0
NEW_SIZE=0

The update engine suddenly goes from UPDATE_STATUS_DOWNLOADING to UPDATE_STATUS_IDLE, no idea why. AFAICT the DUT does not reboot (but I'm not fully sure as I can't find system logs...)
 
It is weird, I cannot see any system logs specially update engine logs in /var/log/update_engine. We probably have to find out why the logs aren't being gathered! update_engine logs can shed light on what could be the cause of the problem.
Cc: rspangler@chromium.org
Owner: caveh@chromium.org
Cc: pho...@chromium.org dgarr...@chromium.org
Comment 4 by caveh@chromium.org, Dec 7 (6 days ago)
the logs are under crashinfo.*/var/log once you drill down to the collected logs.

eve's update_engine.log has gems like:

Pending updates found. Abort.
ERROR: Failed to complete.

but there are additional errors from dbus, but they may be unrelated.

all the logs seem to get terminated (truncated?) after the 10% or 20% progress marker from the delta_performer.

there's nothing obvious in the logs that might explain this.


Comment 5 by ahassani@chromium.org, Dec 8 (5 days ago)
Cc: jrbarnette@chromium.org
Yeah, I don't know why I didn't see those logs the first time. Probably looking at the wrong place :/.

But, anyways, if you look at the eve logs, you can see this pattern:


From CrOS_update_100.115.230.132_16142.log update starts at:

2017/11/27 13:01:06.089 DEBUG|    cros_build_lib:0593| RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /tmp/ssh-tmpWszFjN/testing_rsa root@100.115.230.132 -- update_engine_client -check_for_update '-omaha_url=http://127.0.0.1:39029/update/pregenerated'


And here it gets the wrong update engine status:
2017/11/27 13:01:16.680 DEBUG|    cros_build_lib:0593| RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /tmp/ssh-tmpWszFjN/testing_rsa root@100.115.230.132 -- update_engine_client --status
2017/11/27 13:01:49.352 ERROR|     remote_access:0961| Error connecting to device 100.115.230.132
2017/11/27 13:02:18.972 DEBUG|    cros_build_lib:0642| (stdout):
LAST_CHECKED_TIME=0
PROGRESS=0.000000
CURRENT_OP=UPDATE_STATUS_IDLE
NEW_VERSION=0.0.0.0
NEW_SIZE=0


But the last update_engine log that exists and has the logs for the actual update starts with this:

[1127/130216:INFO:main.cc(113)] Chrome OS Update Engine starting
[1127/130216:INFO:boot_control_chromeos.cc(127)] Booted from slot 0 (slot A) of 2 slots present on disk /dev/mmcblk0
[1127/130216:INFO:real_system_state.cc(74)] Booted non-official build.

which shows that at some point the update_engine was rebooted, so it started a new log with a new state UPDATE_STATUS_IDLE.
It seems like that happened two times. The update_engine.20171127-130058 is the actual log that starts the update check at 13:01:06. Then it gets the following error:

[1127/130108:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.NetworkProxyServiceInterface.ResolveProxy: object_path= /org/chromium/NetworkProxyService: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.NetworkProxyService was not provided by any .service files
[1127/130108:ERROR:http_proxy.cc(27)] org.chromium.NetworkProxyService D-Bus call to ResolveProxy failed

But that error doesn't necessary means any problem. It just means that the chrome was shut down (which provision script does it).

Then it exits here before finishing the update:
[1127/130114:INFO:main.cc(128)] Chrome OS Update Engine terminating with exit code 0
[1127/130114:INFO:action_processor.cc(58)] ActionProcessor: aborted OmahaRequestAction
[1127/130114:INFO:base_message_loop.cc(75)] Leaking 4 canceled tasks.

and the new update engine log update_engine.20171127-130204 exits at: 
[1127/130211:INFO:main.cc(128)] Chrome OS Update Engine terminating with exit code 0
[1127/130211:INFO:base_message_loop.cc(75)] Leaking 3 canceled tasks.

and then you can see the last update_engine log which shows the delta_performer stopped in the middle.

I have no idea at this point why that two update_engine reboots happened. It seems they were forced externally and it was not an update_engine crash. But I cannot find the source of reboot either.
I'm wondering if this is related to crbug.com/777969

Comment 6 by r...@chromium.org, Dec 8 (4 days ago)
Components: Internals>Installer
Sign in to add a comment