[Xiaomi Mi A2 / 6X Questions & Answers] User699:
@tecknight ls /data/adb withhin twrps terminal gave me

magisk magisk.db modules post-fs-data.d service.d

So my userdata seems to be successfully decrypted and mounted, but somehow the update still won't work...

Did the logcat I send you help you? I actually run out on ideas...

EDIT: I viewed that logcat an found for example this:

03-04 01:04:12.362 584 584 I recovery: type=1400 audit(0.0:947): avc: denied { getattr } for path="/data/misc/profman" dev="mmcblk0p69" ino=2670634 scontext=u:r:recovery:s0 tcontext=u:object_r:profman_dump_data_file:s0 tclass=dir permissive=1

That's in line 257 and seems to be a selinux restriction.Via twrp I cannot access its content and if I boot back to the os I get nothing as well (adb as root). So in that case it seems to fail to get an attribute stored in /data/misc/profman/ because selinux denies it. But since it doesn't exist either it shouldn't be much of an issue, right?

In addition I also get this right after the line above:

03-04 01:04:12.362 584 584 I recovery: type=1400 audit(0.0:948): avc: denied { read } for name="profman" dev="mmcblk0p69" ino=2670634 scontext=u:r:recovery:s0 tcontext=u:object_r:profman_dump_data_file:s0 tclass=dir permissive=1
03-04 01:04:12.362 584 584 I recovery: type=1400 audit(0.0:949): avc: denied { open } for path="/data/misc/profman" dev="mmcblk0p69" ino=2670634 scontext=u:r:recovery:s0 tcontext=u:object_r:profman_dump_data_file:s0 tclass=dir permissive=1
03-04 01:04:12.362 584 584 I recovery: type=1400 audit(0.0:950): avc: denied { search } for name="profman" dev="mmcblk0p69" ino=2670634 scontext=u:r:recovery:s0 tcontext=u:object_r:profman_dump_data_file:s0 tclass=dir permissive=1

It fails to getattr, read, open and search because of selinux denial and this also happens on a few other paths. (E.g. user and bootstat).

I also found that in line 626:

03-04 01:04:26.866 584 584 I recovery: type=1400 audit(0.0:1312): avc: denied { read } for name="1000_USRPKEY_synthetic_password_17d511af4c9a7451" dev="mmcblk0p69" ino=2671181 scontext=u:r:recovery:s0 tcontext=u:object_r:keystore_data_file:s0 tclass=file permissive=1
03-04 01:04:26.866 584 584 I recovery: type=1400 audit(0.0:1313): avc: denied { open } for path="/data/misc/keystore/user_0/1000_USRPKEY_synthetic_password_17d511af4c9a7451" dev="mmcblk0p69" ino=2671181 scontext=u:r:recovery:s0 tcontext=u:object_r:keystore_data_file:s0 tclass=file permissive=1

Since it could be a password/ key related problem, I investigated that file by pulling it to my device. However, it doesn't seem to contain my screen password (checked that with ghex also).

Strange is, that it also says this

03-04 01:04:26.862 584 584 I recovery: type=1400 audit(0.0:1310): avc: denied { read } for name="user_0" dev="mmcblk0p69" ino=2670668 scontext=u:r:recovery:s0 tcontext=u:object_r:keystore_data_file:s0 tclass=dir permissive=1

in line 624 which is strange. It has been denied to read "user_0" but continues to read it later on (and getting a selinux denial again)? I don't understand that actually.

However, it still seems to wait for the keystore to bind, but it fails (lines 633 - 636):

03-04 01:04:26.907 584 684 I ServiceManager: Waiting for service 'android.security.keystore' on '/dev/binder'...
03-04 01:04:26.936 577 577 I servicemanager: type=1400 audit(0.0:1315): avc: denied { create } for scontext=u:r:recovery:s0 tcontext=u:r:recovery:s0 tclass=netlink_selinux_socket permissive=1
03-04 01:04:26.936 577 577 I servicemanager: type=1400 audit(0.0:1316): avc: denied { bind } for scontext=u:r:recovery:s0 tcontext=u:r:recovery:s0 tclass=netlink_selinux_socket permissive=1
03-04 01:04:26.938 687 687 E cutils-trace: Error opening trace file: No such file or directory (2)

And finally in line 640

03-04 01:04:26.940 576 576 I hwservicemanager: getTransport: Cannot find entry android.hardware.keymaster@4.0::IKeymasterDevice/default in either framework or device manifest

After that it failes but somehow still manages (?) to get to the keys. Honestly, I hope you can explain this logcat output! That doesn't seem to make sense to me.

