[0928/140001.034938] [INFO:main.cc(55)] A/B Update Engine starting
[0928/140001.053396] [INFO:boot_control_android.cc(68)] Loaded boot control hidl hal.
[0928/140001.092284] [ERROR:metrics_utils.cc(368)] time_to_reboot is negative - system_updated_at: 1/2/1970 21:00:07 GMT
[0928/140001.092809] [INFO:delta_performer.cc(1394)] Resetting recorded hash for prepared partitions.
[0928/140001.092898] [INFO:update_attempter_android.cc(1089)] Scheduling CleanupPreviousUpdateAction.
[0928/140001.092925] [INFO:action_processor.cc(51)] ActionProcessor: starting CleanupPreviousUpdateAction
[0928/140001.092940] [INFO:cleanup_previous_update_action.cc(149)] Starting/resuming CleanupPreviousUpdateAction
[0928/140001.093100] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 1 for WaitBootCompleted
[0928/140003.094570] [INFO:cleanup_previous_update_action.cc(112)] Executing task 1
[0928/140003.094847] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 3 for WaitBootCompleted
[0928/140005.097107] [INFO:cleanup_previous_update_action.cc(112)] Executing task 3
[0928/140005.097168] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 4 for WaitBootCompleted
[0928/140007.098689] [INFO:cleanup_previous_update_action.cc(112)] Executing task 4
[0928/140007.098754] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 5 for WaitBootCompleted
[0928/140009.101234] [INFO:cleanup_previous_update_action.cc(112)] Executing task 5
[0928/140009.101303] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 6 for WaitBootCompleted
[0928/140011.102720] [INFO:cleanup_previous_update_action.cc(112)] Executing task 6
[0928/140011.102908] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 7 for WaitBootCompleted
[0928/140013.105120] [INFO:cleanup_previous_update_action.cc(112)] Executing task 7
[0928/140013.105186] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 8 for WaitBootCompleted
[0928/140015.106334] [INFO:cleanup_previous_update_action.cc(112)] Executing task 8
[0928/140015.106395] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 9 for WaitBootCompleted
[0928/140017.107427] [INFO:cleanup_previous_update_action.cc(112)] Executing task 9
[0928/140017.107507] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 10 for WaitBootCompleted
[0928/140019.109681] [INFO:cleanup_previous_update_action.cc(112)] Executing task 10
[0928/140019.109781] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 11 for WaitBootCompleted
[0928/140021.110777] [INFO:cleanup_previous_update_action.cc(112)] Executing task 11
[0928/140021.110866] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 12 for WaitBootCompleted
[0928/140023.113460] [INFO:cleanup_previous_update_action.cc(112)] Executing task 12
[0928/140023.115460] [INFO:cleanup_previous_update_action.cc(189)] Boot completed, waiting on markBootSuccessful()
[0928/140023.120055] [INFO:snapshot.cpp(3353)] EnsureMetadataMounted does nothing in Android mode.
[0928/140023.122322] [INFO:snapshot_stats.cpp(37)] Read merge statistics file failed: No such file or directory
[0928/140023.124146] [INFO:cleanup_previous_update_action.cc(261)] Waiting for any previous merge request to complete. This can take up to several minutes.
[0928/140023.135710] [INFO:snapshot.cpp(1458)] Update state is being processed while booting at target slot, taking no action.
[0928/140023.137122] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 2
[0928/140023.138361] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 2
[0928/140023.139626] [INFO:cleanup_previous_update_action.cc(397)] Attempting to initiate merge.
[0928/140023.161105] [INFO:snapshot.cpp(835)] Successfully switched snapshot device to a merge target: odm_b
[0928/140023.173820] [INFO:snapshot.cpp(835)] Successfully switched snapshot device to a merge target: vendor_b
[0928/140023.196052] [INFO:snapshot.cpp(835)] Successfully switched snapshot device to a merge target: product_b
[0928/140023.209928] [INFO:snapshot.cpp(835)] Successfully switched snapshot device to a merge target: system_b
[0928/140023.245352] [INFO:snapshot.cpp(835)] Successfully switched snapshot device to a merge target: system_ext_b
[0928/140023.256154] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for odm_b returned: 3
[0928/140023.261327] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 3
[0928/140023.273691] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 3
[0928/140023.274714] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140023.285466] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 3
[0928/140023.286692] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140023.288147] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140023.300117] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 13 for WaitForMerge
[0928/140025.302626] [INFO:cleanup_previous_update_action.cc(112)] Executing task 13
[0928/140025.310535] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for odm_b returned: 3
[0928/140025.312135] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 3
[0928/140025.313512] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 3
[0928/140025.319819] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140025.334629] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 3
[0928/140025.335507] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140025.336304] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140025.337855] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 12%.
[0928/140025.350970] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 14 for WaitForMerge
[0928/140024.851102] [INFO:cleanup_previous_update_action.cc(112)] Executing task 14
[0928/140024.860161] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for odm_b returned: 3
[0928/140024.861506] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 3
[0928/140024.863098] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 3
[0928/140024.866841] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140024.882581] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 3
[0928/140024.884787] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140024.885787] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140024.887096] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 23%.
[0928/140024.901174] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 15 for WaitForMerge
[0928/140026.903451] [INFO:cleanup_previous_update_action.cc(112)] Executing task 15
[0928/140027.941721] Waited one second for gsiservice (is service started? are binder threads started and available?)
[0928/140027.957751] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for odm_b returned: 5
[0928/140027.962268] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 3
[0928/140027.963785] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 3
[0928/140027.965805] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140027.967506] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 3
[0928/140027.972949] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140027.981340] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140027.983380] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 40%.
[0928/140027.985377] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 16 for WaitForMerge
[0928/140029.988010] [INFO:cleanup_previous_update_action.cc(112)] Executing task 16
[0928/140029.990433] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 3
[0928/140029.992136] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 3
[0928/140030.002179] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140030.009459] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 3
[0928/140030.010772] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140030.012363] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140030.014536] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 51%.
[0928/140030.026020] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 17 for WaitForMerge
[0928/140032.028008] [INFO:cleanup_previous_update_action.cc(112)] Executing task 17
[0928/140032.031565] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 3
[0928/140032.034121] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 3
[0928/140032.056678] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140032.058648] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 3
[0928/140032.060344] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140032.061576] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140032.076426] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 62%.
[0928/140032.078070] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 18 for WaitForMerge
[0928/140034.080299] [INFO:cleanup_previous_update_action.cc(112)] Executing task 18
[0928/140034.209858] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for vendor_b returned: 5
[0928/140034.262558] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for product_b returned: 5
[0928/140034.265942] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140034.365479] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_ext_b returned: 5
[0928/140034.368721] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140034.370489] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140034.372761] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 72%.
[0928/140034.375024] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 19 for WaitForMerge
[0928/140036.377577] [INFO:cleanup_previous_update_action.cc(112)] Executing task 19
[0928/140036.387767] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140036.393370] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140036.400115] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140036.403974] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 77%.
[0928/140036.406355] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 20 for WaitForMerge
[0928/140038.409509] [INFO:cleanup_previous_update_action.cc(112)] Executing task 20
[0928/140038.413560] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140038.417062] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140038.420599] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140038.424564] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 83%.
[0928/140038.427906] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 21 for WaitForMerge
[0928/140040.430129] [INFO:cleanup_previous_update_action.cc(112)] Executing task 21
[0928/140040.434621] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140040.437805] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140040.441014] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140040.443393] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 88%.
[0928/140040.445872] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 22 for WaitForMerge
[0928/140042.448392] [INFO:cleanup_previous_update_action.cc(112)] Executing task 22
[0928/140042.454243] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140042.458045] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140042.461242] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140042.465302] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 93%.
[0928/140042.469131] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 23 for WaitForMerge
[0928/140044.472917] [INFO:cleanup_previous_update_action.cc(112)] Executing task 23
[0928/140044.480096] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 3
[0928/140044.485476] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 3
[0928/140044.491380] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 3
[0928/140044.504281] [INFO:cleanup_previous_update_action.cc(361)] Waiting for merge to complete: 98%.
[0928/140044.506991] [INFO:cleanup_previous_update_action.cc(124)] CleanupPreviousUpdateAction scheduled task ID 24 for WaitForMerge
[0928/140046.510327] [INFO:cleanup_previous_update_action.cc(112)] Executing task 24
[0928/140046.617391] [INFO:snapshot.cpp(1006)] CheckTargetMergeState for system_b returned: 5
[0928/140046.625225] [INFO:snapshot.cpp(941)] CheckMergeState for snapshots returned: 5
[0928/140046.629475] [INFO:snapshot.cpp(258)] Removing all update state.
[0928/140046.647664] [INFO:snapshot.cpp(913)] ProcessUpdateState handling state: 5
[0928/140046.653668] [INFO:cleanup_previous_update_action.cc(320)] Merge finished with state MergeCompleted.
[0928/140046.656428] [INFO:cleanup_previous_update_action.cc(130)] Stopping/suspending/completing CleanupPreviousUpdateAction
[0928/140046.659430] [INFO:cleanup_previous_update_action.cc(491)] Reporting merge stats: MergeCompleted in 26039ms (resumed 0 times), using 1562419200 bytes of COW image.
[0928/140046.662704] [INFO:cleanup_previous_update_action.cc(130)] Stopping/suspending/completing CleanupPreviousUpdateAction
[0928/140046.665131] [INFO:action_processor.cc(116)] ActionProcessor: finished last action CleanupPreviousUpdateAction with code ErrorCode::kSuccess
[0928/140046.667361] [INFO:update_attempter_android.cc(565)] Processing Done.
[0928/140046.669886] [INFO:update_attempter_android.cc(713)] Terminating cleanup previous update.
[0929/084351.670243] [INFO:main.cc(72)] A/B Update Engine terminating with exit code 0
