Issue 735482  has been merged into this issue.

Chrisha, mind assigning to the right person within Chrome to help out?

The log rotation code needs to create another symlink ("chrome.previous" for instance) pointing to the second to latest log.

Then the feedback tool (src/platform2/feedback) needs to add chrome.previous to the list of files that it sends to chrome, which reads them and passes their content back to the feedback tool.  (This dance is needed because the feedback tool runs in a minijail that doesn't allow access to /home/chronos/user/log).

The only problem is that we'll increase the size of the report, potentially by a lot.  Ideally we'd do this only when the most recent log is short.

Or perhaps when the current log was created within the past couple of
minutes?

Yes, maybe a little longer in case the user waited before filing feedback?  I don't know what the distribution of those delays would be, we'll have to guess it.  My guess is that 95% or more of the reports are within 15 minutes of the problem.

Ah, but what if they suspend and send the feedback later, after resuming?

This will take some thought...

Redirecting to achuith, who seems to have touched the logging symlink related code most recently on ChromeOS. Care to chime in here?

Another possibility would be NOT to preferentially rotate the log right after the browser crash/restart, but wait some time (or some amount of logging).

I am working on this.

In my proposed approach, the first step is to have two symlinks: log/chrome and log/chrome.PREVIOUS, with the obvious creation, deletion, and renaming logic.

The next step is to have the feedback log collector collect both, possibly only when log/chrome is below a certain size.

Is this referring to Chrome system logs (/var/log/chrome), Chrome user logs (/home/chronos/user/log), or both? Mind going with .LATEST and .PREVIOUS symlinks to match the naming convention used elsewhere (which I think was borrowed from google3)?

Sure, chrome.LATEST and chrome.PREVIOUS is fine.  It may break a few things since now we're only using "chrome".

Something seems wrong with the logging code.  Of course it's a pain to debug logging when one uses logging to debug.  I hacked syslog logging to see what's happening (that's in addition to my own code to maintain the .PREVIOUS file), see code below.

I am wondering if the DPLOG(WARNING) are useful when new_log == true.  Are those going anywhere?  I doubt it.  But in any case here's what I see:

2017-08-01T11:16:58.605812-07:00 ERR luigo[14259]: symlink: /home/chronos/user/log/chrome, new_log: true
2017-08-01T11:16:58.644454-07:00 ERR luigo[14259]: in conditional
2017-08-01T11:16:58.644511-07:00 ERR luigo[14259]: unlink failed
2017-08-01T11:16:58.644538-07:00 ERR luigo[14259]: rename failed
2017-08-01T11:16:58.644553-07:00 ERR luigo[14259]: symlink failed

(correlate with code below)

so I am wondering how those failures happen, I can see the first two fail easily, but the symlink call should not fail.  I am wondering whether there can be a race with the mounting of the user file system.


#if defined(OS_CHROMEOS)
base::FilePath SetUpSymlinkIfNeeded(const base::FilePath& symlink_path,
                                    bool new_log) {
  DCHECK(!symlink_path.empty());

  lllog("symlink: %s, new_log: %s", symlink_path.value().c_str(),
        new_log? "true" : "false");

  // If not starting a new log, then just log through the existing
  // symlink, but if the symlink doesn't exist, create it.
  //
  // If starting a new log, then save the old symlink as symlink_path.PREVIOUS
  // and make a new one to a fresh log file.
  base::FilePath target_path;
  bool symlink_exists = base::PathExists(symlink_path);
  if (new_log || !symlink_exists) {
    lllog("in conditional");
    target_path = GenerateTimestampedName(symlink_path, base::Time::Now());

    if (symlink_exists) {
      base::FilePath previous_symlink_path =
        symlink_path.AppendASCII(".PREVIOUS");
      // Remove existing .PREVIOUS symlink if it exists.
      if (::unlink(previous_symlink_path.value().c_str()) == -1) {
        lllog("unlink failed");
        DPLOG(WARNING) << "Unable to unlink " << symlink_path.value();
      }
      // Rename symlink to .PREVIOUS.
      if (!base::ReplaceFile(symlink_path, previous_symlink_path, NULL)) {
        lllog("rename failed");
        DPLOG(WARNING) << "Cannot rename " << symlink_path.value()
                       << " to " << previous_symlink_path.value();
      }
    }
    // If all went well, the symlink no longer exists.  Recreate it.
    if (!base::CreateSymbolicLink(target_path, symlink_path)) {
      lllog("symlink failed");
      DPLOG(ERROR) << "Unable to create symlink " << symlink_path.value()
                   << " pointing at " << target_path.value();
    }
  } else {
    if (!base::ReadSymbolicLink(symlink_path, &target_path)) {
      lllog("cannot read symlink");
      DPLOG(ERROR) << "Unable to read symlink " << symlink_path.value();
    }
  }
  return target_path;
}

For future reference, here's the lllog() hack.

extern "C" {
#include <stdarg.h>
       void openlog(const char *ident, int option, int facility);
       void vsyslog(int priority, const char *format, ...);

void lllog(const char *format, ...) {
  static bool opened = false;
  va_list ap;
  va_start(ap, format);
  if (!opened) {
    openlog("luigo", 0, 1<<3);
    opened = true;
  }
  vsyslog(3, format, ap);
  va_end(ap);
}
}

to use it, one needs

 extern "C" {
   extern void lllog(const char *format, ...);
 }

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

commit 5238430af2b1ef611a830c789ffc190ef0658969
Author: Luigi Semenzato <semenzato@chromium.org>
Date: Thu Aug 10 20:22:59 2017

chromeos: logging: maintain chrome.LATEST and chrome.PREVIOUS links

In many situations the chrome log is restarted after a crash, and
the previous log (with the information that matters) is not included
in feedback reports.  This changes logging for Chrome OS only (which
already has a bunch of specialized code) to maintain two symlinks
to the two most recent logs.

BUG= chromium:731158 
TEST=tested on chromebook, with changes to debugd and chromeos-login

Change-Id: Ia7d037fcbf04c392f6fdc00394c6f73bf92685d9
Reviewed-on: https://chromium-review.googlesource.com/599026
Commit-Queue: Luigi Semenzato <semenzato@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>
Reviewed-by: Lei Zhang <thestig@chromium.org>
Cr-Commit-Position: refs/heads/master@{#493506}
[modify] https://crrev.com/5238430af2b1ef611a830c789ffc190ef0658969/chrome/common/logging_chrome.cc
[modify] https://crrev.com/5238430af2b1ef611a830c789ffc190ef0658969/chrome/common/logging_chrome.h

This should be fixed.