search

WeAreFairphone / android_device_fairphone_FP3

Android / LineageOS 16 device tree for Fairphone 3
46 stars 7 forks source link

Flashing with TWRP doesn't work #3

Closed mstaz closed 4 years ago

mstaz commented 4 years ago

As already stated in README flashing with TWRP doesn't work. I played around with it again. This the logcat output I get when installing the lineage-16.0-2020xxxx-UNOFFICIAL-fp3.zip via TWRP:

01-15 04:53:33.292   569   569 I update_engine_sideload: [0114/235333.291532:INFO:sideload_main.cc(206)] Update Engine Sideloading starting
01-15 04:53:33.292   569   569 I update_engine_sideload: [0114/235333.292365:INFO:boot_control_recovery.cc(76)] Loaded boot_control HAL 'Boot control HAL' version 0.1 authored by 'Code Aurora Forum'.
01-15 04:53:33.293   569   569 E update_engine_sideload: [0114/235333.293478:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:53:33.293   569   569 E update_engine_sideload: [0114/235333.293550:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:53:33.293   569   569 E update_engine_sideload: [0114/235333.293577:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:53:33.293   569   569 E update_engine_sideload: [0114/235333.293605:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:53:33.293   569   569 E update_engine_sideload: [0114/235333.293629:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:53:33.293   569   569 E update_engine_sideload: [0114/235333.293734:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:53:33.294   569   569 I update_engine_sideload: [0114/235333.294052:INFO:update_attempter_android.cc(250)] Using this install plan:
01-15 04:53:33.294   569   569 I update_engine_sideload: [0114/235333.294110:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: B, target_slot: A, url: file:///sdcard/lineage-16.0-20200427-UNOFFICIAL-fp3.zip, payload: (size: 607009446, metadata_size: 118995, metadata signature: , hash: 31CE9C455EA98B4E14823FA6123D0C4600DB7DCEBB255999996458D57C296D24, payload type: unknown), hash_checks_mandatory: false, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true
01-15 04:53:33.294   569   569 I update_engine_sideload: [0114/235333.294424:INFO:update_attempter_android.cc(563)] Marking booted slot as good.
01-15 04:53:33.331   569   569 I update_engine_sideload: [0114/235333.331659:INFO:metrics_utils.cc(336)] Number of Reboots during current update attempt = 0
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332017:INFO:metrics_utils.cc(344)] Payload Attempt Number = 1
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332071:INFO:metrics_utils.cc(361)] Update Timestamp Start = 1/1/1970 0:02:04 GMT
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332487:INFO:update_attempter_android.cc(578)] Scheduling an action processor start.
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332665:INFO:action_processor.cc(46)] ActionProcessor: starting InstallPlanAction
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332714:INFO:action_processor.cc(116)] ActionProcessor: finished InstallPlanAction with code ErrorCode::kSuccess
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332746:INFO:action_processor.cc(143)] ActionProcessor: starting DownloadAction
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332796:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: B, target_slot: A, url: file:///sdcard/lineage-16.0-20200427-UNOFFICIAL-fp3.zip, payload: (size: 607009446, metadata_size: 118995, metadata signature: , hash: 31CE9C455EA98B4E14823FA6123D0C4600DB7DCEBB255999996458D57C296D24, payload type: unknown), hash_checks_mandatory: false, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true
01-15 04:53:33.332   569   569 I update_engine_sideload: [0114/235333.332839:INFO:download_action.cc(200)] Marking new slot as unbootable
01-15 04:53:33.335   569   569 I update_engine_sideload: [0114/235333.335660:INFO:multi_range_http_fetcher.cc(45)] starting first transfer
01-15 04:53:33.335   569   569 I update_engine_sideload: [0114/235333.335728:INFO:multi_range_http_fetcher.cc(74)] starting transfer of range 7576+607009446
01-15 04:53:33.336   569   569 I update_engine_sideload: [0114/235333.336440:INFO:delta_performer.cc(210)] Completed 0/? operations, 16384/607009446 bytes downloaded (0%), overall progress 0%
01-15 04:53:33.337   569   569 I update_engine_sideload: [0114/235333.337373:INFO:delta_performer.cc(470)] Manifest size in payload matches expected value from Omaha
01-15 04:53:33.337   569   569 I update_engine_sideload: [0114/235333.337651:INFO:payload_metadata.cc(182)] Verifying metadata hash signature using public key: /etc/update_engine/update-payload-key.pub.pem
01-15 04:53:33.338   569   569 I update_engine_sideload: [0114/235333.338914:INFO:payload_verifier.cc(93)] signature blob size = 264
01-15 04:53:33.340   569   569 I update_engine_sideload: [0114/235333.340164:INFO:payload_verifier.cc(112)] Verified correct signature 1 out of 1 signatures.
01-15 04:53:33.340   569   569 I update_engine_sideload: [0114/235333.340258:INFO:payload_metadata.cc(224)] Metadata hash signature matches value in Omaha response.
01-15 04:53:33.345   569   569 I update_engine_sideload: [0114/235333.345548:INFO:delta_performer.cc(1405)] Detected a 'full' payload.
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374028:INFO:delta_performer.cc(400)] PartitionInfo new boot sha256: NpYHtr1qzYCJWJ42rkoNsMpbZll2DvIfdYrK78K2IvA= size: 45043712
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374125:INFO:delta_performer.cc(400)] PartitionInfo new system sha256: 7ZmDNMvBms1zM4OU4yDmO9hCug93An0s6We6coh8TfY= size: 3221225472
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374145:INFO:delta_performer.cc(400)] PartitionInfo new vendor sha256: 3o9AEKRb6IMGGB+U8XHLD3g3fdzGwT0UiaMN9ySWgpM= size: 1073741824
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374162:INFO:delta_performer.cc(400)] PartitionInfo new dtbo sha256: buIC6jixgXRyJErBzjA6E5fpGZzoQhfSvSi6kuqyirs= size: 806912
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374177:INFO:delta_performer.cc(400)] PartitionInfo new product sha256: sBkQQOCeUT8Z+ezAFxzPLRNCXPjRvidkVAAZ+IXmRgg= size: 134217728
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374204:INFO:delta_performer.cc(374)] Opening /dev/block/bootdevice/by-name/boot_a partition without O_DSYNC
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374891:INFO:delta_performer.cc(126)] Caching writes.
01-15 04:53:33.374   569   569 I update_engine_sideload: [0114/235333.374988:INFO:delta_performer.cc(386)] Applying 22 operations to partition "boot"
01-15 04:53:33.384   569   569 I update_engine_sideload: [0114/235333.384152:INFO:delta_performer.cc(601)] Starting to apply update payload operations
01-15 04:53:35.014   569   569 I update_engine_sideload: [0114/235335.014467:INFO:delta_performer.cc(374)] Opening /dev/block/bootdevice/by-name/system_a partition without O_DSYNC
01-15 04:53:35.015   569   569 I update_engine_sideload: [0114/235335.015252:INFO:delta_performer.cc(126)] Caching writes.
01-15 04:53:35.015   569   569 I update_engine_sideload: [0114/235335.015302:INFO:delta_performer.cc(386)] Applying 1536 operations to partition "system"
01-15 04:53:46.618   569   569 I update_engine_sideload: [0114/235346.618379:INFO:delta_performer.cc(210)] Completed 119/2135 operations (5%), 97124352/607009446 bytes downloaded (16%), overall progress 10%
01-15 04:54:01.560   569   569 I update_engine_sideload: [0114/235401.560217:INFO:delta_performer.cc(210)] Completed 241/2135 operations (11%), 182108160/607009446 bytes downloaded (30%), overall progress 20%
01-15 04:54:17.578   569   569 I update_engine_sideload: [0114/235417.578112:INFO:delta_performer.cc(210)] Completed 383/2135 operations (17%), 267091968/607009446 bytes downloaded (44%), overall progress 30%
01-15 04:54:34.741   569   569 I update_engine_sideload: [0114/235434.741897:INFO:delta_performer.cc(210)] Completed 496/2135 operations (23%), 352075776/607009446 bytes downloaded (58%), overall progress 40%
01-15 04:54:49.690   569   569 I update_engine_sideload: [0114/235449.690275:INFO:delta_performer.cc(210)] Completed 605/2135 operations (28%), 437059584/607009446 bytes downloaded (72%), overall progress 50%
01-15 04:55:02.291   569   569 I update_engine_sideload: [0114/235502.291808:INFO:delta_performer.cc(210)] Completed 854/2135 operations (40%), 487587840/607009446 bytes downloaded (80%), overall progress 60%
01-15 04:55:08.217   569   569 I update_engine_sideload: [0114/235508.217158:INFO:delta_performer.cc(210)] Completed 1281/2135 operations (60%), 487620608/607009446 bytes downloaded (80%), overall progress 70%
01-15 04:55:14.081   569   569 I update_engine_sideload: [0114/235514.081444:INFO:delta_performer.cc(374)] Opening /dev/block/bootdevice/by-name/vendor_a partition without O_DSYNC
01-15 04:55:14.082   569   569 I update_engine_sideload: [0114/235514.082332:INFO:delta_performer.cc(126)] Caching writes.
01-15 04:55:14.082   569   569 I update_engine_sideload: [0114/235514.082437:INFO:delta_performer.cc(386)] Applying 512 operations to partition "vendor"
01-15 04:55:19.709   569   569 I update_engine_sideload: [0114/235519.709347:INFO:delta_performer.cc(210)] Completed 1623/2135 operations (76%), 518111232/607009446 bytes downloaded (85%), overall progress 80%
01-15 04:55:33.659   569   569 I update_engine_sideload: [0114/235533.659876:INFO:delta_performer.cc(210)] Completed 1768/2135 operations (82%), 594870272/607009446 bytes downloaded (98%), overall progress 90%
01-15 04:55:41.687   569   569 I update_engine_sideload: [0114/235541.687938:INFO:delta_performer.cc(374)] Opening /dev/block/bootdevice/by-name/dtbo_a partition without O_DSYNC
01-15 04:55:41.688   569   569 I update_engine_sideload: [0114/235541.688879:INFO:delta_performer.cc(126)] Caching writes.
01-15 04:55:41.689   569   569 I update_engine_sideload: [0114/235541.689016:INFO:delta_performer.cc(386)] Applying 1 operations to partition "dtbo"
01-15 04:55:41.726   569   569 I update_engine_sideload: [0114/235541.726453:INFO:delta_performer.cc(374)] Opening /dev/block/bootdevice/by-name/product_a partition without O_DSYNC
01-15 04:55:41.727   569   569 I update_engine_sideload: [0114/235541.727037:INFO:delta_performer.cc(126)] Caching writes.
01-15 04:55:41.727   569   569 I update_engine_sideload: [0114/235541.727133:INFO:delta_performer.cc(386)] Applying 64 operations to partition "product"
01-15 04:55:42.636   569   569 I update_engine_sideload: [0114/235542.636482:INFO:delta_performer.cc(210)] Completed 2135/2135 operations (100%), 607009446/607009446 bytes downloaded (100%), overall progress 100%
01-15 04:55:42.636   569   569 I update_engine_sideload: [0114/235542.636580:INFO:delta_performer.cc(1370)] Extracted signature data of size 264 at 606889923
01-15 04:55:42.636   569   569 I update_engine_sideload: [0114/235542.636610:INFO:multi_range_http_fetcher.cc(112)] terminating transfer
01-15 04:55:42.636   569   569 I update_engine_sideload: [0114/235542.636656:INFO:multi_range_http_fetcher.cc(172)] Received transfer terminated.
01-15 04:55:42.636   569   569 I update_engine_sideload: [0114/235542.636672:INFO:multi_range_http_fetcher.cc(124)] TransferEnded w/ code 200
01-15 04:55:42.636   569   569 I update_engine_sideload: [0114/235542.636687:INFO:multi_range_http_fetcher.cc(158)] Done w/ all transfers
01-15 04:55:43.328   569   569 I update_engine_sideload: [0114/235543.328156:INFO:delta_performer.cc(1549)] Verifying payload using public key: /etc/update_engine/update-payload-key.pub.pem
01-15 04:55:43.328   569   569 I update_engine_sideload: [0114/235543.328261:INFO:delta_performer.cc(1586)] Payload hash matches value in payload.
01-15 04:55:43.328   569   569 I update_engine_sideload: [0114/235543.328347:INFO:download_action.cc(395)] Collections of histograms for UpdateEngine.DownloadAction.
01-15 04:55:43.328   569   569 I update_engine_sideload: Histogram: UpdateEngine.DownloadAction.InstallOperation::REPLACE.Duration recorded 2135 samples, mean = 55.9
01-15 04:55:43.328   569   569 I update_engine_sideload: 0    O                                                                         (1 = 0.0%)
01-15 04:55:43.328   569   569 I update_engine_sideload: 10   ------------------------------------------------------------------------O (1273 = 59.6%) {0.0%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 18   O                                                                         (7 = 0.3%) {59.7%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 32   ----O                                                                     (72 = 3.4%) {60.0%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 57   -----------------O                                                        (307 = 14.4%) {63.4%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 101  ---------------------O                                                    (370 = 17.3%) {77.8%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 179  -----O                                                                    (92 = 4.3%) {95.1%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 317  -O                                                                        (13 = 0.6%) {99.4%}
01-15 04:55:43.328   569   569 I update_engine_sideload: 561  ... 
01-15 04:55:43.328   569   569 I update_engine_sideload: 
01-15 04:55:43.328   569   569 I update_engine_sideload: 
01-15 04:55:43.328   569   569 I update_engine_sideload: [0114/235543.328786:INFO:action_processor.cc(116)] ActionProcessor: finished DownloadAction with code ErrorCode::kSuccess
01-15 04:55:43.328   569   569 I update_engine_sideload: [0114/235543.328818:INFO:action_processor.cc(143)] ActionProcessor: starting FilesystemVerifierAction
01-15 04:55:43.328   569   569 I update_engine_sideload: [0114/235543.328857:INFO:filesystem_verifier_action.cc(108)] Hashing partition 0 (boot) on device /dev/block/bootdevice/by-name/boot_a
01-15 04:55:43.801   569   569 I update_engine_sideload: [0114/235543.801614:INFO:filesystem_verifier_action.cc(199)] Hash of boot: NpYHtr1qzYCJWJ42rkoNsMpbZll2DvIfdYrK78K2IvA=
01-15 04:55:43.807   569   569 I update_engine_sideload: [0114/235543.807694:INFO:filesystem_verifier_action.cc(108)] Hashing partition 1 (system) on device /dev/block/bootdevice/by-name/system_a
01-15 04:56:17.371   569   569 I update_engine_sideload: [0114/235617.371003:INFO:filesystem_verifier_action.cc(199)] Hash of system: 7ZmDNMvBms1zM4OU4yDmO9hCug93An0s6We6coh8TfY=
01-15 04:56:17.780   569   569 I update_engine_sideload: [0114/235617.780080:INFO:filesystem_verifier_action.cc(108)] Hashing partition 2 (vendor) on device /dev/block/bootdevice/by-name/vendor_a
01-15 04:56:29.005   569   569 I update_engine_sideload: [0114/235629.005061:INFO:filesystem_verifier_action.cc(199)] Hash of vendor: 3o9AEKRb6IMGGB+U8XHLD3g3fdzGwT0UiaMN9ySWgpM=
01-15 04:56:29.139   569   569 I update_engine_sideload: [0114/235629.139380:INFO:filesystem_verifier_action.cc(108)] Hashing partition 3 (dtbo) on device /dev/block/bootdevice/by-name/dtbo_a
01-15 04:56:29.151   569   569 I update_engine_sideload: [0114/235629.151321:INFO:filesystem_verifier_action.cc(199)] Hash of dtbo: buIC6jixgXRyJErBzjA6E5fpGZzoQhfSvSi6kuqyirs=
01-15 04:56:29.153   569   569 I update_engine_sideload: [0114/235629.153387:INFO:filesystem_verifier_action.cc(108)] Hashing partition 4 (product) on device /dev/block/bootdevice/by-name/product_a
01-15 04:56:30.555   569   569 I update_engine_sideload: [0114/235630.555388:INFO:filesystem_verifier_action.cc(199)] Hash of product: sBkQQOCeUT8Z+ezAFxzPLRNCXPjRvidkVAAZ+IXmRgg=
01-15 04:56:30.572   569   569 I update_engine_sideload: [0114/235630.572834:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kSuccess
01-15 04:56:30.572   569   569 I update_engine_sideload: [0114/235630.572932:INFO:action_processor.cc(143)] ActionProcessor: starting PostinstallRunnerAction
01-15 04:56:30.573   569   569 I update_engine_sideload: [0114/235630.573812:INFO:postinstall_runner_action.cc(174)] /dev/block/bootdevice/by-name/system_b has been mounted R/W 0 times.
01-15 04:56:30.573   569   569 I update_engine_sideload: [0114/235630.573859:INFO:postinstall_runner_action.cc(188)] Skipping backuptool scripts
01-15 04:56:30.573   569   569 I update_engine_sideload: [0114/235630.573888:INFO:utils.cc(693)] Not a mountpoint: /postinstall
01-15 04:56:30.576   569   569 I update_engine_sideload: [0114/235630.576836:INFO:postinstall_runner_action.cc(213)] Performing postinst (system/bin/otapreopt_script at /postinstall/system/bin/otapreopt_script) installed on device /dev/block/bootdevice/by-name/system_a and mountable device /dev/block/bootdevice/by-name/system_a
01-15 04:56:30.580   569   569 I update_engine_sideload: [0114/235630.576871:INFO:postinstall_runner_action.cc(220)] Format file for new system/bin/otapreopt_script is: data
01-15 04:56:30.582   569   569 I update_engine_sideload: [0114/235630.582239:INFO:subprocess.cc(152)] Subprocess exited with si_status: 127
01-15 04:56:30.582   569   569 I update_engine_sideload: [0114/235630.582284:INFO:subprocess.cc(156)] Subprocess output:
01-15 04:56:30.582   569   569 I update_engine_sideload: [0115/045630.581625:ERROR:process.cc(303)] Exec of /postinstall/system/bin/otapreopt_script failed:: No such file or directory
01-15 04:56:30.582   569   569 I update_engine_sideload: 
01-15 04:56:30.639   569   569 E update_engine_sideload: [0114/235630.639127:ERROR:postinstall_runner_action.cc(346)] Postinst command failed with code: 127
01-15 04:56:30.639   569   569 I update_engine_sideload: [0114/235630.639160:INFO:postinstall_runner_action.cc(366)] Ignoring postinstall failure since it is optional
01-15 04:56:30.641   569   569 I update_engine_sideload: [0114/235630.641307:INFO:postinstall_runner_action.cc(405)] All post-install commands succeeded
01-15 04:56:30.641   569   569 I update_engine_sideload: [0114/235630.641344:INFO:action_processor.cc(116)] ActionProcessor: finished last action PostinstallRunnerAction with code ErrorCode::kSuccess
01-15 04:56:30.641   569   569 I update_engine_sideload: [0114/235630.641364:INFO:update_attempter_android.cc(447)] Processing Done.
01-15 04:56:30.641   569   569 I update_engine_sideload: [0114/235630.641425:INFO:update_attempter_android.cc(455)] Update successfully applied, waiting to reboot.
01-15 04:56:30.641   569   569 E update_engine_sideload: [0114/235630.641630:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
01-15 04:56:30.641   569   569 I update_engine_sideload: [0114/235630.641658:INFO:metrics_utils.cc(353)] Updated Marker = 1/1/1970 0:05:02 GMT

Most things look quite fine here, except the postinstall stuff. However I guess this is only important for ota updates and not for initial installation. However after reboot it bootloader seems to fail, automatically switches slot and reboots again. When booting the boot.img with fastboot I get the same error as I got when one of the slot's success flag is "No": FAILED (status read failed (No such device))

dk1978 commented 4 years ago

Hi Max, have not tried this before. What happens if you simply flash all the included partitions by hand? Does that work?

mstaz commented 4 years ago

Hi Daniel, It works, but thinking about it I always flash it on the currently active slot. The difference here is that it is flashed on the inactive slot and afterwards it's switched. I will try that manually. Did you face this error before? Could you solve this by flashing vbmeta with some option like --disable-verity?

mstaz commented 4 years ago

Works now with vbmeta image.