I don't have any insight into chrome startup log. Handing to stevenjb.

It doesn't sound like the bug is within chrome per-se, but rather the infrastructure somehow. We're correctly saving the log to /var/log/ui/ under normal circumstances (e.g. on a dev machine), but somehow the log isn't being archived correctly in tests.

I can add it to the huge list of things for gardeners to investigate when not gardening, but it seems like something that someone more familiar with how we gather logs from test runs might be able to take a look at.

Yeah, from chrome's perspective there is nothing special about this log file.

+derat on the off chance he has an idea why this might be happening.

Have you looked into /var/log/chrome/?

I don't know anything about how log files are gathered from tests, but yeah, Chrome logs things to different places at different times:

- /var/log/ui/ui.LATEST before logging is initialized (we actually redirect stdout and stderr from session_manager here, so this is basically stuff that Chrome writes to stderr)

- /var/log/chrome/chrome at the login screen

- /home/chronos/user/log after the session starts

(/home/chronos/user/log/chrome is the file for the last one, I think.)

/var/log/chrome is also an empty file for the one run I care about:

See chrome_20161206-062734 here:
https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/89287533-chromeos-test/chromeos6-row2-rack7-host11/desktopui_MashLogin/sysinfo/var/log/chrome/?pli=1

The CHECK is early in chrome startup, before the login screen. I would expect the log to appear in /var/log/ui, and when I run on my local device it shows up there.

The file is only empty when the lab uploads artifacts.

Could chrome be holding a file open while dumping core and that prevents some sort of log-collector from copying it?

Not sure if it's happening here, but in the past I think I've had problems due to the test-output-archiving system trying to save only the incremental diff in logs between test runs and missing the output that was responsible for the failure.

akeshet, this really sounds more like a test infra problem than a chrome problem? Can this get assigned to someone in infra, or at least into a triage queue?

+jrbarnette today's deputy

+dshi who knows about log collection from DUTs  -- any idea what might be going on?

When a test fails, autotest collect everything in /var/log. So having an empty file in the logs collected likely means the file is indeed empty in the dut.

Is it possible to reproduce the issue on a dut? That is, run the test, after it fails, check the ui file in autotest result folder and the one on dut. If they are not the same, could it be a timing issue? Maybe autotest needs to wait longer for the ui file being generated?

The log collection usually happens right after the test is finished. Maybe adding some wait time in test code can help?

This is a chrome problem, not a lab problem. If you run an official build on a device, and you hit a CHECK during startup, the /var/log/ui log file is empty. The problem goes away if you don't build an official build (for example, you use go/simplechrome with default settings).

Repro:
* Patch in https://codereview.chromium.org/2560953003
* Use go/simplechrome to deploy to device
* start ui
-> Message "Check failed: false" appears in /var/log/ui

* In cros sdk, edit out/$SDK_BOARD/args.gn and add is_official_build
* Rebuild and redeploy
* start ui
-> File in /var/log/ui is empty

I looked in base/logging.cc and don't see any Chrome OS specific behavior. CHECK turns into LOG(FATAL) which should output a message, output a stack trace (only on non-official builds) and die.

Does anyone have a contact who is familiar with logging? Could this be related to crash reporting?

Since this bug hasn't had any real activity in a while, and it seemed like it didn't require specialized knowledge, I just went and took a look at the Chrome logging code.

The thing that jumped out at me was this section in src/base/logging.h:

(https://chromium.googlesource.com/chromium/src/base/+/7fb93ff3f30019989dded5785f991e01c1e107b8/logging.h#548)

    #if defined(OFFICIAL_BUILD) && defined(NDEBUG)

    // Make all CHECK functions discard their log strings to reduce code bloat, and
    // improve performance, for official release builds.
    //
    // This is not calling BreakDebugger since this is called frequently, and
    // calling an out-of-line function instead of a noreturn inline macro prevents
    // compiler optimizations.
    #define CHECK(condition) \
      UNLIKELY(!(condition)) ? IMMEDIATE_CRASH() : EAT_STREAM_PARAMETERS

It seems that the lack of a log message for a CHECK in an official release build is entirely intentional.

There might be something else we can do on Chrome OS. I know we made an attempt on ARC to store some strings on the stack on a crash, so they are visible in the minidump. But then that means including all the string data in the executable.

Just printing "Check failed", even without a line number or message, would be helpful.

I'm not going to get around to this anytime soon.

This may have been fixed by the my fixes for this bug:
https://bugs.chromium.org/p/chromium/issues/detail?id=724273