attached log file.

Deleted: update_engine.20171205-110240.txt 62.7 KB

update_engine.20171205-110240.txt 62.7 KB View Download

The thing that bothers me is the log boot partition payload application time. I looked at the operations for the kernel partition, they are as follows:

Kernel install operations:
  0: SOURCE_BSDIFF
    Data offset: 54570360
    Data length: 5895236
    Source: 4 extents (1477 blocks)
      (0,1) (16,1474) (1494,1) (1497,1)
    Destination: 4 extents (1473 blocks)
      (0,1) (16,1470) (1490,1) (1493,1)
  1: ZERO
    Destination: 1 extent (15 blocks)
      (1,15)
  2: SOURCE_COPY
    Source: 1 extent (2 blocks)
      (1490,2)
    Destination: 1 extent (2 blocks)
      (1486,2)
  3: ZERO
    Destination: 1 extent (1 block)
      (1488,1)
  4: SOURCE_COPY
    Source: 1 extent (1 block)
      (1493,1)
    Destination: 1 extent (1 block)
      (1489,1)
  5: SOURCE_COPY
    Source: 1 extent (2 blocks)
      (1495,2)
    Destination: 1 extent (2 blocks)
      (1491,2)
  6: ZERO
    Destination: 1 extent (512 blocks)
      (1494,512)
  7: ZERO
    Destination: 1 extent (512 blocks)
      (2006,512)
  8: ZERO
    Destination: 1 extent (512 blocks)
      (2518,512)
  9: ZERO
    Destination: 1 extent (512 blocks)
      (3030,512)
  10: ZERO
    Destination: 1 extent (512 blocks)
      (3542,512)
  11: ZERO
    Destination: 1 extent (42 blocks)
      (4054,42)
  12: REPLACE
    Data offset: 60465596
    Data length: 264
    Destination: 1 extent (1 block)
      (18446744073709551615,1)

However the last (12th) operation has a very weird extent offset. Have to investigate why. 

Except for the kernel partition time, the system update time looks normal with regard to new changes. kernel update time should be quite fast, just a few seconds should be enough. The fact that it takes 3 minutes is case to be worried about. 

Please, let me know if this can easily be reproduced with the same device.

From a recent M64 dev build for cave I see the following paygentestdev logs.

https://storage.cloud.google.com/chromeos-autotest-results/160251000-chromeos-test/chromeos2-row8-rack6-host4/autoupdate_EndToEndTest.paygen_au_dev_delta.tgz

It updated from 10172.0.0(M64) => 10176.4.0. It took only a little more than one minute to do the update and the operations seems to be similar.

[1205/015131:INFO:delta_performer.cc(684)] Starting to apply update payload operations
[1205/015136:INFO:delta_performer.cc(217)] Completed 1842/10594 operations (17%), 2408240/60018280 bytes downloaded (4%), overall progress 10%
[1205/015143:INFO:delta_performer.cc(217)] Completed 3391/10594 operations (32%), 5062448/60018280 bytes downloaded (8%), overall progress 20%
[1205/015150:INFO:delta_performer.cc(217)] Completed 5509/10594 operations (52%), 5668656/60018280 bytes downloaded (9%), overall progress 30%
[1205/015153:INFO:delta_performer.cc(217)] Completed 7192/10594 operations (67%), 8404784/60018280 bytes downloaded (14%), overall progress 40%
[1205/015156:INFO:update_attempter.cc(1140)] Already updated boot flags. Skipping.
[1205/015157:INFO:delta_performer.cc(217)] Completed 8688/10594 operations (82%), 10977072/60018280 bytes downloaded (18%), overall progress 50%
[1205/015159:INFO:delta_performer.cc(217)] Completed 8919/10594 operations (84%), 21610288/60018280 bytes downloaded (36%), overall progress 60%
[1205/015218:INFO:delta_performer.cc(217)] Completed 9121/10594 operations (86%), 32423728/60018280 bytes downloaded (54%), overall progress 70%
[1205/015232:INFO:delta_performer.cc(217)] Completed 9648/10594 operations (91%), 42024752/60018280 bytes downloaded (70%), overall progress 80%
[1205/015240:INFO:delta_performer.cc(217)] Completed 10271/10594 operations (96%), 50429744/60018280 bytes downloaded (84%), overall progress 90%
[1205/015243:INFO:delta_performer.cc(376)] Opening /dev/mmcblk0p2 partition without O_DSYNC
[1205/015243:INFO:delta_performer.cc(133)] Caching writes.
[1205/015243:INFO:delta_performer.cc(388)] Applying 12 operations to partition "boot"
[1205/015244:INFO:delta_performer.cc(217)] Completed 10594/10594 operations (100%), 60018280/60018280 bytes downloaded (100%), overall progress 100%

