on the topic, does power_manager need to do its own manual log file management ?  is there a reason it can't use syslog for everything ?

I don't know the background here, but the format that our syslog logs use seems pretty hard-to-read to me:

2016-09-23T12:37:33.471187-06:00 INFO session_manager[2158]: [INFO:system_utils_impl.cc(86)] Sending 15 to 2212 as 1000

vs.

[1024/093234:INFO:ec_wakeup_helper.cc(72)] EC wake angle set to 180

powerd's logging is pretty verbose (which makes me happy whenever I'm investigating a bug report about a system doing something unexpected), and it's handy that a new log is created every time the process starts.

Can we get all of the current things (terse headers, new file every time the process starts, google3-style powerd.LATEST/powerd.PREVIOUS symlinks) using rsyslogd? http://www.rsyslog.com/doc/v8-stable/configuration/templates.html makes me think we could have terse headers, at least.

while the format might not be the same, i think we should err on the side of "make it look like everything else".  personally i find the syslog timestamp to be more readable w/out any context at all, and provides more details (like nanosecond resolution).  the power manager timestamp i need to go look up in the source code to figure out what it means.

it also makes it easier to compare issues across files when everything is "the same".

does it really need to rotate every time i starts up ?  we don't do that with other daemons and it doesn't seem like an issue.  if powerd needs to be clear, it could just log "startup" or some other marker you'd find handy.

when it comes to naming, the convention is that "powerd" would always be the latest, and "powerd.1" would always be the previous.  but those would be rotated along size/time lines rather than process startup lines.  since those names are stable, do you need the explicit .LATEST and .PREVIOUS ?

Re format, I guess it depends on where you're coming from. I'm used to looking at Chromium logs, so powerd's logs look nice and familiar to me. :-P

Re rotation, well, it's pretty convenient for feedback and crash reports, the two main sources of logs that I look at besides the ones from my dev machines.

In debugd, we cat powerd.LATEST, powerd.PREVIOUS, and powerd.out as separate attachments. It might be possible to ship an extra binary or script that tries to extract similar information from syslog's logs if we switch to it.

In crash-reporter, we run this for powerd crashes:

# Dump the last 50 lines of the last two powerd log files -- if the job has
# already restarted, we want to see the end of the previous instance's logs.
powerd=\
  for f in $(ls -1tr /var/log/power_manager/powerd.[0-9]* | tail -2); do \
    echo "===$(basename $f) (tail)==="; \
    tail -50 $f; \
    echo EOF; \
  done

I'm not sure if there's an easy way to do something similar if things are spread across multiple (possibly large) logs by e.g. "grep -B"-ing for a marker. Maybe we could cat all the logs into one big file first, but I'm worried about that getting slow.

The main use case that I care about is being able to figure out what happened during the previous boot when I get a report that the system spontaneously shut down/rebooted/etc.

the system format should be consistent.  we shouldn't be allowing daemons to pick an arbitrary format or log location and doing it all themselves.

the current log rotation logic runs once a day.  so if we cat "powerd" and "powerd.1", it seems like we should still contain all the info you need ?

So, this is now pretty far afield from what I initially filed it for. Mike's fault for derailing and then mine for not creating a new bug, I guess. :-P There's no way to split existing comments into a new bug, so I'll repurpose this one.

I'm not particularly opposed to having powerd use syslog for everything (by calling "brillo::InitLog(brillo::kLogToSyslog | brillo::kLogHeader)" like session_manager does, maybe), but I want to make changes to the way it currently logs first, mostly to cut down the frequency of messages about Chrome's reports of user and video activity.

Re #4, for debugd, I think I'm okay with just including powerd.log and powerd.log.1 or whatever. For crash-reporter, we can probably get the important bits from before the process died by both doing "grep -B 50 <process-start-marker>" and "tail -50". We'll get the last log messages from earlier runs as well then, but that's probably avoidable by feeding all of that into "tail -100" or something similar.

I still want the thing that I originally asked for here, for powerd to put a line in /var/log/messages saying why/when we're shutting down. That's independent of switching powerd to use syslog for its regular logging, so I'll do it in parallel.

There are also a few autotests that grep through powerd's logs. Those have always been gross; I'll see if I can change them to do something more reasonable.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/3a60c30894f2add313cbc8e93d1503f4749fc3d4

commit 3a60c30894f2add313cbc8e93d1503f4749fc3d4
Author: Daniel Erat <derat@chromium.org>
Date: Fri Nov 18 22:32:03 2016

autotest: Make power_AudioDetector not use powerd's logs.

Make powerd_AudioDetector use dbus-monitor to check whether
the system suspended rather than searching for a hardcoded
message in powerd's log file.

BUG=chromium:658769
TEST=test passes normally. after hacking it up to not
     actually play audio, it failed with "System suspended
     while audio was playing."

Change-Id: I3222f9513657c73014272402b203a347c73797f4
Reviewed-on: https://chromium-review.googlesource.com/412929
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Cheng-Yi Chiang <cychiang@chromium.org>
Reviewed-by: Chinyue Chen <chinyue@chromium.org>

[modify] https://crrev.com/3a60c30894f2add313cbc8e93d1503f4749fc3d4/client/site_tests/power_AudioDetector/power_AudioDetector.py

Android bug tool currently has parser for powerd logs (powerd_parser.ts) +Ravi as well for visibility.

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

commit f0f0b606d56359330037c6d5325103e5ea612c77
Author: Daniel Erat <derat@chromium.org>
Date: Fri Nov 18 20:36:59 2016

