Android OTA executes the update_engine_client command and reports ErrorCode::kDownloadInvalidMetadataSize (32)
Manual execution of the update_engine_client
command fails, and multiple attempts to hit the OTA package have no effect. The following error is still reported.
[INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_IDLE (0), 0)
[INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_UPDATE_AVAILABLE (2), 0)
[INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_DOWNLOADING (3), 4.4213e-05)
[INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_IDLE (0), 0)
[INFO:update_engine_client_android.cc(98)] onPayloadApplicationComplete(ErrorCode::kDownloadInvalidMetadataSize (32))
Finally found the reason is no line break! (Emmmmmm...)
Everyone pay attention to the --headers
parameter here, which must be separated by newlines. (For the reasons, see the analysis below)
update_engine_client \
--update \
--follow \
--payload=file:///data/ota_package/update.zip \
--offset=9053 \
--size=555750616 \
--headers="FILE_HASH=BMYgJY7CIoJCsowiXgi3L4kK4Og+aGOdfpzUGURCDvY=
FILE_SIZE=555750616
METADATA_HASH=33c52T0k5Xi7Q3kSx8tJszDtTzNNYQRTZTLiEUTbkLs=
METADATA_SIZE=87205"
The analysis process is rather verbose, mainly to record how my ideas for troubleshooting have changed.
1. Try to change the machine to eliminate the machine problem
The problem still exists after the replacement, not a device problem
2. Play the OTA package many times, and test it, and preliminarily rule out the problem of the OTA package
./build/tools/releasetools/ota_from_target_files
method to manually open the ota package. I tried to replace the lunch combo, but it didn’t work. It doesn’t seem to be a packaging problem.3. Check ota.py
#!/usr/bin/env python
# -*- coding=utf8 -*-
import sys
import zipfile
def main():
if len(sys.argv) != 2:
sys.stderr.write('Use: %s <ota_file.zip>\n' % sys.argv[0])
return 1
otazip = zipfile.ZipFile(sys.argv[1], 'r')
payload_info = otazip.getinfo('payload.bin')
payload_offset = payload_info.header_offset + len(payload_info.FileHeader())
payload_size = payload_info.file_size
payload_localtion = '/data/ota_package/update.zip'
headers = otazip.read("payload_properties.txt")
print(
'update_engine_client --update --follow --payload=file://{payload_localtion}'
' --offset={payload_offset} --size={payload_size}'
' --headers="{headers}"').format(**locals())
return 0
if __name__ == '__main__':
sys.exit(main())
Manually decompress the ota package and open the payload_properties.txt
file to view
$ ls
care_map.txt compatibility.zip META-INF payload.bin payload_properties.txt
$ cat payload_properties.txt
FILE_HASH=BMYgJY7CIoJCsowiXgi3L4kK4Og+aGOdfpzUGURCDvY=
FILE_SIZE=555750616
METADATA_HASH=33c52T0k5Xi7Q3kSx8tJszDtTzNNYQRTZTLiEUTbkLs=
METADATA_SIZE=87205
No parsing error for the parameter
4. Try other ways to flash ota
Attempt to enter recovery, but failed (reason unknown)
5. Grasp the logcat analysis of the failed update_engine_client command
07-20 02:53:42.184 1011 1011 W update_engine: [0720/025342.184628:WARNING:update_attempter_android.cc(181)] Unable to decode base64 file hash: BMYgJY7CIoJCsowiXgi3L4kK4Og+aGOdfpzUGURCDvY= FILE_SIZE=555750616 METADATA_HASH=33c52T0k5Xi7Q3kSx8tJszDtTzNNYQRTZTLiEUTbkLs= METADATA_SIZE=87205
07-20 02:53:42.187 1011 1011 I update_engine: [0720/025342.187518:INFO:update_attempter_android.cc(246)] Using this install plan:
07-20 02:53:42.187 1011 1011 I update_engine: [0720/025342.187676:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: A, target_slot: B, url: file:///data/ota_package/update.zip, payload: (size: 555750616, metadata_size: 0, metadata signature: , hash: , payload type: unknown), hash_checks_mandatory: true, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true
07-20 02:53:42.187 1011 1011 I update_engine: [0720/025342.187840:INFO:update_attempter_android.cc(542)] Already updated boot flags. Skipping.
07-20 02:53:42.187 1011 1011 I update_engine: [0720/025342.187892:INFO:update_attempter_android.cc(562)] Scheduling an action processor start.
07-20 02:53:42.189 1011 1011 I update_engine: [0720/025342.189407:INFO:metrics_utils.cc(336)] Number of Reboots during current update attempt = 0
07-20 02:53:42.189 1011 1011 I update_engine: [0720/025342.189855:INFO:metrics_utils.cc(344)] Payload Attempt Number = 1
07-20 02:53:42.190 1011 1011 I update_engine: [0720/025342.190252:INFO:metrics_utils.cc(361)] Update Timestamp Start = 1/1/1970 0:44:02 GMT
07-20 02:53:42.190 1011 1011 I update_engine: [0720/025342.190612:INFO:action_processor.cc(46)] ActionProcessor: starting InstallPlanAction
07-20 02:53:42.190 1011 1011 I update_engine: [0720/025342.190686:INFO:action_processor.cc(116)] ActionProcessor: finished InstallPlanAction with code ErrorCode::kSuccess
07-20 02:53:42.190 1011 1011 I update_engine: [0720/025342.190737:INFO:action_processor.cc(143)] ActionProcessor: starting DownloadAction
07-20 02:53:42.190 1011 1011 I update_engine: [0720/025342.190794:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: A, target_slot: B, url: file:///data/ota_package/update.zip, payload: (size: 555750616, metadata_size: 0, metadata signature: , hash: , payload type: unknown), hash_checks_mandatory: true, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true
07-20 02:53:42.190 1011 1011 I update_engine: [0720/025342.190865:INFO:download_action.cc(200)] Marking new slot as unbootable
07-20 02:53:42.191 8304 8304 I update_engine_client: [INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_IDLE (0), 0)
07-20 02:53:42.192 8304 8304 I update_engine_client: [INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_UPDATE_AVAILABLE (2), 0)
07-20 02:53:42.196 1011 1011 I update_engine: [0720/025342.196508:INFO:multi_range_http_fetcher.cc(45)] starting first transfer
07-20 02:53:42.196 1011 1011 I update_engine: [0720/025342.196731:INFO:multi_range_http_fetcher.cc(74)] starting transfer of range 9053+555750616
07-20 02:53:42.197 8304 8304 I update_engine_client: [INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_DOWNLOADING (3), 4.57705e-05)
07-20 02:53:42.198 1011 1011 I update_engine: [0720/025342.198474:INFO:delta_performer.cc(210)] Completed 0/? operations, 16384/555750616 bytes downloaded (0%), overall progress 0%
07-20 02:53:42.198 1011 1011 E update_engine: [0720/025342.198630:ERROR:delta_performer.cc(451)] Mandatory metadata size in Omaha response (0) is missing/incorrect, actual = 87205
07-20 02:53:42.198 1011 1011 E update_engine: [0720/025342.198698:ERROR:download_action.cc(337)] Error ErrorCode::kDownloadInvalidMetadataSize (32) in DeltaPerformer's Write method when processing the received payload -- Terminating processing
07-20 02:53:42.198 1011 1011 I update_engine: [0720/025342.198769:INFO:delta_performer.cc(314)] Discarding 24 unused downloaded bytes
07-20 02:53:42.198 1011 1011 I update_engine: [0720/025342.198842:INFO:multi_range_http_fetcher.cc(172)] Received transfer terminated.
07-20 02:53:42.198 1011 1011 I update_engine: [0720/025342.198889:INFO:multi_range_http_fetcher.cc(124)] TransferEnded w/ code 200
07-20 02:53:42.198 1011 1011 I update_engine: [0720/025342.198936:INFO:multi_range_http_fetcher.cc(126)] Terminating.
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.198988:INFO:action_processor.cc(116)] ActionProcessor: finished DownloadAction with code ErrorCode::kDownloadInvalidMetadataSize
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199048:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199095:INFO:update_attempter_android.cc(431)] Processing Done.
07-20 02:53:42.199 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_number,801,1,802,1]
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199480:INFO:metrics_reporter_android.cc(29)] uploading 1 to histogram for metric ota_update_engine_attempt_number
07-20 02:53:42.199 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_payload_type,801,0,802,1]
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199578:INFO:metrics_reporter_android.cc(29)] uploading 0 to histogram for metric ota_update_engine_attempt_payload_type
07-20 02:53:42.199 8304 8304 I update_engine_client: [INFO:update_engine_client_android.cc(90)] onStatusUpdate(UPDATE_STATUS_IDLE (0), 0)
07-20 02:53:42.199 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_duration_boottime_in_minutes,801,0,802,1]
07-20 02:53:42.199 8304 8304 I update_engine_client: [INFO:update_engine_client_android.cc(98)] onPayloadApplicationComplete(ErrorCode::kDownloadInvalidMetadataSize (32))
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199755:INFO:metrics_reporter_android.cc(29)] uploading 0 to histogram for metric ota_update_engine_attempt_duration_boottime_in_minutes
07-20 02:53:42.199 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_duration_monotonic_in_minutes,801,0,802,1]
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199837:INFO:metrics_reporter_android.cc(29)] uploading 0 to histogram for metric ota_update_engine_attempt_duration_monotonic_in_minutes
07-20 02:53:42.199 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_payload_size_mib,801,530,802,1]
07-20 02:53:42.199 1011 1011 I update_engine: [0720/025342.199898:INFO:metrics_reporter_android.cc(29)] uploading 530 to histogram for metric ota_update_engine_attempt_payload_size_mib
07-20 02:53:42.199 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_result,801,3,802,1]
07-20 02:53:42.200 1011 1011 I update_engine: [0720/025342.200026:INFO:metrics_reporter_android.cc(29)] uploading 3 to histogram for metric ota_update_engine_attempt_result
07-20 02:53:42.200 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_error_code,801,32,802,1]
07-20 02:53:42.200 1011 1011 I update_engine: [0720/025342.200085:INFO:metrics_reporter_android.cc(29)] uploading 32 to histogram for metric ota_update_engine_attempt_error_code
07-20 02:53:42.200 1011 1011 I sysui_multi_action: [757,804,799,ota_update_engine_attempt_current_bytes_downloaded_mib,801,16384,802,1]
07-20 02:53:42.200 1011 1011 I update_engine: [0720/025342.200232:INFO:metrics_reporter_android.cc(29)] uploading 16384 to histogram for metric ota_update_engine_attempt_current_bytes_downloaded_mib
These two lines in the log gave me clues
The first line of warning, there is a problem with the base64 hash here, it seems that there is an error in separating the string
07-20 02:53:42.184 1011 1011 W update_engine: [0720/025342.184628:WARNING:update_attempter_android.cc(181)] Unable to decode base64 file hash: BMYgJY7CIoJCsowiXgi3L4kK4Og+aGOdfpzUGURCDvY= FILE_SIZE=555750616 METADATA_HASH=33c52T0k5Xi7Q3kSx8tJszDtTzNNYQRTZTLiEUTbkLs= METADATA_SIZE=87205
The following line further explains (the second line), the parsing was not successful (the hash value is empty)
07-20 02:53:42.187 1011 1011 I update_engine: [0720/025342.187676:INFO:install_plan.cc(83)] InstallPlan: new_update, version: , source_slot: A, target_slot: B, url: file:///data/ota_package/update.zip, payload: (size: 555750616, metadata_size: 0, metadata signature: , hash: , payload type: unknown), hash_checks_mandatory: true, powerwash_required: false, switch_slot_on_reboot: true, run_post_install: true
Find the code corresponding to the first line of log
system/update_engine/update_attempter_android.cc
bool UpdateAttempterAndroid::ApplyPayload(
const string& payload_url,
int64_t payload_offset,
int64_t payload_size,
const vector<string>& key_value_pair_headers,
brillo::ErrorPtr* error) {
...// Omit
std::map<string, string> headers;
for (const string& key_value_pair : key_value_pair_headers) {
string key;
string value;
if (!brillo::string_utils::SplitAtFirst(
key_value_pair, "=", &key, &value, false)) {
return LogAndSetError(
error, FROM_HERE, "Passed invalid header: " + key_value_pair);
}
if (!headers.emplace(key, value).second)
return LogAndSetError(error, FROM_HERE, "Passed repeated key: " + key);
}
...//Omit
if (!brillo::data_encoding::Base64Decode(headers[kPayloadPropertyFileHash],
&payload.hash)) {
LOG(WARNING) << "Unable to decode base64 file hash: "
<< headers[kPayloadPropertyFileHash];
}
Find the place where the ApplyPayload function is called, and look up layer by layer
int UpdateEngineClientAndroid::OnInit() {}--->
Status BinderUpdateEngineAndroidService::applyPayload(...) --->
bool UpdateAttempterAndroid::ApplyPayload(...)
In the int UpdateEngineClientAndroid::OnInit() {}
function, it is found that the --headers=
parameter of the command line is divided by \n
here, so the parameters must be separated by newlines.
The problem was found.
if (FLAGS_update) {
std::vector<std::string> headers = base::SplitString(
FLAGS_headers, "\n", base::KEEP_WHITESPACE, base::SPLIT_WANT_NONEMPTY);
std::vector<android::String16> and_headers;
for (const auto& header : headers) {
and_headers.push_back(android::String16{header.data(), header.size()});
}
Status status = service_->applyPayload(
android::String16{FLAGS_payload.data(), FLAGS_payload.size()},
FLAGS_offset,
FLAGS_size,
and_headers);
if (!status.isOk())
return ExitWhenIdle(status);
}