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

Bug #1201865 reported by Colin Ian King on 2013-07-16
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
upstart
Undecided
James Hunt
upstart (Ubuntu)
High
Unassigned

Bug Description

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

Related branches

tags: added: mobile-power-consumption
Steve Langasek (vorlon) wrote :

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?

affects: upstart → ubuntu-touch-session (Ubuntu)
Changed in ubuntu-touch-session (Ubuntu):
status: New → Incomplete
Steve Langasek (vorlon) wrote :

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

Changed in ubuntu-touch-session (Ubuntu):
status: Incomplete → Triaged
Steve Langasek (vorlon) wrote :

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.

affects: ubuntu-touch-session (Ubuntu) → upstart (Ubuntu)
Changed in upstart (Ubuntu):
importance: Undecided → High
James Hunt (jamesodhunt) wrote :

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.

James Hunt (jamesodhunt) on 2013-07-19
Changed in upstart:
assignee: nobody → James Hunt (jamesodhunt)
status: New → Fix Committed
Changed in upstart:
status: Fix Committed → Fix Released
Changed in upstart (Ubuntu):
status: Triaged → In Progress
Changed in upstart (Ubuntu):
status: In Progress → Fix Released
status: Fix Released → Fix Committed
Launchpad Janitor (janitor) wrote :

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

Changed in upstart (Ubuntu):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers