New issue
Advanced search Search tips

Issue 867842 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Aug 10
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug

Blocking:
issue 867738



Sign in to add a comment

[Cros] ZipFiles/FilesAppBrowserTest.Test/zipFileOpen* consistently fails in DEBUG

Project Member Reported by hbos@chromium.org, Jul 26

Issue description

Labels: Sheriff-Chromium
Adding sheriff label until tests have been disabled (or fixed).
Project Member

Comment 3 by bugdroid1@chromium.org, Jul 26

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/4810077ba30e7f6d975ca5d061f56ce35ad65787

commit 4810077ba30e7f6d975ca5d061f56ce35ad65787
Author: Noel Gordon <noel@chromium.org>
Date: Thu Jul 26 11:16:12 2018

Disable FilesAppBrowserTest zipFileOpen tests in DEBUG

NaCl module is crashing in DEBUG in the zipFileOpen* cases: causes the
DEBUG bots to TIMEOUT waiting for the unzipped file results.

Disable these tests in DEBUG.

Tbr: hbos@
Bug:  867738 , 867842 
Change-Id: If2717bcd2f427c7e8ff0bd5a532f0a9405bfc31d
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Reviewed-on: https://chromium-review.googlesource.com/1151176
Reviewed-by: Noel Gordon <noel@chromium.org>
Commit-Queue: Noel Gordon <noel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#578259}
[modify] https://crrev.com/4810077ba30e7f6d975ca5d061f56ce35ad65787/chrome/browser/chromeos/file_manager/file_manager_browsertest.cc

Labels: -Sheriff-Chromium
Status: Fixed (was: Assigned)
Blocking: 867738
Labels: OS-Chrome
This should probably not be "Fixed" until the problem fixed and tests are re-enabled but it's off the sheriff's queue, thanks for helping disable.
No worries.  I'm OK with "Fixed" here.  We will deal with the actual fix and test re-enable in  issue 867738 .
Cc: -yamaguchi@chromium.org noel@chromium.org
Owner: yamaguchi@chromium.org
Status: Assigned (was: Fixed)
Actually, this easy to reproduce locally

assertion "var_dict.Get(request::key::kOperation).is_int()" failed: file "../../chrome/browser/resources/chromeos/zip_archiver/cpp/module.cc", line 168, function: virtual void NaclArchiveInstance::HandleMessage(const pp::Var &)
** abort() called
** Signal 4 from untrusted code: pc=332c0015d740
[253423:253461:0726/214614.247545:ERROR:nacl_process_host.cc(262)] NaCl process exited with status 64512 (0xfc00)  // Handler for messages coming in from JS via postMessage().

CRASH@ chrome/browser/resources/chromeos/zip_archiver/cpp/module.cc", line 168

  virtual void HandleMessage(const pp::Var& var_message) {
    PP_DCHECK(var_message.is_dictionary());
    pp::VarDictionary var_dict(var_message);

    PP_DCHECK(var_dict.Get(request::key::kOperation).is_int());  <== CRASH
    int operation = var_dict.Get(request::key::kOperation).AsInt();

    if (request::IsPackRequest(operation))
      HandlePackMessage(var_dict, operation);
    else
      HandleUnpackMessage(var_dict, operation);
  }

yamaguchi-san@

