upstart on nexus4 is frequently writing :sys:power_supply-device-changed event messages

[Colin Ian King]

Running fatrace on today's ubuntu touch images on the nexus4 I'm seeing very frequent upstart messages in /var/log/upstart/ubuntu-touch-session-phablet.log

To reproduce:

sudo apt-get install fatrace
cd /
fatrace -c
init(1): W /var/log/upstart/ubuntu-touch-session-phablet.log
init(1): W /var/log/upstart/ubuntu-touch-session-phablet.log
init(1): W /var/log/upstart/ubuntu-touch-session-phablet.log
init(1): W /var/log/upstart/ubuntu-touch-session-phablet.log

..every second or so an new message is written on an idle phone.

And tail -f /var/log/upstart/ubuntu-touch-session-phablet.log shows:

event_finished: Finished :sys:cpu-device-offline event
event_new: Pending :sys:power_supply-device-changed event
Handling :sys:power_supply-device-changed event
event_finished: Finished :sys:power_supply-device-changed event
event_new: Pending :sys:cpu-device-online event
Handling :sys:cpu-device-online event
event_finished: Finished :sys:cpu-device-online event
event_new: Pending :sys:cpu-device-offline event
Handling :sys:cpu-device-offline event
event_finished: Finished :sys:cpu-device-offline event
event_new: Pending :sys:cpu-device-online event
Handling :sys:cpu-device-online event
event_finished: Finished :sys:cpu-device-online event
event_new: Pending :sys:power_supply-device-changed event
Handling :sys:power_supply-device-changed event
event_finished: Finished :sys:power_supply-device-changed event
event_new: Pending :sys:cpu-device-offline event
Handling :sys:cpu-device-offline event
event_finished: Finished :sys:cpu-device-offline event
event_new: Pending :sys:cpu-device-online event
Handling :sys:cpu-device-online event

[Steve Langasek (vorlon)]

This doesn't look like an upstart bug. upstart is reasonably echoing kernel events as upstart events; the fact that a job is then echoing all this activity on stderr, causing lots of log writes, is a bug in that job, not in upstart. However, I don't know what would be creating /var/log/upstart/ubuntu-touch-session-phablet.log on your system - the only related job I see in a current N4 image is /etc/init/ubuntu-touch-session.conf, which logs to /var/log/upstart/ubuntu-touch-session.log, and isn't logging much there. Where is this -phablet job coming from?

[Steve Langasek (vorlon)]

ah, I had an out of date version of the ubuntu-touch-session package installed. I can reproduce this issue perfectly now.

[Steve Langasek (vorlon)]

Furthemore, these log entries seem to be courtesy of the session init itself (so, the output of upstart) and running init with -q does not suppress the messages. So yeah, this is an upstart bug after all.

[James Hunt (jamesodhunt)]

This is rather an interesting one: we first added support for running upstart as a non-priv user, we forced it to run in debug mode (since debugging was the main reason for running init as a non-priv user). As such, when you run "init --user", you are automatically in debug mode ('initctl log-priority' confirms this).

This problem has not been seen on the desktop because there, the login script redirect stdout to null and only redirect stderr to $HOME/.xsession-errors... but Upstart, when run as a non-priv user, outputs its debug to stdout.

There are 2 work-arounds for this problem:

1) Create a job that specifies:

    start on startup
    exec initctl log-priority message

2) Use shell redirection to change the exec line in /etc/init/ubuntu-touch-session.conf to discard stdout.

    This sounds a little extreme, but higher priority messages from Upstart go to stderr and hence *will* still get logged to /var/log/upstart/ubuntu-touch-session.log as expected.

[Launchpad Janitor (janitor)]

This bug was fixed in the package upstart - 1.10-0ubuntu1

---------------
upstart (1.10-0ubuntu1) saucy; urgency=low

  * New upstream release (LP: #1199778, #1200264, #1201865).
  * debian/user-conf/{re-exec,upstart-file-bridge}.conf: Removed as now
    supplied by upstream.
  * debian/upstart.install: Use all upstream-provided session config files.
  * debian/control: Add upstart-dconf-bridge package.
  * debian/rules: Remove files from upstart package that now live in the
    upstart-dconf-bridge package.
  * debian/upstart-dconf-bridge.install: New.
  * debian/upstart-dconf-bridge.manpages: New.
 -- James Hunt <email address hidden> Tue, 27 Aug 2013 09:08:28 +0100