But the update_engine logs says the source was from stable-channel. Your attached update_engine log says it was from dev-channel. I'm not sure how much a difference it could have. Do we intentionally change the image to stable-channel on autotests? This case looks weird to me.

Deleted: update_engine.log 38.4 KB

update_engine.log 38.4 KB View Download

@abodeti: Can you give the exact link to the source and target images for the payload you tried?

Devices in the lab run on test images which show up as stable-channel. 

Rep# 4

Source image page: https://pantheon.corp.google.com/storage/browser/chromeos-releases/dev-channel/cave/10172.0.0

Target image page: https://pantheon.corp.google.com/storage/browser/chromeos-releases/dev-channel/cave/10176.4.0/

I just created a delta from source and target images in #6 and it doesn't have the 12th operation. 

Kernel install operations:
  0: SOURCE_BSDIFF
    Data offset: 54570360
    Data length: 5895236
    Source: 4 extents (1477 blocks)
      (0,1) (16,1474) (1494,1) (1497,1)
    Destination: 4 extents (1473 blocks)
      (0,1) (16,1470) (1490,1) (1493,1)
  1: ZERO
    Destination: 1 extent (15 blocks)
      (1,15)
  2: SOURCE_COPY
    Source: 1 extent (2 blocks)
      (1490,2)
    Destination: 1 extent (2 blocks)
      (1486,2)
  3: ZERO
    Destination: 1 extent (1 block)
      (1488,1)
  4: SOURCE_COPY
    Source: 1 extent (1 block)
      (1493,1)
    Destination: 1 extent (1 block)
      (1489,1)
  5: SOURCE_COPY
    Source: 1 extent (2 blocks)
      (1495,2)
    Destination: 1 extent (2 blocks)
      (1491,2)
  6: ZERO
    Destination: 1 extent (512 blocks)
      (1494,512)
  7: ZERO
    Destination: 1 extent (512 blocks)
      (2006,512)
  8: ZERO
    Destination: 1 extent (512 blocks)
      (2518,512)
  9: ZERO
    Destination: 1 extent (512 blocks)
      (3030,512)
  10: ZERO
    Destination: 1 extent (512 blocks)
      (3542,512)
  11: ZERO
    Destination: 1 extent (42 blocks)
      (4054,42)


I'm not sure if we are messing stuff when signing the payload or not. I'm looking more into it.

Regarding the slowness of the kernel partition, update it seems like a low bandwidth situation. The most of the time is consumed on downloading the last part of the payload (about 5MB based on this payload). Once it finishes downloading the last 13 operations are applied successfully. 


But, why is there any extra operation at the end? I found out that it is intended based on update_engine/payload_consumer/delta_performer.cc:1588:

    // No hash is present for an operation that has data blobs. This shouldn't
    // happen normally for any client that has this code, because the
    // corresponding update should have been produced with the operation
    // hashes. So if it happens it means either we've turned operation hash
    // generation off in DeltaDiffGenerator or it's a regression of some sort.
    // One caveat though: The last operation is a dummy signature operation
    // that doesn't have a hash at the time the manifest is created. So we
    // should not complaint about that operation. This operation can be
    // recognized by the fact that it's offset is mentioned in the manifest.
    if (manifest_.signatures_offset() &&
        manifest_.signatures_offset() == operation.data_offset()) {
      LOG(INFO) << "Skipping hash verification for signature operation "
                << next_operation_num_ + 1;
    } else {
      if (install_plan_->hash_checks_mandatory) {
        LOG(ERROR) << "Missing mandatory operation hash for operation "
                   << next_operation_num_ + 1;
        return ErrorCode::kDownloadOperationHashMissingError;
      }

      LOG(WARNING) << "Cannot validate operation " << next_operation_num_ + 1
                   << " as there's no operation hash in manifest";
    }


To sum it up, I don't think there is any problem here. It is just a slow network connection. So feel free to mark it as won't fix if you don't have any objections.