03-04 01:04:27.033 687 687 E SELinux : avc: denied { add_auth } for pid=689 uid=1000 sid=u:r:recovery:s0 scontext=u:r:recovery:s0 tcontext=u:r:recovery:s0 tclass=keystore_key permissive=1
03-04 01:04:27.033 687 687 D keystore: AddAuthenticationToken: timestamp = 40127, time_received = 26
03-04 01:04:27.034 689 689 D : successfully added auth token to keystore
03-04 01:04:27.120 659 659 E KeyMasterHalDevice: Begin send cmd failed
03-04 01:04:27.121 659 659 E KeyMasterHalDevice: ret: 0
03-04 01:04:27.121 659 659 E KeyMasterHalDevice: resp->status: -62
03-04 01:04:27.121 687 690 I keymaster_worker: upgradeKeyBlob USRPKEY_synthetic_password_17d511af4c9a7451 0

If those keys are the issues, then maybe this line could be a problem (l. 661):

03-04 01:04:27.141 577 577 I ServiceManager: service 'android.security.keystore' died

Do you remember that moment you asked me to move/write things in the /data directory to see if it works or not? I told you it worked because it really did. But here's the log about it...

03-04 01:06:48.999 741 741 I ls : type=1400 audit(0.0:1836): avc: denied { read } for name="org.mozilla.fennec_fdroie" dev="mmcblk0p69" ino=1040960 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0:c179,c256,c512,c768 tclass=dir permissive=1
03-04 01:06:48.999 741 741 I ls : type=1400 audit(0.0:1837): avc: denied { open } for path="/data/data/org.mozilla.fennec_fdroie" dev="mmcblk0p69" ino=1040960 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0:c179,c256,c512,c768 tclass=dir permissive=1
03-04 01:07:00.616 742 742 I touch : type=1400 audit(0.0:1838): avc: denied { write } for name="org.mozilla.fennec_fdroie" dev="mmcblk0p69" ino=1040960 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0:c179,c256,c512,c768 tclass=dir permissive=1
03-04 01:07:00.616 742 742 I touch : type=1400 audit(0.0:1839): avc: denied { add_name } for name="muhahahahaha.txt" scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0:c179,c256,c512,c768 tclass=dir permissive=1
03-04 01:07:00.616 742 742 I touch : type=1400 audit(0.0:1840): avc: denied { create } for name="muhahahahaha.txt" scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0 tclass=file permissive=1
03-04 01:07:00.669 742 742 I touch : type=1400 audit(0.0:1841): avc: denied { read open } for path="/data/data/org.mozilla.fennec_fdroie/muhahahahaha.txt" dev="mmcblk0p69" ino=1040977 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0 tclass=file permissive=1
03-04 01:07:03.702 743 743 I ls : type=1400 audit(0.0:1842): avc: denied { getattr } for path="/data/data/org.mozilla.fennec_fdroie/muhahahahaha.txt" dev="mmcblk0p69" ino=1040977 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0 tclass=file permissive=1
03-04 01:07:14.219 744 744 I rm : type=1400 audit(0.0:1843): avc: denied { write } for name="muhahahahaha.txt" dev="mmcblk0p69" ino=1040977 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0 tclass=file permissive=1
03-04 01:07:14.219 744 744 I rm : type=1400 audit(0.0:1844): avc: denied { remove_name } for name="muhahahahaha.txt" dev="mmcblk0p69" ino=1040977 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0:c179,c256,c512,c768 tclass=dir permissive=1
03-04 01:07:14.219 744 744 I rm : type=1400 audit(0.0:1845): avc: denied { unlink } for name="muhahahahaha.txt" dev="mmcblk0p69" ino=1040977 scontext=u:r:recovery:s0 tcontext=u:object_r:app_data_file:s0 tclass=file permissive=1

I created that very original file `muhahahahaha.txt' in `/data/data/org.mozilla.fennec_fdroie/' and removed it afterwards. I don't understand the output of that logcat, since there couldn't have been a denial. It really worked!

Line 1200 - 1455. That is the log while flashing the zip via twrp. Seems like it didn't really install successfull, even though that's what my device and the terminal had told me... Logcat tells kind of the opposite,right?:

03-04 01:17:26.466 584 584 I recovery: type=1400 audit(0.0:1853): avc: denied { read } for name="lineage-17.1-20201219-nightly-jasmine_sprout-signed.zip" dev="mmcblk0p69" ino=1720323 scontext=u:r:recovery:s0 tcontext=u:object_r:ota_package_file:s0:c512,c768 tclass=file permissive=1
03-04 01:17:26.466 584 584 I recovery: type=1400 audit(0.0:1854): avc: denied { open } for path="/data/lineageos_updates/lineage-17.1-20201219-nightly-jasmine_sprout-signed.zip" dev="mmcblk0p69" ino=1720323 scontext=u:r:recovery:s0 tcontext=u:object_r:ota_package_file:s0:c512,c768 tclass=file permissive=1
03-04 01:17:26.528 584 768 I /system/bin/recovery: comment is 1455 bytes; signature is 1437 bytes from end
03-04 01:17:29.639 584 768 I /system/bin/recovery: signature (offset: 29e5d613, length: 597): 3082059306092a864886f70d010702a082058430820580020101310b300906052b0e03021a0500300b06092a864886f70d010701a08203b7308203b33082029ba003020102020900e10413c773c3c54f300d06092a864886f70d01010505003070310b30090603550406130255533113301106035504080c0a57617368696e67746f6e3110300e06035504070c0753656174746c6531123010060355040a0c094c696e656167654f5331123010060355040b0c094c696e656167654f533112301006035504030c094c696e656167654f53301e170d3137303130373034323132355a170d3434303532353034323132355a3070310b30090603550406130255533113301106035504080c0a57617368696e67746f6e3110300e06035504070c0753656174746c6531123010060355040a0c094c696e656167654f5331123010060355040b0c094c696e656167654f533112301006035504030c094c696e656167654f5330820122300d06092a864886f70d01010105000382010f003082010a0282010100a64dd3e1f842038ff03f67b8e9bf09530fc2913cb53e3654c78ec20dbc8b1e7113628ca5abc0860560cb442c1b51f98b6dce5e59c49037f27f64f48aef0490ab99106f0807a2130e1a8b3aacd834e656f0854b602677b66c007b14c2d0c28d0dc61341de648d
03-04 01:17:29.639 584 768 I /system/bin/recovery: failed to verify against RSA key 0
03-04 01:17:29.640 584 768 I chatty : uid=0(root) /system/bin/recovery identical 2 lines
03-04 01:17:29.640 584 768 I /system/bin/recovery: failed to verify against RSA key 0
03-04 01:17:29.640 584 768 I /system/bin/recovery: whole-file signature verified against RSA key 0
03-04 01:17:29.636 584 584 I recovery: type=1400 audit(0.0:1855): avc: denied { write } for name="by-name" dev="tmpfs" ino=5190 scontext=u:r:recovery:s0 tcontext=u:object_r:block_device:s0 tclass=dir permissive=1
03-04 01:17:29.636 584 584 I recovery: type=1400 audit(0.0:1856): avc: denied { remove_name } for name="system" dev="tmpfs" ino=15048 scontext=u:r:recovery:s0 tcontext=u:object_r:block_device:s0 tclass=dir permissive=1
03-04 01:17:29.636 584 584 I recovery: type=1400 audit(0.0:1857): avc: denied { add_name } for name="system" scontext=u:r:recovery:s0 tcontext=u:object_r:block_device:s0 tclass=dir permissive=1
03-04 01:17:29.649 584 584 I recovery: type=1400 audit(0.0:1858): avc: denied { mounton } for path="/system/bin/sh" dev="rootfs" ino=13679 scontext=u:r:recovery:s0 tcontext=u:object_r:rootfs:s0 tclass=file permissive=1
03-04 01:17:29.679 771 771 I update_engine_sideload: [0303/191729.678883:INFO:sideload_main.cc(201)] Update Engine Sideloading starting
03-04 01:17:29.679 771 771 E cutils-trace: Error opening trace file: No such file or directory (2)
03-04 01:17:29.676 771 771 I update_engine_s: type=1400 audit(0.0:1859): avc: denied { call } for scontext=u:r:recovery:s0 tcontext=u:r:recovery:s0 tclass=binder permissive=1
03-04 01:17:29.680 771 771 I update_engine_sideload: [0303/191729.680822:INFO:boot_control_android.cc(76)] Loaded boot control hidl hal.
03-04 01:17:29.681 771 771 E libprocessgroup: Failed to read task profiles from /etc/task_profiles.json
03-04 01:17:29.681 771 771 E libprocessgroup: Loading /etc/task_profiles.json for [771] failed
03-04 01:17:29.681 771 771 W libprocessgroup: Failed to find HighEnergySavingtask profile: No such file or directory
03-04 01:17:29.681 771 771 W libprocessgroup: Failed to find ProcessCapacityLowtask profile: No such file or directory
03-04 01:17:29.681 771 771 W libprocessgroup: Failed to find LowIoPrioritytask profile: No such file or directory
03-04 01:17:29.681 771 771 W libprocessgroup: Failed to find TimerSlackHightask profile: No such file or directory
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682237:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682299:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682354:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682384:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682409:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682475:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682503:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 E update_engine_sideload: [0303/191729.682528:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:17:29.682 771 771 I update_engine_sideload: [0303/191729.682981:INFO:update_attempter_android.cc(259)] Using this install plan:
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683022:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: A, target_slot: B, url: file:///data/lineageos_updates/lineage-17.1-20201219-nightly-jasmine_sprout-signed.zip, payload: (size: 702919424, metadata_size: 143188, metadata signature: , hash: 20B2E7CC81277BD65A6C5F50A011B7584660B13DC4536D4075325C7196EC01BD, payload type: unknown), hash_checks_mandatory: false, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true, is_rollback: false, write_verity: true
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683104:INFO:metrics_utils.cc(349)] Number of Reboots during current update attempt = 0
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683138:INFO:metrics_utils.cc(357)] Payload Attempt Number = 1
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683160:INFO:metrics_utils.cc(374)] Update Monotonic Timestamp Start = 1/1/1970 0:13:28 GMT
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683288:INFO:metrics_utils.cc(383)] Update Boot Timestamp Start = 1/1/1970 0:13:28 GMT
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683311:INFO:update_attempter_android.cc(580)] Scheduling an action processor start.
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683375:INFO:action_processor.cc(51)] ActionProcessor: starting UpdateBootFlagsAction
03-04 01:17:29.683 771 771 I update_engine_sideload: [0303/191729.683415:INFO:update_boot_flags_action.cc(45)] Marking booted slot as good.
03-04 01:17:29.684 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.684 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.685 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.685 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.685 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.686 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.686 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.686 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.686 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.686 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.687 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.687 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.687 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.687 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.687 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.687 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.687 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.687 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.688 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.688 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.688 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.688 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.689 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.689 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.689 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.689 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.689 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.689 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.690 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.690 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.690 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.690 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.690 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.690 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.691 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.691 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.691 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.691 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.691 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.692 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.692 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.692 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.692 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.692 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.693 771 771 I update_engine_sideload: [0303/191729.693555:INFO:action_processor.cc(116)] ActionProcessor: finished UpdateBootFlagsAction with code ErrorCode::kSuccess
03-04 01:17:29.693 771 771 I update_engine_sideload: [0303/191729.693633:INFO:action_processor.cc(143)] ActionProcessor: starting InstallPlanAction
03-04 01:17:29.693 771 771 I update_engine_sideload: [0303/191729.693665:INFO:action_processor.cc(116)] ActionProcessor: finished InstallPlanAction with code ErrorCode::kSuccess
03-04 01:17:29.693 771 771 I update_engine_sideload: [0303/191729.693690:INFO:action_processor.cc(143)] ActionProcessor: starting DownloadAction
03-04 01:17:29.693 771 771 I update_engine_sideload: [0303/191729.693727:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: A, target_slot: B, url: file:///data/lineageos_updates/lineage-17.1-20201219-nightly-jasmine_sprout-signed.zip, payload: (size: 702919424, metadata_size: 143188, metadata signature: , hash: 20B2E7CC81277BD65A6C5F50A011B7584660B13DC4536D4075325C7196EC01BD, payload type: unknown), hash_checks_mandatory: false, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true, is_rollback: false, write_verity: true
03-04 01:17:29.693 771 771 I update_engine_sideload: [0303/191729.693760:INFO:download_action.cc(199)] Marking new slot as unbootable
03-04 01:17:29.694 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.694 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.694 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.694 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.694 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:17:29.694 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:17:29.694 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:17:29.694 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:17:29.694 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:17:29.694 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:17:29.697 771 771 I update_engine_sideload: [0303/191729.697141:INFO:multi_range_http_fetcher.cc(45)] starting first transfer
03-04 01:17:29.697 771 771 I update_engine_sideload: [0303/191729.697193:INFO:multi_range_http_fetcher.cc(74)] starting transfer of range 7287+702919424
03-04 01:17:29.697 771 771 I update_engine_sideload: [0303/191729.697395:INFO:delta_performer.cc(208)] Completed 0/? operations, 16384/702919424 bytes downloaded (0%), overall progress 0%
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698124:INFO:delta_performer.cc(519)] Manifest size in payload matches expected value from Omaha
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698188:INFO:delta_performer.cc(1612)] Verifying using public key: /etc/update_engine/update-payload-key.pub.pem
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698401:INFO:payload_verifier.cc(58)] signature blob size = 264
03-04 01:17:29.698 771 771 E update_engine_sideload: [0303/191729.698659:ERROR:payload_verifier.cc(84)] None of the 1 signatures is correct. Expected hash before padding:
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698692:INFO:utils.cc(439)] Logging array of length: 32
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698725:INFO:utils.cc(456)] 0x00000000 : 7c fa ea 79 21 c9 7f c6 15 bf b0 c5 0d 5d df 61
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698753:INFO:utils.cc(456)] 0x00000010 : ec ee a4 28 19 f9 26 d6 46 23 29 85 60 50 ff 11
03-04 01:17:29.698 771 771 E update_engine_sideload: [0303/191729.698776:ERROR:payload_verifier.cc(87)] But found decrypted hashes:
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698799:INFO:utils.cc(439)] Logging array of length: 256
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698826:INFO:utils.cc(456)] 0x00000000 : c3 86 38 0f 7f 29 6e ec 3a 68 83 4c 2f 75 d3 a7
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698851:INFO:utils.cc(456)] 0x00000010 : 18 3e 27 3d 46 c3 42 6d 60 2f 71 87 3b 56 a5 5b
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698878:INFO:utils.cc(456)] 0x00000020 : 9b 3c 05 a7 27 a1 6f 38 a8 9d bd a0 87 66 88 12
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698905:INFO:utils.cc(456)] 0x00000030 : 35 c7 b6 0e 4b c1 8b 67 aa 87 a2 c9 77 83 89 2f
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698934:INFO:utils.cc(456)] 0x00000040 : 82 54 eb 43 44 45 7d 8b d9 d8 5d ad 01 2d 8f e0
03-04 01:17:29.698 771 771 I update_engine_sideload: [0303/191729.698960:INFO:utils.cc(456)] 0x00000050 : da a7 3d 4c 68 5b 76 91 21 d6 a8 02 c6 ba 1e 0a
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699015:INFO:utils.cc(456)] 0x00000060 : 49 f7 af 09 a2 48 bf 6c 57 b7 a5 0a c0 5f 19 64
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699045:INFO:utils.cc(456)] 0x00000070 : ff e4 12 20 a3 f0 b3 e9 87 83 0e 35 9e ed 53 b1
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699072:INFO:utils.cc(456)] 0x00000080 : aa 0a 3c eb 22 59 2a 72 4d 83 42 89 c2 b3 07 57
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699100:INFO:utils.cc(456)] 0x00000090 : 5d 55 7b d3 8a 41 9f 26 eb 97 c3 8e ec 55 b5 e9
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699126:INFO:utils.cc(456)] 0x000000a0 : 86 e8 fb 25 e0 61 af f9 7e 6d b9 22 ca 60 96 fb
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699154:INFO:utils.cc(456)] 0x000000b0 : 59 d5 a7 89 8d 24 18 ae fc da 4d 30 9d 89 28 69
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699180:INFO:utils.cc(456)] 0x000000c0 : 97 b1 ad ec 78 af c9 42 77 62 01 8f 64 b6 98 24
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699206:INFO:utils.cc(456)] 0x000000d0 : 7c 1e 9f 4d 9a 6d 63 cc 3c 1a 89 1b 0f f9 67 5b
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699233:INFO:utils.cc(456)] 0x000000e0 : 7c 98 1c 77 3d 16 d8 d1 e8 9e b8 4e 46 15 85 d2
03-04 01:17:29.699 771 771 I update_engine_sideload: [0303/191729.699260:INFO:utils.cc(456)] 0x000000f0 : d1 0c 84 62 f5 08 ef ab 55 ba 02 9b 36 55 4c c7
03-04 01:17:29.699 771 771 E update_engine_sideload: [0303/191729.699286:ERROR:payload_metadata.cc(230)] Manifest hash verification failed.
03-04 01:17:29.699 771 771 W update_engine_sideload: [0303/191729.699312:WARNING:delta_performer.cc(549)] Ignoring metadata signature validation failures
03-04 01:17:29.702 771 771 I update_engine_sideload: [0303/191729.702034:INFO:delta_performer.cc(1643)] Detected a 'full' payload.
03-04 01:17:29.708 771 771 I update_engine_sideload: [0303/191729.708162:INFO:delta_performer.cc(979)] InitPartitionMetadata done.
03-04 01:17:29.702 771 771 I update_engine_s: type=1400 audit(0.0:1861): avc: denied { read } for name="filesystems" dev="proc" ino=4026532138 scontext=u:r:recovery:s0 tcontext=u:object_r:proc_filesystems:s0 tclass=file permissive=1
03-04 01:17:29.702 771 771 I update_engine_s: type=1400 audit(0.0:1862): avc: denied { open } for path="/proc/filesystems" dev="proc" ino=4026532138 scontext=u:r:recovery:s0 tcontext=u:object_r:proc_filesystems:s0 tclass=file permissive=1
03-04 01:17:29.702 771 771 I update_engine_s: type=1400 audit(0.0:1863): avc: denied { getattr } for path="/proc/filesystems" dev="proc" ino=4026532138 scontext=u:r:recovery:s0 tcontext=u:object_r:proc_filesystems:s0 tclass=file permissive=1
03-04 01:17:29.709 771 771 I update_engine_sideload: [0303/191729.709668:INFO:delta_performer.cc(450)] PartitionInfo new boot sha256: KbbD/rar2KsDM7moUIaTFPoA0OxutBkFlHwuF5dgjgE= size: 25100288
03-04 01:17:29.709 771 771 I update_engine_sideload: [0303/191729.709732:INFO:delta_performer.cc(450)] PartitionInfo new system sha256: PFMJ+c3m/65mGuc2NTuCisPJlJyszvI1i8Gp0TpUKHM= size: 3221225472
03-04 01:17:29.709 771 771 I update_engine_sideload: [0303/191729.709757:INFO:delta_performer.cc(450)] PartitionInfo new vendor sha256: Vl0qfLW8Mfw2kDnZUGhdVaRWjRWN06vniDXCYKIGKnk= size: 2147483648
03-04 01:17:29.709 771 771 I update_engine_sideload: [0303/191729.709790:INFO:delta_performer.cc(384)] Opening /dev/block/bootdevice/by-name/boot_b partition without O_DSYNC
03-04 01:17:29.710 771 771 I update_engine_sideload: [0303/191729.710490:INFO:delta_performer.cc(127)] Caching writes.
03-04 01:17:29.710 771 771 I update_engine_sideload: [0303/191729.710582:INFO:delta_performer.cc(396)] Applying 12 operations to partition "boot"
03-04 01:17:29.718 771 771 I update_engine_sideload: [0303/191729.718649:INFO:delta_performer.cc(654)] Starting to apply update payload operations
03-04 01:17:30.725 771 771 I update_engine_sideload: [0303/191730.725743:INFO:delta_performer.cc(384)] Opening /dev/block/bootdevice/by-name/system_b partition without O_DSYNC
03-04 01:17:30.727 771 771 I update_engine_sideload: [0303/191730.727185:INFO:delta_performer.cc(127)] Caching writes.
03-04 01:17:30.727 771 771 I update_engine_sideload: [0303/191730.727299:INFO:delta_performer.cc(396)] Applying 1536 operations to partition "system"
03-04 01:17:41.445 771 771 I update_engine_sideload: [0303/191741.445618:INFO:delta_performer.cc(208)] Completed 127/2572 operations (4%), 112476160/702919424 bytes downloaded (16%), overall progress 10%
03-04 01:17:54.582 771 771 I update_engine_sideload: [0303/191754.582282:INFO:delta_performer.cc(208)] Completed 271/2572 operations (10%), 210878464/702919424 bytes downloaded (30%), overall progress 20%
03-04 01:18:08.111 771 771 I update_engine_sideload: [0303/191808.111410:INFO:delta_performer.cc(208)] Completed 455/2572 operations (17%), 309297152/702919424 bytes downloaded (44%), overall progress 30%
03-04 01:18:26.845 771 771 I update_engine_sideload: [0303/191826.845169:INFO:delta_performer.cc(208)] Completed 597/2572 operations (23%), 407699456/702919424 bytes downloaded (58%), overall progress 40%
03-04 01:18:40.254 771 771 I update_engine_sideload: [0303/191840.254894:INFO:delta_performer.cc(208)] Completed 721/2572 operations (28%), 509460480/702919424 bytes downloaded (72%), overall progress 50%
03-04 01:18:47.082 771 771 I update_engine_sideload: [0303/191847.082592:INFO:delta_performer.cc(208)] Completed 1235/2572 operations (48%), 517128192/702919424 bytes downloaded (73%), overall progress 60%
03-04 01:19:17.871 771 771 I update_engine_sideload: [0303/191917.871045:INFO:delta_performer.cc(384)] Opening /dev/block/bootdevice/by-name/vendor_b partition without O_DSYNC
03-04 01:19:17.871 771 771 I update_engine_sideload: [0303/191917.871872:INFO:delta_performer.cc(127)] Caching writes.
03-04 01:19:17.872 771 771 I update_engine_sideload: [0303/191917.872001:INFO:delta_performer.cc(396)] Applying 1024 operations to partition "vendor"
03-04 01:19:17.872 771 771 I update_engine_sideload: [0303/191917.872210:INFO:delta_performer.cc(208)] Completed 1548/2572 operations (60%), 553549824/702919424 bytes downloaded (78%), overall progress 69%
03-04 01:19:19.161 771 771 I update_engine_sideload: [0303/191919.161298:INFO:delta_performer.cc(208)] Completed 1568/2572 operations (60%), 562348032/702919424 bytes downloaded (80%), overall progress 70%
03-04 01:19:32.652 771 771 I update_engine_sideload: [0303/191932.652492:INFO:delta_performer.cc(208)] Completed 1705/2572 operations (66%), 660750336/702919424 bytes downloaded (94%), overall progress 80%
03-04 01:19:43.399 771 771 I update_engine_sideload: [0303/191943.399358:INFO:delta_performer.cc(208)] Completed 2161/2572 operations (84%), 683065344/702919424 bytes downloaded (97%), overall progress 90%
03-04 01:20:05.603 771 771 I update_engine_sideload: [0303/192005.602983:INFO:delta_performer.cc(208)] Completed 2572/2572 operations (100%), 702919424/702919424 bytes downloaded (100%), overall progress 100%
03-04 01:20:05.603 771 771 I update_engine_sideload: [0303/192005.603167:INFO:delta_performer.cc(1602)] Extracted signature data of size 264 at 702775708
03-04 01:20:05.603 771 771 I update_engine_sideload: [0303/192005.603220:INFO:multi_range_http_fetcher.cc(115)] Terminating transfer.
03-04 01:20:05.603 771 771 I update_engine_sideload: [0303/192005.603285:INFO:multi_range_http_fetcher.cc(177)] Received transfer terminated.
03-04 01:20:05.603 771 771 I update_engine_sideload: [0303/192005.603330:INFO:multi_range_http_fetcher.cc(129)] TransferEnded w/ code 200
03-04 01:20:05.603 771 771 I update_engine_sideload: [0303/192005.603379:INFO:multi_range_http_fetcher.cc(163)] Done w/ all transfers
03-04 01:20:20.974 771 771 I update_engine_sideload: [0303/192020.974875:INFO:delta_performer.cc(1612)] Verifying using public key: /etc/update_engine/update-payload-key.pub.pem
03-04 01:20:20.975 771 771 I update_engine_sideload: [0303/192020.975271:INFO:delta_performer.cc(1829)] Payload hash matches value in payload.
03-04 01:20:20.975 771 771 I update_engine_sideload: [0303/192020.975435:INFO:download_action.cc(400)] Collections of histograms for UpdateEngine.DownloadAction.
03-04 01:20:20.975 771 771 I update_engine_sideload: Histogram: UpdateEngine.DownloadAction.InstallOperation::REPLACE.Duration recorded 2572 samples, mean = 50.8
03-04 01:20:20.975 771 771 I update_engine_sideload: 0 O (4 = 0.2%)
03-04 01:20:20.975 771 771 I update_engine_sideload: 10 ------------------------------------------------------------------------O (982 = 38.2%) {0.2%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 18 ---------------------O (280 = 10.9%) {38.3%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 32 ------------------------------O (406 = 15.8%) {49.2%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 57 ------------------------------------------O (575 = 22.4%) {65.0%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 101 -----------------O (235 = 9.1%) {87.4%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 179 -----O (73 = 2.8%) {96.5%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 317 -O (17 = 0.7%) {99.3%}
03-04 01:20:20.975 771 771 I update_engine_sideload: 561 ...
03-04 01:20:20.975 771 771 I update_engine_sideload:
03-04 01:20:20.975 771 771 I update_engine_sideload:
03-04 01:20:20.979 771 771 I update_engine_sideload: [0303/192020.979270:INFO:action_processor.cc(116)] ActionProcessor: finished DownloadAction with code ErrorCode::kSuccess
03-04 01:20:20.979 771 771 I update_engine_sideload: [0303/192020.979364:INFO:action_processor.cc(143)] ActionProcessor: starting FilesystemVerifierAction
03-04 01:20:20.979 771 771 I update_engine_sideload: [0303/192020.979405:INFO:filesystem_verifier_action.cc(117)] Hashing partition 0 (boot) on device /dev/block/bootdevice/by-name/boot_b
03-04 01:20:21.134 771 771 I update_engine_sideload: [0303/192021.134550:INFO:filesystem_verifier_action.cc(237)] Hash of boot: KbbD/rar2KsDM7moUIaTFPoA0OxutBkFlHwuF5dgjgE=
03-04 01:20:21.140 771 771 I update_engine_sideload: [0303/192021.140698:INFO:filesystem_verifier_action.cc(117)] Hashing partition 1 (system) on device /dev/block/bootdevice/by-name/system_b
03-04 01:20:30.906 771 771 I update_engine_sideload: [0303/192030.906330:INFO:filesystem_verifier_action.cc(237)] Hash of system: PFMJ+c3m/65mGuc2NTuCisPJlJyszvI1i8Gp0TpUKHM=
03-04 01:20:31.209 771 771 I update_engine_sideload: [0303/192031.209096:INFO:filesystem_verifier_action.cc(117)] Hashing partition 2 (vendor) on device /dev/block/bootdevice/by-name/vendor_b
03-04 01:20:37.788 771 771 I update_engine_sideload: [0303/192037.788643:INFO:filesystem_verifier_action.cc(237)] Hash of vendor: Vl0qfLW8Mfw2kDnZUGhdVaRWjRWN06vniDXCYKIGKnk=
03-04 01:20:38.024 771 771 I update_engine_sideload: [0303/192038.024888:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kSuccess
03-04 01:20:38.025 771 771 I update_engine_sideload: [0303/192038.024993:INFO:action_processor.cc(143)] ActionProcessor: starting PostinstallRunnerAction
03-04 01:20:38.026 771 771 I update_engine_sideload: [0303/192038.026453:INFO:postinstall_runner_action.cc(186)] /dev/block/bootdevice/by-name/system_a has been mounted R/W 186 times.
03-04 01:20:38.026 771 771 I update_engine_sideload: [0303/192038.026588:INFO:postinstall_runner_action.cc(190)] Running backuptool scripts
03-04 01:20:38.152 776 776 I sh : type=1400 audit(0.0:1864): avc: denied { getattr } for path="/postinstall/system/bin/backuptool_postinstall.sh" dev="mmcblk0p66" ino=582 scontext=u:r:recovery:s0 tcontext=u:object_r:otapreopt_chroot_exec:s0 tclass=file permissive=1
03-04 01:20:38.152 776 776 I sh : type=1400 audit(0.0:1865): avc: denied { execute } for name="backuptool_postinstall.sh" dev="mmcblk0p66" ino=582 scontext=u:r:recovery:s0 tcontext=u:object_r:otapreopt_chroot_exec:s0 tclass=file permissive=1
03-04 01:20:38.152 776 776 I sh : type=1400 audit(0.0:1866): avc: denied { read open } for path="/postinstall/system/bin/backuptool_postinstall.sh" dev="mmcblk0p66" ino=582 scontext=u:r:recovery:s0 tcontext=u:object_r:otapreopt_chroot_exec:s0 tclass=file permissive=1
03-04 01:20:38.152 776 776 I sh : type=1400 audit(0.0:1867): avc: denied { execute_no_trans } for path="/postinstall/system/bin/backuptool_postinstall.sh" dev="mmcblk0p66" ino=582 scontext=u:r:recovery:s0 tcontext=u:object_r:otapreopt_chroot_exec:s0 tclass=file permissive=1
03-04 01:20:38.179 778 778 I mkdir : type=1400 audit(0.0:1868): avc: denied { create } for name="tmp" scontext=u:r:recovery:s0 tcontext=u:object_r:rootfs:s0 tclass=dir permissive=1
03-04 01:20:38.179 778 778 I mkdir : type=1400 audit(0.0:1869): avc: denied { associate } for name="tmp" scontext=u:object_r:rootfs:s0 tcontext=u:object_r:labeledfs:s0 tclass=filesystem permissive=1
03-04 01:20:39.034 771 771 I update_engine_sideload: [0303/192039.034516:INFO:postinstall_runner_action.cc(225)] Performing postinst (system/bin/otapreopt_script at /postinstall/system/bin/otapreopt_script) installed on device /dev/block/bootdevice/by-name/system_b and mountable device /dev/block/bootdevice/by-name/system_b
03-04 01:20:39.037 771 771 I update_engine_sideload: [0303/192039.034653:INFO:postinstall_runner_action.cc(232)] Format file for new system/bin/otapreopt_script is: data
03-04 01:20:39.036 785 785 I otapreopt_scrip: type=1400 audit(0.0:1870): avc: denied { read } for path="/system/bin/sh" dev="tmpfs" ino=22600 scontext=u:r:postinstall:s0 tcontext=u:object_r:tmpfs:s0 tclass=file permissive=1
03-04 01:20:39.036 785 785 I otapreopt_scrip: type=1400 audit(0.0:1871): avc: denied { execute } for path="/system/bin/sh" dev="tmpfs" ino=22600 scontext=u:r:postinstall:s0 tcontext=u:object_r:tmpfs:s0 tclass=file permissive=1
03-04 01:20:39.050 771 771 I update_engine_sideload: [0303/192039.050795:INFO:subprocess.cc(157)] Subprocess output:
03-04 01:20:39.050 771 771 I update_engine_sideload: Error: boot-complete not detected.
03-04 01:20:39.050 771 771 I update_engine_sideload:
03-04 01:20:39.055 583 583 I gpt-utils: gpt_disk_commit: Writing back primary GPT header
03-04 01:20:39.055 583 583 I gpt-utils: gpt_set_header: Block size is : 512
03-04 01:20:39.055 583 583 I gpt-utils: gpt_set_header: Writing back header to offset 512
03-04 01:20:39.055 583 583 I gpt-utils: gpt_disk_commit: Writing back primary partition array
03-04 01:20:39.055 583 583 I gpt-utils: gpt_set_pentry_arr : Block size is 512
03-04 01:20:39.055 583 583 I gpt-utils: gpt_set_pentry_arr: Writing partition entry array of size 9216 to offset 1024
03-04 01:20:39.056 771 771 I update_engine_sideload: [0303/192039.055961:INFO:postinstall_runner_action.cc(417)] All post-install commands succeeded
03-04 01:20:39.056 771 771 I update_engine_sideload: [0303/192039.056206:INFO:action_processor.cc(116)] ActionProcessor: finished last action PostinstallRunnerAction with code ErrorCode::kSuccess
03-04 01:20:39.056 771 771 I update_engine_sideload: [0303/192039.056270:INFO:update_attempter_android.cc(468)] Processing Done.
03-04 01:20:39.056 771 771 I update_engine_sideload: [0303/192039.056615:INFO:update_attempter_android.cc(476)] Update successfully applied, waiting to reboot.
03-04 01:20:39.056 771 771 I update_engine_sideload: [0303/192039.056663:INFO:dynamic_partition_control_android.cc(150)] Destroying [] from device mapper
03-04 01:20:39.056 771 771 E update_engine_sideload: [0303/192039.056758:ERROR:prefs.cc(85)] storage_->DeleteKey(key) failed.
03-04 01:20:39.056 771 771 I update_engine_sideload: [0303/192039.056804:INFO:metrics_utils.cc(366)] Updated Marker = 1/1/1970 0:16:38 GMT
03-04 01:20:39.057 771 771 I update_engine_sideload: [0303/192039.056902:INFO:dynamic_partition_control_android.cc(150)] Destroying [] from device mapper

Well and, after that there are only more selinux denials... Seems like it wanted to start my os, since I see packagenames of my (OS)Apps there.

I know, that was a lot of input all at once! Maybe it helps to shed a bit light into this... And at least you don't have to go though the whole logcat.txt