Any reason the JS would send an invalid kOperation key?
I re-wrote the NaCl HandleMessage() to debug it, and it seems someone/thing is sending an _undefined_ kOperation in the first request sent to the NaCl module.
If I see an _undefined_ kOperation, I reset it to int 0 ...

  // Handler for messages coming in from JS via postMessage().
  virtual void HandleMessage(const pp::Var& var_message) {
    PP_DCHECK(var_message.is_dictionary());
    pp::VarDictionary var_dict(var_message);

    PP_DCHECK(var_dict.Get(request::key::kFileSystemId).is_string());
    const std::string file_system_id =
        var_dict.Get(request::key::kFileSystemId).AsString();

    PP_DCHECK(var_dict.Get(request::key::kRequestId).is_string());
    const std::string request_id =
        var_dict.Get(request::key::kRequestId).AsString();

    if (!var_dict.Get(request::key::kOperation).is_int()) {
      // Well what type of operation is it exactly: guess
      const pp::Var op = var_dict.Get(request::key::kOperation);
      std::string optype;
      if (op.is_string())
        optype.append("string");
      else if (op.is_undefined())
        optype.append("undefined");
      else if (op.is_null())
        optype.append("null");

      // Debug the request, show its keys
      std::string debug =
        "HandleMessage: FSI(" + file_system_id + ") RID (" + request_id + ")";
      printf("%s kOperation type [%s] \n", debug.c_str(), optype.c_str());

      std::string keys("kOperation is not int!\n  request keys were:");
      pp::VarArray array = var_dict.GetKeys();
      for (uint32_t i = 0; i < array.GetLength(); ++i)
         keys.append(" " + array.Get(i).DebugString());
      printf(" %s\n", keys.c_str());

      // now HACK: reset the dict kOperation to an int, with value 0.
      var_dict.Set(request::key::kOperation, 0);
      printf(" Forcing kOperation to int 0\n");
    }

    PP_DCHECK(var_dict.Get(request::key::kOperation).is_int());
    int operation = var_dict.Get(request::key::kOperation).AsInt();

    std::string debug =
      "HandleMessage: FSI(" + file_system_id + ") RID (" + request_id + ")";
    printf("%s kOperation [int] %d\n", debug.c_str(), operation);

    if (request::IsPackRequest(operation))
      HandlePackMessage(var_dict, operation);
    else
      HandleUnpackMessage(var_dict, operation);
  }

In the log the zipFileOpenDownloads test running DEBUG locally, I now see:

[14164:14164:0726/232936.414307:INFO:CONSOLE(0)] "Styling master document from stylesheets defined in HTML Imports is deprecated. Please refer to https://goo.gl/EGXzpw for possible migration paths.", source:  (0)
[14164:14164:0726/232939.415867:INFO:CONSOLE(156)] "at /file_manager/background.js:373:27: The number of file is 0. Not changed.", source: chrome-extension://oobinhbdbiehknkpbpejbbpdbkdjmoco/test_util.js (156)
Still waiting for the following processes to finish:
  ./out/Debug/browser_tests --disable-gpu-process-for-dx12-vulkan-info-collection --gtest_also_run_disabled_tests --gtest_filter=ZipFiles/FilesAppBrowserTest.Test/zipFileOpenDownloads --single_process --test-launcher-output=/tmp/.org.chromium.Chromium.wU9fEs/resultsWVuMuO/test_results.xml --user-data-dir=/tmp/.org.chromium.Chromium.wU9fEs/dhDxvz8
[14164:14164:0726/232943.872558:INFO:CONSOLE(156)] "at StepsRunner.<anonymous> (/file_manager/zip_files.js:45:18): waitForFiles: expected: [["image.png","272 bytes","PNG image","Sep 2, 2013, 10:01 PM"],["text.txt","51 bytes","Plain text","Sep 2, 2013, 10:01 PM"]] actual [["archive.zip","533 bytes","Zip archive","Jan 1, 2014, 1:00 AM"]].", source: chrome-extension://oobinhbdbiehknkpbpejbbpdbkdjmoco/test_util.js (156)
[1,2098178304:13:29:45.617317] Native Client module will be loaded at base address 0x00003d9b00000000
[1,2098178304:13:29:45.898568] Native Client module will be loaded at base address 0x00004d7900000000
HandleMessage: FSI(~/Downloads/archive.zip) RID (-1) kOperation type [undefined] 
 kOperation is not int!
  request keys were: Var<'archive_size'> Var<'encoding'> Var<'file_system_id'> Var<'operation'> Var<'request_id'>
 Forcing kOperation to int 0