power: Add low-battery-shutdown flags to check_powerd_config

Add --low_battery_shutdown_percent and
--low_battery_shutdown_time flags to the check_powerd_config
utility so that load tests can get powerd's threshold from
it rather than by grepping through powerd's logs.

BUG=chromium:658769
TEST=ran it with either or both prefs set

Change-Id: I72d8ae396b39bd23167b805a49881999164a517b
Reviewed-on: https://chromium-review.googlesource.com/412901
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Todd Broch <tbroch@chromium.org>

[modify] https://crrev.com/f0f0b606d56359330037c6d5325103e5ea612c77/power_manager/tools/check_powerd_config.cc
[modify] https://crrev.com/f0f0b606d56359330037c6d5325103e5ea612c77/power_manager/powerd/system/power_supply.cc

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/8b4fdc2687016da15a37da7767bc97d97186f647

commit 8b4fdc2687016da15a37da7767bc97d97186f647
Author: Daniel Erat <derat@chromium.org>
Date: Tue Nov 22 16:09:47 2016

autotest: Make power_LoadTest not read powerd's logs.

Update powerd_LoadTest to get powerd's low-battery shutdown
thresholds from the check_powerd_config tool instead of by
grepping through /var/log/power_manager/powerd.LATEST.

BUG=chromium:658769
TEST=ran powerd_LoadTest.fast and verified that results
     display correct shutdown thresholds when powerd is
     configured for either time- or percent-based shutdown

Change-Id: I9f420294d9e1f63c90de8b64c3cd12d95383692c
Reviewed-on: https://chromium-review.googlesource.com/413704
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Todd Broch <tbroch@chromium.org>

[modify] https://crrev.com/8b4fdc2687016da15a37da7767bc97d97186f647/client/site_tests/power_LoadTest/power_LoadTest.py

you change broke some of our test
https://chromium-review.googlesource.com/#/c/413704/

please make the test backward compatible to older dut/OS.

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

commit bb4c047ccbcae6b95dbf7407fe117cbe3d854100
Author: Daniel Erat <derat@chromium.org>
Date: Wed Nov 09 23:21:06 2016

power: Make user/video activity logging less spammy.

Introduce PeriodicActivityLogger and
StartStopActivityLogger, classes that makes it easier to log
periodically-reported or frequently-starting/stopping
activity. Use the former to log user and video activity
(formerly logged every five seconds as it's reported by
Chrome) and the latter to replace the existing ad-hoc
hovering logging in KeyboardBacklightController and audio
logging in Daemon.

BUG=chromium:658769
TEST=manual: hovering, video, and user activity are each
     logged when they start and 20 seconds after they stop.
     audio and video activity are logged every 3 minutes
     while they're ongoing. also added tests.

Change-Id: I172935086c16829f9d6ee76b214deaa95618ca29
Reviewed-on: https://chromium-review.googlesource.com/410224
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/power_manager.gyp
[modify] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/powerd/daemon.cc
[add] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/common/activity_logger_unittest.cc
[modify] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/powerd/policy/keyboard_backlight_controller.cc
[modify] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/powerd/policy/keyboard_backlight_controller.h
[add] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/common/activity_logger.cc
[add] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/common/activity_logger.h
[modify] https://crrev.com/bb4c047ccbcae6b95dbf7407fe117cbe3d854100/power_manager/powerd/daemon.h

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

commit 5a64b9c6640b374309e524e3359bd557cca78ecf
Author: Daniel Erat <derat@chromium.org>
Date: Wed Jul 19 04:50:34 2017

init: Make the pre-shutdown job log shutdown.

Make the pre-shutdown Upstart job write a "Shutting down for
[job]: [reason]" message to syslog to aid in debugging. This
should typically be the last thing that's logged before the
system goes down; rsyslogd runs in boot-services and stops
immediately afterward.

BUG=chromium:658769
TEST=manual: after shutting the system down and booting it
     again, /var/log/messages contains a "Shutting down"
     message

Change-Id: I105c3e0f21ef45354b698544f4be522f6369207b
Reviewed-on: https://chromium-review.googlesource.com/562541
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Richard Barnette <jrbarnette@chromium.org>
Reviewed-by: Jorge Lucangeli Obes <jorgelo@chromium.org>

[modify] https://crrev.com/5a64b9c6640b374309e524e3359bd557cca78ecf/init/upstart/halt/halt.conf
[modify] https://crrev.com/5a64b9c6640b374309e524e3359bd557cca78ecf/init/upstart/pre-shutdown.conf
[modify] https://crrev.com/5a64b9c6640b374309e524e3359bd557cca78ecf/init/upstart/reboot.conf
[modify] https://crrev.com/5a64b9c6640b374309e524e3359bd557cca78ecf/init/upstart/halt/s3halt.conf

allowing symlinks in /var/log is allowing people to abuse and exploit the system (see issue 916152).  we're not going to allow any program have an exception to symlinks under /var.  so powerd needs to migrate away from its custom logging logic and to syslog like every other program in the system.

I'm not able to view 916152, 'permission denied'.  Tried both chromium & corp accts.

the exact details don't really matter here.  the end result is "symlinks are going away under /var w/no exception".

I don't think that powerd needs to switch to syslog in order for the symlinks to go away. Just make powerd stop creating the symlinks and update anything that depends on them: debugd, crash_reporter, various Autotest tests, ...