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

[Colin Watson]

** Description changed:

  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:
+ having its output written to the log *before* 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
+   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.

-- 
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 *before* 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