Not reprod on another cave device. I will mark it as wontfix now.  

[1205/155747:INFO:delta_performer.cc(1505)] Metadata hash signature matches value in Omaha response.
[1205/155747:INFO:delta_performer.cc(838)] Converting update information from old format.
[1205/155747:INFO:delta_performer.cc(403)] PartitionInfo old system sha256: yDc2rSqLTSN3vu/5LkWSbHG2yptN0u4EeSCSgdxaQbg= size: 1835008000
[1205/155747:INFO:delta_performer.cc(403)] PartitionInfo new system sha256: W8EqR9NgRySVR81yVxJEvrtfIhF1eOae/bU51YzR6Zc= size: 1835008000
[1205/155747:INFO:delta_performer.cc(403)] PartitionInfo old boot sha256: bqKqqoMZNPL/JIH9Ujv+zmPgvobAtPqxgaBs69k/6Iw= size: 16777216
[1205/155747:INFO:delta_performer.cc(403)] PartitionInfo new boot sha256: 84pXZCv8Rvksv4nMwo+dBKWrdrzV7fLIUMxejsNiv6w= size: 16777216
[1205/155747:INFO:delta_performer.cc(376)] Opening /dev/mmcblk0p5 partition without O_DSYNC
[1205/155747:INFO:delta_performer.cc(133)] Caching writes.
[1205/155747:INFO:delta_performer.cc(388)] Applying 10523 operations to partition "system"
[1205/155747:INFO:delta_performer.cc(684)] Starting to apply update payload operations
[1205/155757:INFO:delta_performer.cc(217)] Completed 422/10536 operations (4%), 9962914/61158517 bytes downloaded (16%), overall progress 10%
[1205/155804:INFO:delta_performer.cc(217)] Completed 2318/10536 operations (22%), 11339170/61158517 bytes downloaded (18%), overall progress 20%
[1205/155811:INFO:delta_performer.cc(217)] Completed 4385/10536 operations (41%), 12240290/61158517 bytes downloaded (20%), overall progress 30%
[1205/155817:INFO:delta_performer.cc(217)] Completed 5901/10536 operations (56%), 14910882/61158517 bytes downloaded (24%), overall progress 40%
[1205/155821:INFO:delta_performer.cc(217)] Completed 7586/10536 operations (72%), 18204066/61158517 bytes downloaded (29%), overall progress 50%
[1205/155825:INFO:delta_performer.cc(217)] Completed 8885/10536 operations (84%), 22021538/61158517 bytes downloaded (36%), overall progress 60%
[1205/155839:INFO:delta_performer.cc(217)] Completed 8904/10536 operations (84%), 34259610/61158517 bytes downloaded (56%), overall progress 70%
[1205/155857:INFO:delta_performer.cc(217)] Completed 9483/10536 operations (90%), 43172506/61158517 bytes downloaded (70%), overall progress 80%
[1205/155906:INFO:delta_performer.cc(217)] Completed 9694/10536 operations (92%), 53879506/61158517 bytes downloaded (88%), overall progress 90%
[1205/155910:INFO:delta_performer.cc(376)] Opening /dev/mmcblk0p4 partition without O_DSYNC
[1205/155910:INFO:delta_performer.cc(133)] Caching writes.
[1205/155910:INFO:delta_performer.cc(388)] Applying 13 operations to partition "boot"
[1205/155912:INFO:delta_performer.cc(1599)] Skipping hash verification for signature operation 10536
[1205/155912:INFO:delta_performer.cc(1402)] Extracted signature data of size 264 at 60465596
[1205/155912:INFO:delta_performer.cc(217)] Completed 10536/10536 operations (100%), 61158517/61158517 bytes downloaded (100%), overall progress 100%
[1205/155912:INFO:libcurl_http_fetcher.cc(433)] HTTP response code: 200
[1205/155912:INFO:libcurl_http_fetcher.cc(509)] Transfer completed (200), 61158517 bytes downloaded
[1205/155912:INFO:multi_range_http_fetcher.cc(167)] Received transfer complete.
[1205/155912:INFO:multi_range_http_fetcher.cc(124)] TransferEnded w/ code 200

Deleted: update_engine.20171205-155432.txt 43.4 KB

update_engine.20171205-155432.txt 43.4 KB View Download