[Bug 1324627] [NEW] startpar-bridge cycles when logging upstart events (trusty)

[Robert Chekaluk]

Public bug reported:

Trusty 14.04. When installing a custom init script to log upstart events
(see http://upstart.ubuntu.com/cookbook/#record-all-jobs-and-events-
which-emit-an-event), PID 1 init consumes significant CPU and events are
logged by the custom script in a repeating stream, like this:

upstart_events/ (/proc/self/fd/9):14382:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--started stopping.
upstart_events/ (/proc/self/fd/9):14386:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--stopped stopping.
upstart_events/ (/proc/self/fd/9):14390:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--started stopping.
upstart_events/ (/proc/self/fd/9):14394:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--stopped stopping.

It's possible that these reports are also reflect a variant of this issue:
* http://askubuntu.com/questions/367079/strange-boot-log-multiple-startpar-bridge-starting-and-stopping-repeatedly
* http://askubuntu.com/questions/419431/ubuntu-13-10-not-booting-startpar-bridge
* https://bugs.launchpad.net/ubuntu/+source/lightdm/+bug/1244989/comments/3

To reproduce on Vagrant:
1. vagrant box add trusty64 https://cloud-images.ubuntu.com/vagrant/trusty/current/trusty-server-cloudimg-amd64-vagrant-disk1.box
2. vagrant init trusty64
3. vagrant up
4. vagrant ssh
5. Copy this script into /etc/init/upstart_events.conf:
description "Log upstart events"

start on ( starting JOB!=upstart_events \
        or started JOB!=upstart_events \
        or stopping JOB!=upstart_events \
        or stopped JOB!=upstart_events )
script
  exec 1>>/tmp/upstart_events.log
  echo -n "$UPSTART_JOB/$UPSTART_INSTANCE ($0):$$:`date`:"
  echo "Job $JOB/$INSTANCE $UPSTART_EVENTS."
end script
6. sudo reboot
7. vagrant ssh
8. tail -f /tmp/upstart_events.log

** Affects: sysvinit (Ubuntu)
     Importance: Undecided
         Status: New

** Description changed:

  Trusty 14.04. When installing a custom init script to log upstart events
  (see http://upstart.ubuntu.com/cookbook/#record-all-jobs-and-events-
  which-emit-an-event), PID 1 init consumes significant CPU and events are
  logged by the custom script in a repeating stream, like this:
  
  upstart_events/ (/proc/self/fd/9):14382:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--started stopping.
  upstart_events/ (/proc/self/fd/9):14386:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--stopped stopping.
  upstart_events/ (/proc/self/fd/9):14390:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--started stopping.
  upstart_events/ (/proc/self/fd/9):14394:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--stopped stopping.
  
  It's possible that these reports are also reflect a variant of this issue:
  * http://askubuntu.com/questions/367079/strange-boot-log-multiple-startpar-bridge-starting-and-stopping-repeatedly
  * http://askubuntu.com/questions/419431/ubuntu-13-10-not-booting-startpar-bridge
  * https://bugs.launchpad.net/ubuntu/+source/lightdm/+bug/1244989/comments/3
  
  To reproduce on Vagrant:
  1. vagrant box add trusty64 https://cloud-images.ubuntu.com/vagrant/trusty/current/trusty-server-cloudimg-amd64-vagrant-disk1.box
  2. vagrant init trusty64
  3. vagrant up
  4. vagrant ssh
  5. Copy this script into /etc/init/upstart_events.conf:
  description "Log upstart events"
  
  start on ( starting JOB!=upstart_events \
-         or started JOB!=upstart_events \
-         or stopping JOB!=upstart_events \
-         or stopped JOB!=upstart_events )
+         or started JOB!=upstart_events \
+         or stopping JOB!=upstart_events \
+         or stopped JOB!=upstart_events )
  script
-   exec 1>>/tmp/upstart_events.log
-   echo -n "$UPSTART_JOB/$UPSTART_INSTANCE ($0):$$:`date`:"
-   echo "Job $JOB/$INSTANCE $UPSTART_EVENTS."
+   exec 1>>/tmp/upstart_events.log
+   echo -n "$UPSTART_JOB/$UPSTART_INSTANCE ($0):$$:`date`:"
+   echo "Job $JOB/$INSTANCE $UPSTART_EVENTS."
  end script
  6. sudo reboot
  7. vagrant ssh
- 8. tail -v /tmp/upstart_events.log
+ 8. tail -f /tmp/upstart_events.log

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to sysvinit in Ubuntu.
https://bugs.launchpad.net/bugs/1324627

Title:
  startpar-bridge cycles when logging upstart events (trusty)

Status in “sysvinit” package in Ubuntu:
  New

Bug description:
  Trusty 14.04. When installing a custom init script to log upstart
  events (see http://upstart.ubuntu.com/cookbook/#record-all-jobs-and-
  events-which-emit-an-event), PID 1 init consumes significant CPU and
  events are logged by the custom script in a repeating stream, like
  this:

  upstart_events/ (/proc/self/fd/9):14382:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--started stopping.
  upstart_events/ (/proc/self/fd/9):14386:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--stopped stopping.
  upstart_events/ (/proc/self/fd/9):14390:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--started stopping.
  upstart_events/ (/proc/self/fd/9):14394:Thu May 29 17:06:03 UTC 2014:Job startpar-bridge/upstart_events--stopped stopping.

  It's possible that these reports are also reflect a variant of this issue:
  * http://askubuntu.com/questions/367079/strange-boot-log-multiple-startpar-bridge-starting-and-stopping-repeatedly
  * http://askubuntu.com/questions/419431/ubuntu-13-10-not-booting-startpar-bridge
  * https://bugs.launchpad.net/ubuntu/+source/lightdm/+bug/1244989/comments/3

  To reproduce on Vagrant:
  1. vagrant box add trusty64 https://cloud-images.ubuntu.com/vagrant/trusty/current/trusty-server-cloudimg-amd64-vagrant-disk1.box
  2. vagrant init trusty64
  3. vagrant up
  4. vagrant ssh
  5. Copy this script into /etc/init/upstart_events.conf:
  description "Log upstart events"

  start on ( starting JOB!=upstart_events \
          or started JOB!=upstart_events \
          or stopping JOB!=upstart_events \
          or stopped JOB!=upstart_events )
  script
    exec 1>>/tmp/upstart_events.log
    echo -n "$UPSTART_JOB/$UPSTART_INSTANCE ($0):$$:`date`:"
    echo "Job $JOB/$INSTANCE $UPSTART_EVENTS."
  end script
  6. sudo reboot
  7. vagrant ssh
  8. tail -f /tmp/upstart_events.log

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/sysvinit/+bug/1324627/+subscriptions