[Bug 942898] [NEW] out-of-order log output possible with a respawning job during early boot

[Steve Langasek]

Public bug reported:

If a job exits before the filesystem is mounted, the job's output isn't
written immediately, but instead queued in memory by upstart until the
fs becomes writable.

This sequence of events can result in the second instance of a job
having its output written to the log *after* the first instance:

  job starts on boot and generates output
  job exits
  /var mounted rw
  job starts again and generates output
  filesystem event is emitted
  'initctl flush-early-job-log' is called

Since /var is writable by the time the second job instance starts, its
output is written immediately.  Then upstart learns that the whole
filesystem has become writable, and it writes out all the queued data.

In email, James wrote:

> To protect against the scenario above, we'd need to store a
> reference to the job instance (name) in the log itself, and add a
> counter to all entries in the log_unflushed_list such that when the
> job starts again, we first look for any entries in
> log_unflushed_list that match the job instance, flush those first,
> then proceed with flushing any new data.

Sounds sensible to me.

** Affects: upstart (Ubuntu)
     Importance: Medium
         Status: Triaged

** Changed in: upstart (Ubuntu)
       Status: New => Triaged

** Changed in: upstart (Ubuntu)
   Importance: Undecided => Medium

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

Title:
  out-of-order log output possible with a respawning job during early
  boot

Status in “upstart” package in Ubuntu:
  Triaged

Bug description:
  If a job exits before the filesystem is mounted, the job's output
  isn't written immediately, but instead queued in memory by upstart
  until the fs becomes writable.

  This sequence of events can result in the second instance of a job
  having its output written to the log *after* the first instance:

    job starts on boot and generates output
    job exits
    /var mounted rw
    job starts again and generates output
    filesystem event is emitted
    'initctl flush-early-job-log' is called

  Since /var is writable by the time the second job instance starts, its
  output is written immediately.  Then upstart learns that the whole
  filesystem has become writable, and it writes out all the queued data.

  In email, James wrote:

  > To protect against the scenario above, we'd need to store a
  > reference to the job instance (name) in the log itself, and add a
  > counter to all entries in the log_unflushed_list such that when the
  > job starts again, we first look for any entries in
  > log_unflushed_list that match the job instance, flush those first,
  > then proceed with flushing any new data.

  Sounds sensible to me.

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