ErrorCode::kDownloadInvalidMetadataSize (32)

created at 08-12-2021 views: 20

description

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))

solution first

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"

analysis process

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

  1. Make dist to play ota package
  2. Make otapackage way to play ota package
  3. use ./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);
 }

created at:08-12-2021
edited at: 08-12-2021: