second call of 'initctl start' leads to fork instead of exec ('mount: / is busy' during shutdown)

[Max]

The real case for this issue is the Bug lp: #1181528 (ureadahead)
"/etc/init.d/umountroot: 'mount / is busy' due to upstart log file"
and a variant of Bug lp: #1073433
"Ext4 corruption associated with shutdown of Ubuntu 12.10"
Upstart holds a file open for writing so /etc/init.d/umountroot
can not cleanly remount root filesystem readonly.

Assume the following job description that is simulation of
ureadahead-other.conf when there is no .pack file for a mount
<file name="lazy-daemon.conf">
description "Debug open log file issue"
manual
expect fork
normal exit 0 4
exec /bin/sh -c 'echo "I am tired" >&2 ; exit 4 '
</file>

Let's start it

start lazy-daemon
[ 8433.561627] init: Connection from private client
[ 8433.563649] init: lazy-daemon goal changed from stop to start
[ 8433.563854] init: lazy-daemon state changed from waiting to starting
[ 8433.564474] init: Handling starting event
[ 8433.564797] init: lazy-daemon state changed from starting to pre-start
[ 8433.565106] init: lazy-daemon state changed from pre-start to spawned
[ 8433.567494] init: lazy-daemon main process (3673)
[ 8433.569516] init: lazy-daemon main process (3673) executable changed
[ 8433.570797] init: lazy-daemon main process (3673) terminated with status 4
[ 8433.571183] init: lazy-daemon goal changed from start to stop
[ 8433.571597] init: lazy-daemon state changed from spawned to stopping
[ 8433.571981] init: Handling stopping event
[ 8433.572459] init: lazy-daemon state changed from stopping to killed
[ 8433.572817] init: lazy-daemon state changed from killed to post-stop
[ 8433.573164] init: lazy-daemon state changed from post-stop to waiting
[ 8433.574376] init: Handling stopped event
lazy-daemon stop/waiting

In general everything works as expected (However I am in doubt
concerning 'executable changed'

Let's start again (One more mount and call of ureadahead-other
for it)

start lazy-daemon
[ 8493.929425] init: Connection from private client
[ 8493.931370] init: lazy-daemon goal changed from stop to start
[ 8493.931576] init: lazy-daemon state changed from waiting to starting
[ 8493.931817] init: Handling starting event
[ 8493.932444] init: lazy-daemon state changed from starting to pre-start
[ 8493.932750] init: lazy-daemon state changed from pre-start to spawned
[ 8493.935620] init: lazy-daemon main process (3681)
[ 8493.937540] init: lazy-daemon main process (3681) became new process (3682)
[ 8493.937620] init: lazy-daemon state changed from spawned to post-start
[ 8493.937860] init: lazy-daemon state changed from post-start to running
[ 8493.938093] init: Handling started event
lazy-daemon start/running, process 3682

I do not expect fake fork here. There is no 3682 process.
In any case upstart has to close the log file

ps uw 3682
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
initctl status lazy-daemon
lazy-daemon start/running, process 3682
lsof | grep lazy-daemon
init 1 root 13w REG 8,2 24 2888252 /var/log/upstart/lazy-daemon.log

Bug lp: #1130611 "Upstart never closes /var/log/upstart/mysql.log"
might be related to this issue

Versions:
Ubuntu 13.10 Raring i686
upstart: Installed: 1.8-0ubuntu1

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Max (m-gorodok)]

Quotes are crucial in the exec line of the .conf file.
The bug is reproducible with

expect fork
exec /bin/sh -c "exit"

But never happens for the following .conf

expect fork
exec /bin/sh -c exit

Quotes (or $ in the original ureadahead-other.conf) force
upstart to add shell wrapping. First time it leads to

lazy-daemon main process (3673) executable changed

I have no guess why during the second launch
job_process_trace_fork() is called instead of
job_process_trace_exec()

lazy-daemon main process (3681) became new process (3682)

I have not notice any variable within init (upstart) that may
control this behavior. Perhaps it is due to libnih.

[Max (m-gorodok)]

The problem is in init/job_process.c, function job_process_run().
Upstart detects SHELL_CHARS in the exec line, so first time
it launches command with shell and exec wrappings

/bin/sh -e -c exec /bin/sh -c "exit"

and set "script" flag for the job's MAIN_PROCESS.
During the second "initctl start" and job_process_run
the "script" flags is set so the following line is passed
to job_process_span and execve

/bin/sh -e -c /bin/sh -c "exit"

Because of absent "exec", shell forks, it is caught by
handler, so upstart believes that daemon has been started.

It seems that "proc->script = TRUE;" should not be set.

[Steve Dodd (anarchetic)]

The setting of proc->script was introduced here:

http://bazaar.launchpad.net/~ubuntu-branches/ubuntu/saucy/upstart/saucy/revision/1182.62.1

At the moment it doesn't seem to be tested anywhere other than in job_process_run(), so simply reverting the change should fix the problem, but presumably this was intended to be useful later, as the comment says "That way tests can reliably check for shell-specific behaviour."

[Steve Dodd (anarchetic)]

Removing the assignment of proc->script solves this problem for me. If in future we need to know how the process was started, we should store that information elsewhere, because implicit and explicit use of the shell are not exactly equivalent. Patch attached.

This and the patch in bug #1169614 give me a clean shutdown on current saucy.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "Don't set proc->script on implicit shell use" seems to be a patch. If it isn't, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are a member of the ~ubuntu-reviewers, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issues please contact him.]

[Stéphane Graber (stgraber)]

Fixed in lp:upstart and cherry-picked for the next ubuntu:upstart upload to saucy, will then cherry-pick back to raring once we're done with the current SRU.

[Dimitri John Ledkov (xnox)]

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

  [ Dmitrijs Ledkovs ]
  * Use dh_auto_build to run the testsuite, as dh_auto_test stopped
    finding autotools test suite.
  * Correct typo in upstart postinst (LP: #1195955)

  [ James Hunt ]
  * New upstream release.
  * init/tests/test_conf.c: Remove duplicate define.

  [ Stéphane Graber ]
  * Cherry-pick r1498 from upstream upstart to fix incorrect respawn handling
    for jobs that have shell characters in their expanded command line.
    (LP: 1181789)

  [ Marc Deslauriers ]
  * Added some distro-specific changes:
    - init/apparmor.c: do not load apparmor if running in a container or a
      live cd.
    - init/job_process.c: don't fail if the security profile failed to load
      to emulate current behaviour on Ubuntu.
 -- Dmitrijs Ledkovs <email address hidden> Tue, 02 Jul 2013 20:14:51 +0100

[Max (m-gorodok)]

I have built upstart_1.9.1-0ubuntu3 for Ubuntu 13.04 Raring.
I do not see the bug with ureadahead anymore.
However once I have seen busy / on shutdown
due to modem-manager and its file in /var/log/upstart
opened for writing.

There are a couple of minor issues with sources
in saucy and their backproting.

Automake 1.11 in Raring does not have the option "serial-tests"
(introduced in 1.12), so configure.ac must be edited.

Tests rely on exact test messages, so dpkg-buildpackage
must be run with LANG=C, otherwise one test fails.

Due to the issue with modem-manager I am in doubt
if upstart-1.9 should be included to updates of Raring.

[Stéphane Graber (stgraber)]

I committed the fix to the raring SRU branch so it'll be included in the next SRU.

[Steve Langasek (vorlon)]

Landing this fix in raring was blocked by bug #1199778, which we ran out of time to resolve before the 13.10 release. My work-in-progress branch is available at lp:~vorlon/ubuntu/raring/upstart/lp.1199778 in case anyone else wants to pick this up for 13.04. Otherwise, this bug is 'wontfix'.

[Nikolay Morozov (nmorozov)]

afecting this
xubuntu 14.04 trusty beta2 64bit
Dell D430 laptop
13.10 works fine

get error mount: / is busy' during shutdown or reboot
and hangs after will how halt or will now reboot
passing reboot=force acpi=force to kernel will not help me at all

[Nikolay Morozov (nmorozov)]

try boot from live flash xubuntu 14.04 trusty beta2 64bit
on AMD Phenom desktop computer
works fine, after will now halt appears message (too fast for reading) and computer powers off

[Nikolay Morozov (nmorozov)]

i have discovered that my problems doen't releate to this bug, my bug is releated to bcmwl-kernel-source package

[louis kolli (louis-kolli)]

The Nilolay's bug was related to bcmwl-kernel-source package, mine's too but we both had a stopping shutting down with the message "mount:/ is busy" on a laptop HP presario

First I removed network-manager 'cause of the message "dont get "www.networkmanager1" while sutting down. It didn't change

2 I saw that my wifi card was not detected, I removed bcmwl-kernel and installed b43-installer. After reboot i didnt get my wifi then I reinstalled bcmwl-kernel. "mount is busy" came back. I reinstalled network-manager

3 I've done what Nikolay said on the bug 1304532 and now it is Ok : no mount busy while shutting down and my wifi card is detected. I think I bad installed b43-installer

I think that this bug is related with bcmwl. It happend for me before 13.04 but before I didn't need wifi

[Joao S Veiga (jsveiga-it)]

Same here, kubuntu 14.04 64bits on a Dell Precision 390 with nVidia Quadro. No wireless cards.

Tried with nouveau nvidia driver and the 313 proprietary driver.

Had BIOS version 2.4.0, upgraded to 2.6.0 (thought I had bricked the mobo in the process, as kubuntu did not shutdown as part of the bios upgrade process, so I had to long-press the power button, then the pc wouldn't boot anymore - beep codes, fixed with a BIOS reset, then used a usb live debian wheezy rescue to do the BIOS upgrade).

When Booted with a usb pendrive with debian wheezy rescue, it powers off.

I have 3 other Precision 390 machines with debian wheezy, and they shutdown correctly.