New issue
Advanced search Search tips

Issue 904850 link

Starred by 1 user

Issue metadata

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

Blocking:
issue 887123



Sign in to add a comment

session manager should not redirect stderr/stdout to /var/log/ui after user login

Project Member Reported by tnagel@chromium.org, Nov 13

Issue description

Chrome Version: 71
OS: Chrome

What steps will reproduce the problem?
(1) Visit https://expired.badssl.com/
(2) grep badssl /var/log/ui/ui.LATEST

What is the expected result?
(empty)

What happens instead?
cert_verify_proc_nss.cc(974) CERT_PKIXVerifyCert for expired.badssl.com failed
 
Labels: Needs-Bisect
Owner: tnagel@chromium.org
Status: Assigned (was: Untriaged)
Labels: FoundIn-70
Summary: Log stream doesn't switch to cryptohome (was: PII in system logs)
It seems that the log stream doesn't switch over to cryptohome as described in [1]. logging::RedirectChromeLogging() should do that job. 

[1] https://cs.chromium.org/chromium/src/docs/chrome_os_logging.md
/var/log/ui contains stderr and stdout from Chrome. It's typically used to capture messages that Chrome writes before logging has been initialized (e.g. early crashes, linker errors, etc.).

Per IM discussion with Thiemo, it looks like Chrome is switching to the log file from /var/log/chrome to /home/chronos/user/log as expected, but also duplicating ERROR (and also WARNING?) messages to /var/log/ui.
Summary: Chrome logs errors to /var/log/ui after logging has been initialized (was: Log stream doesn't switch to cryptohome)
Cc: ejcaruso@chromium.org derat@chromium.org mnissler@chromium.org
Components: Internals>Logging
When I dump settings from BaseInitLoggingImpl calls, it looks like logging_dest is just set to 1, i.e. LOG_TO_FILE (as expected).

But, uh, this looks like it's intentional and has been there since 2008. In base/logging.cc:

// For LOG_ERROR and above, always print to stderr.
const int kAlwaysPrintErrorLevel = LOG_ERROR;

...

LogMessage::~LogMessage() {
...
  } else if (severity_ >= kAlwaysPrintErrorLevel) {
    // When we're only outputting to a log file, above a certain log level, we
    // should still output to stderr so that we can better detect and diagnose
    // problems with unit tests, especially on the buildbots.
    ignore_result(fwrite(str_newline.data(), str_newline.size(), 1, stderr));
    fflush(stderr);
  }

Did we have something that suppressed this behavior on Chrome OS before?

As a quick workaround, should /var/log/ui be 0700?
Summary: session manager should not redirect stderr/stdout to /var/log/ui after user login (was: Chrome logs errors to /var/log/ui after logging has been initialized)
I'm even getting libudev messages in /var/log/ui, such as "device-enumerator: scan all dirs". I think it's untenable to direct stdout/stderr to /var/log/ui after a user has logged in because it's infeasible to audit all of Chrome's dependencies for console output. Rewriting the title of the bug (again).

Mattias, Dan, as owners of session manager, do you agree with the above?
Components: -Internals>Logging OS>Systems
Cc: jorgelo@chromium.org kerrnel@chromium.org
This seems like more of a Chrome question than a session_manager question.

We could maybe accomplish this for the browser process by making RedirectChromeLogging() in chrome/browser/chromeos/logging.cc use dup2() to send stdout and stderr to /dev/null, but I'm not sure what we'd do about all the other Chrome processes that have already forked.
Labels: -Needs-Bisect
I can think of two options:

1. Prevent Chrome from inheriting the fds of session manager in ForkAndExec(). -- Until a user logs in we'll still get Chrome logging in /var/log/chrome so I'd guess we won't be missing a lot compared to status quo (just very early messages that happen before logging initialization).

2. Upon user login, create a copy of ui.LATEST and then delete it so that any further writes go into the void. I.e. assuming /var/log/ui/ui.LATEST points to /var/log/ui/ui.yyyymmdd-hhmmss:
  cd /var/log/ui
  mv ui.yyyymmdd-hhmmss ui.disconnected
  cp ui.disconnected ui.yyyymmdd-hhmmss
  rm ui.disconnected
The first option makes it impossible to debug certain types of bugs, so let's not do that. The whole point of /var/log/ui is to catch early messages from Chrome.

The second option seems okay to me. Mattias?
Labels: Hotlist-Privacy
Owner: ----
Status: Available (was: Assigned)
In offline conversation with Mattias he agreed with the general plan of cutting off the stdout/stderr log streams once the session starts.

I guess the general direction is clear now, anyone feel free to take this.
Owner: derat@chromium.org
Status: Started (was: Available)
Blocking: 887123
Project Member

Comment 15 by bugdroid1@chromium.org, Nov 30

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/ff6532b9bafea6c0b643a545303ef3b7e9352e1a

commit ff6532b9bafea6c0b643a545303ef3b7e9352e1a
Author: Daniel Erat <derat@chromium.org>
Date: Fri Nov 30 00:09:08 2018

login: Disconnect Chrome's stdout/stderr after login.

Make session_manager replace the active log file in
/var/log/ui with a copy of itself after the initial user
session starts. This ensures that any user-specific messages
that Chrome logs to stderr or stdout won't end up on disk.

BUG= chromium:904850 
TEST=added unit tests; also logged in and checked that
     /proc/<pid>/fd reports that the root chrome process's
     stderr and stdout are disconnected and that
     /var/log/ui/ui.LATEST doesn't contain an SSL error
     after navigating to https://expired.badssl.com/

Change-Id: I70c74074f3d7e3a6a6de4287c0808e8b0edf1eb8
Reviewed-on: https://chromium-review.googlesource.com/1350051
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Mattias Nissler <mnissler@chromium.org>
Reviewed-by: Thiemo Nagel <tnagel@chromium.org>

[modify] https://crrev.com/ff6532b9bafea6c0b643a545303ef3b7e9352e1a/login_manager/session_manager_impl.cc
[modify] https://crrev.com/ff6532b9bafea6c0b643a545303ef3b7e9352e1a/login_manager/session_manager_impl_test.cc
[modify] https://crrev.com/ff6532b9bafea6c0b643a545303ef3b7e9352e1a/login_manager/session_manager_impl.h

Status: Fixed (was: Started)
This change broke a an autotest that was expecting to find Chrome logs in /var/log/ui/ [https://b.corp.google.com/issues/72205615#comment6]. Before fixing the test, I was hoping to clear some things up about the intentions behind this change.

With this change the stdout/stderr of chrome is still available through /proc/<pid>/fd/{1,2} where <pid> is session_manager's or Chrome's pid. I believe session_manager and chrome are always killed between user sessions, so it normally wouldn't be accessible between user sessions. I'd be worried about some errant process that's session_manager descendant  hanging around between logins, as session_manager and upstart don't do a good job at ensuring all their descendants are dead. Putting that concern aside, the contents will still be available on a disk that isn't encrypted with a user specific key, even after the last process referencing the file terminates, since we don't do any file shredding as far as I'm aware.

The autotest I mentioned above used the "--enable-logging=stderr" flag. I feel this flag no longer makes sense, because it now only affects messages before login. The trick we do here is surprising in a few other ways, since it's not obvious why when chrome is writing to a file at a path that exists, the log messages aren't showing up in said file. We had to look at the inodes of the files in order to figure out that they're different.

I had some questions about the concern with child processes of Chrome. Do they not run the "RedirectChromeLogging" function too? If not, and if they do log PII messages, how do they log to a different place after login? I ask because I feel a solution more similar to what derat@ suggested in comment #9 would solve the concerns I raised here.
Thiemo can probably comment more about the privacy implications, but I don't think that /proc/<pid>/fd/{1,2} is a concern, since we (IIRC) kill all processes that are running as chronos or that have open files under /home at the end of the session. (If there are indeed cases where we're not killing all session_manager-spawned processes, I bet the security team wants to hear about them!)

Sign in to add a comment