HandleMessage: FSI(~/Downloads/archive.zip) RID (-1) kOperation [int] 0
HandleMessage: FSI(~/Downloads/archive.zip) RID (-1) kOperation [int] 3
[14164:14164:0726/232946.170258:INFO:CONSOLE(6048)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (6048)
...

Not sure if that helps, or is safe to do, but the test does PASS with that change. Full log attached.
ZipFiles:FilesAppBrowserTest.Test:zipFileOpenDownloads.DEBUG.log.txt
11.8 KB View Download
Summary: [Cros] ZipFiles/FilesAppBrowserTest.Test/zipFileOpen* consistently fails in DEBUG (was: ZipFiles/FilesAppBrowserTest.Test/zipFileOpen* consistently fails on linux-chromeos-dbg)
Cc: fukino@chromium.org
Looks to me like this is exposing an unzip race condition (and my feeling this is affecting Files app users).
Cc: slangley@chromium.org
Cc: yamaguchi@chromium.org
Owner: noel@chromium.org
Seems Operation type is undefined.

HandleMessage: FSI(~/Downloads/archive.zip) RID (-1) kOperation type [undefined] 
 kOperation is not int!
  request keys were: Var<'archive_size'> Var<'encoding'> Var<'file_system_id'> Var<'operation'> Var<'request_id'>
 Forcing kOperation to int 0

Looking at zip_acrhiver results.js 

https://cs.chromium.org/chromium/src/chrome/browser/resources/chromeos/zip_archiver/js/request.js?q=isPackRequest&dr=CSs&l=69

  /**
   * Defines request operations. These operation should be the same as the
   * operations on the NaCL side. FILE_SYSTEM_ID and REQUEST_ID are mandatory
   * for all unpack requests, while COMPRESSOR_ID is required for all pack
   * requests. All the values of unpacking operations must be smaller than any
   * packing operation (except errors).
   * @enum {number}
   */
  Operation: {
    READ_METADATA_DONE: 1,
    READ_CHUNK: 2,
    READ_CHUNK_DONE: 3,
    ...

"READ_METADATA" is not defined as an operation in the JS code.  It is defined as an operation in the NaCL C++ code.
Project Member

Comment 15 by bugdroid1@chromium.org, Aug 10

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/db7657b8d3d775d3c9ce4dc338d03b0a16e808bc

commit db7657b8d3d775d3c9ce4dc338d03b0a16e808bc
Author: Noel Gordon <noel@chromium.org>
Date: Fri Aug 10 12:17:31 2018

Add a missing ZipArchiver operation define: READ_METADATA

READ_METADATA was defined in the NaCL C++ but wasn't defined in the JS
code. It is a requirement of the ZipArchiver design that the operation
values are defined, and have the same values, in the C++ and JS code.

This is likely causing crashes in the field: it certainly caused CHECK
stop crashes in DEBUG C++ NaCL code in integration test (ZipArchiver's
unit_tests did not exhibit the bug at all).

Define READ_METADATA in the JS, add protective code to check operation
validity (make it throw, if not) when constructing pack messages in JS
that will be sent to the NaCL module C++ code.

Re-enable the zip integration tests that were disabled due to this bug
in  issue 867738 . (Those tests discovered  bug 867842 ).

Test: browser_test --gtest-filter="Zip*FilesApp*"
No-try: true
Bug:  867842 ,  867738 
Change-Id: Ide44e60a47d9e87322115dc66017e8e0313b2162
Reviewed-on: https://chromium-review.googlesource.com/1169485
Commit-Queue: Noel Gordon <noel@chromium.org>
Reviewed-by: Luciano Pacheco <lucmult@chromium.org>
Reviewed-by: Tatsuhisa Yamaguchi <yamaguchi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#582123}
[modify] https://crrev.com/db7657b8d3d775d3c9ce4dc338d03b0a16e808bc/chrome/browser/chromeos/file_manager/file_manager_browsertest.cc
[modify] https://crrev.com/db7657b8d3d775d3c9ce4dc338d03b0a16e808bc/chrome/browser/resources/chromeos/zip_archiver/cpp/request.h
[modify] https://crrev.com/db7657b8d3d775d3c9ce4dc338d03b0a16e808bc/chrome/browser/resources/chromeos/zip_archiver/js/decompressor.js
[modify] https://crrev.com/db7657b8d3d775d3c9ce4dc338d03b0a16e808bc/chrome/browser/resources/chromeos/zip_archiver/js/request.js

Status: Fixed (was: Assigned)
FTR, https://codereview.chromium.org/2807063002/patch/60001/70027 was the change that deleted the READ_METADATA value.  #15 above brings it back.

Cc: yawano@chromium.org
 Issue 782571  has been merged into this issue.

Sign in to add a comment