start and stop hang when run inside a 10.04 Vserver guest

[robs]

I configured a host machine with Ubuntu Lucid 10.04 amd64, then I installed:

ii linux-headers-2.6.32-27-vserver 2.6.32-27.49~ppa3
ii linux-headers-vserver 2.6.32.27.29~ppa1
ii linux-image-2.6.32-27-vserver 2.6.32-27.49~ppa3
ii linux-image-vserver 2.6.32.27.29~ppa1
ii util-vserver 0.30.216~r2842-2ubuntu2

I followed http://linux-vserver.org/Upstart_issues to successfully build a guest system.
The guest boots and halt fine, but if the stop and start commands are executed from the console, they simply hang.

This doesn't allow apt-get upgrades to run smoothly, as post-inst scripts often call restart "servicename"

I attach the Upstart debug I get from stop dbus .. seems fine to me ? :
init: Connection from private client
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
init: dbus goal changed from start to stop
init: dbus state changed from running to pre-stop
init: dbus state changed from pre-stop to stopping
init: event_new: Pending stopping event
init: Handling stopping event
init: event_finished: Finished stopping event
init: dbus state changed from stopping to killed
init: Sending TERM signal to dbus main process (16657)
init: Disconnected from system bus
init: Sending KILL signal to dbus main process (16657)

A similar problem (the same ?) is reported here:
http://www.freak-search.com/de/thread/2643371/vserver_problems_installing_ubuntu_10.10_as_a_guest_of_a_debian_host

Thanks,
Roberto Sebastiano

[robs (roberto-sebastiano)]

While I confirm that both start process and stop process simply hang, here it is an interesting behavior with the -n option:

root@robsvserver:~# ps ax
  PID TTY STAT TIME COMMAND
    1 ? Ss 0:00 /sbin/init
29850 ? Ss 0:00 dbus-daemon --system --fork
29864 ? Sl 0:00 rsyslogd -c4
29872 ? Ss 0:00 /usr/sbin/sshd
29912 ? Ssl 0:00 /usr/sbin/mysqld
30107 ? Ss 0:00 sshd: root@pts/1
31496 ? Sl 0:00 /usr/sbin/console-kit-daemon --no-daemon
31745 pts/1 Ss 0:00 -bash
32285 pts/1 R+ 0:00 ps ax

root@robsvserver:~# status rsyslog
rsyslog start/running, process 27114
root@robsvserver:~# stop -n rsyslog ## This works, process is now stopped
rsyslog stop/killed, process 27114
root@robsvserver:~# ps ax
  PID TTY STAT TIME COMMAND
    1 ? Ss 0:00 /sbin/init
29850 ? Ss 0:00 dbus-daemon --system --fork
29872 ? Ss 0:00 /usr/sbin/sshd
29912 ? Ssl 0:00 /usr/sbin/mysqld
30107 ? Ss 0:00 sshd: root@pts/1
31496 ? Sl 0:00 /usr/sbin/console-kit-daemon --no-daemon
31745 pts/1 Ss 0:00 -bash
32287 pts/1 R+ 0:00 ps ax
root@robsvserver:~# start -n rsyslog ## This will not work
rsyslog start/killed, process 29864
root@robsvserver:~# ps ax
  PID TTY STAT TIME COMMAND
    1 ? Ss 0:00 /sbin/init
29850 ? Ss 0:00 dbus-daemon --system --fork
29872 ? Ss 0:00 /usr/sbin/sshd
29912 ? Ssl 0:00 /usr/sbin/mysqld
30107 ? Ss 0:00 sshd: root@pts/1
31496 ? Sl 0:00 /usr/sbin/console-kit-daemon --no-daemon
31745 pts/1 Ss 0:00 -bash
32289 pts/1 R+ 0:00 ps ax
root@robsvserver:~# status rsyslog
rsyslog start/killed, process 29864

[robs (roberto-sebastiano)]

Attached the output of "strace -f stop rsyslog"

[Clint Byrum (clint-fewbar)]

robs, first off thanks for taking the time to file this bug report.

Could you run

initctl log-priority debug

and repeat the 'stop rsyslog'

then

initctl log-priority message

and then show us the resulting entries in /var/log/daemon.log ?

[robs (roberto-sebastiano)]

This is what I get in /var/log/daemon.log after stop rsyslog:

Jan 24 09:29:47 robsvserver init: Connection from private client
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface_2dsecurity
Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/networking
Jan 24 09:29:56 robsvserver init: Connection from private client
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
Jan 24 09:29:56 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
Jan 24 09:29:56 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
Jan 24 09:29:56 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com...

[Scott James Remnant (scott)]

How long did you wait?

On Mon, Jan 24, 2011 at 1:33 AM, robs <email address hidden> wrote:
> This is what I get in /var/log/daemon.log after stop rsyslog:
>
>
> Jan 24 09:29:47 robsvserver init: Connection from private client
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
> Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
> Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
> Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
> Jan 24 09:29:47 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface_2dsecurity
> Jan 24 09:29:47 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/networking
> Jan 24 09:29:56 robsvserver init: Connection from private client
> Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
> Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
> Jan 24 09:29:56 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
> Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
> Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
> Jan 24 09:29:56 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
> Jan 24 09:29:56 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
> Jan 24 09:29:56 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
> Jan 24 09:29:56 robsvserve...

[robs (roberto-sebastiano)]

root@robsvserver:~# time stop rsyslog
^C

real 44m26.780s
user 0m0.010s
sys 0m0.000s

[Scott James Remnant (scott)]

And there are no further log messages within this time?!

On Tue, Jan 25, 2011 at 6:22 AM, robs <email address hidden> wrote:
> root@robsvserver:~# time stop rsyslog
> ^C
>
> real    44m26.780s
> user    0m0.010s
> sys     0m0.000s
>
> --
> You received this bug notification because you are a member of Upstart
> Developers, which is subscribed to upstart .
> https://bugs.launchpad.net/bugs/703993
>
> Title:
>  start and stop hang when run inside a 10.04 Vserver guest
>
> Status in Upstart:
>  New
>
> Bug description:
>  I configured a host machine with Ubuntu Lucid 10.04 amd64, then I
>  installed:
>
>  ii  linux-headers-2.6.32-27-vserver   2.6.32-27.49~ppa3
>  ii  linux-headers-vserver                    2.6.32.27.29~ppa1
>  ii  linux-image-2.6.32-27-vserver      2.6.32-27.49~ppa3
>  ii  linux-image-vserver                      2.6.32.27.29~ppa1
>  ii  util-vserver                                    0.30.216~r2842-2ubuntu2
>
>  I followed http://linux-vserver.org/Upstart_issues to successfully build a guest system.
>  The guest boots and halt fine, but if the stop and start commands are executed from the console, they simply hang.
>
>  This doesn't allow apt-get upgrades to run smoothly, as post-inst
>  scripts often call restart "servicename"
>
>  I attach the Upstart debug I get from stop dbus .. seems fine to me ? :
>  init: Connection from private client
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
>  init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
>  init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
>  init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
>  init: dbus goal changed from start to stop
>  init: dbus state changed from running to pre-stop
>  init: dbus state changed from pre-stop to stopping
>  init: event_new: Pending stopping event
>  init: Handling stopping event
>  init: event_finished: Finished stopping event
>  init: dbus state changed from stopping to killed
>  init: Sending TERM signal to dbus main process (16657)
>  init: Disconnected from system bus
>  init: Sending KILL signal to dbus main process (16657)
>
>  A similar problem (the same ?) is reported here:
>  http://www.freak-search.com/de/thread/2643371/vserver_problems_installing_ubuntu_10.10_as_a_guest_of_a_debian_host
>
>
>  Thanks,
>  Roberto Sebastiano
>
>
>

[robs (roberto-sebastiano)]

No.

Note that rsyslog is now killed.

I think that the "stop" command is waiting some feedback from upstart ?

I can give access to the virtual machine to debug further

[Clint Byrum (clint-fewbar)]

robs, it makes sense that all logs would stop when rsyslog was killed.. so maybe thats not what does it.

Maybe add a task

# rsyslog-stopped
start on stopped rsyslog
task

script
  initctl list > /list.after.rsyslog.stopped
end script

That should record that rsyslog actually stopped. Maybe also there is more information on the console. I'm not sure how to get to the console on linux v-server but it may offer some clues since you're running in debug mode.

[Scott James Remnant (scott)]

No it doesn't, there should be further logs indicating that rsyslog
actually responded to the signal, shut down and exited - or if not,
15s, Upstart followed up with SIGKILL

On Tue, Jan 25, 2011 at 5:02 PM, Clint Byrum <email address hidden> wrote:
> robs, it makes sense that all logs would stop when rsyslog was killed..
> so maybe thats not what does it.
>
> Maybe add a task
>
> # rsyslog-stopped
> start on stopped rsyslog
> task
>
> script
>  initctl list > /list.after.rsyslog.stopped
> end script
>
>
> That should record that rsyslog actually stopped. Maybe also there is more information on the console. I'm not sure how to get to the console on linux v-server but it may offer some clues since you're running in debug mode.
>
> --
> You received this bug notification because you are a member of Upstart
> Developers, which is subscribed to upstart .
> https://bugs.launchpad.net/bugs/703993
>
> Title:
>  start and stop hang when run inside a 10.04 Vserver guest
>
> Status in Upstart:
>  New
>
> Bug description:
>  I configured a host machine with Ubuntu Lucid 10.04 amd64, then I
>  installed:
>
>  ii  linux-headers-2.6.32-27-vserver   2.6.32-27.49~ppa3
>  ii  linux-headers-vserver                    2.6.32.27.29~ppa1
>  ii  linux-image-2.6.32-27-vserver      2.6.32-27.49~ppa3
>  ii  linux-image-vserver                      2.6.32.27.29~ppa1
>  ii  util-vserver                                    0.30.216~r2842-2ubuntu2
>
>  I followed http://linux-vserver.org/Upstart_issues to successfully build a guest system.
>  The guest boots and halt fine, but if the stop and start commands are executed from the console, they simply hang.
>
>  This doesn't allow apt-get upgrades to run smoothly, as post-inst
>  scripts often call restart "servicename"
>
>  I attach the Upstart debug I get from stop dbus .. seems fine to me ? :
>  init: Connection from private client
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
>  init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
>  init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
>  init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
>  init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
>  init: dbus goal changed from start to stop
>  init: dbus state changed from running to pre-stop
>  init: dbus state changed from pre-stop to stopping
>  init: event_new: Pending stopping event
>  init: Handl...

[Clint Byrum (clint-fewbar)]

Thats exactly what I was thinking happened Scott... that rsyslog's TERM handler got hung up, and the thing had to be SIGKILL'd... which could certainly take a while if the TERM handler was blocking in some virtualized vserver syscall.

So what might be more interesting is to attach strace to rsyslog before starting the shutdown attempt.

[robs (roberto-sebastiano)]

Well rsyslog was a tricky one, but stop ssh gives the same:

Jan 26 09:41:26 robsvserver init: Connection from private client
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
Jan 26 09:41:26 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
Jan 26 09:41:26 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
Jan 26 09:41:26 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
Jan 26 09:41:26 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface_2dsecurity
Jan 26 09:41:26 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/networking
Jan 26 09:41:26 robsvserver init: ssh goal changed from start to stop
Jan 26 09:41:26 robsvserver init: ssh state changed from running to pre-stop
Jan 26 09:41:26 robsvserver init: ssh state changed from pre-stop to stopping
Jan 26 09:41:26 robsvserver init: event_new: Pending stopping event
Jan 26 09:41:26 robsvserver init: Handling stopping event
Jan 26 09:41:26 robsvserver init: event_finished: Finished stopping event
Jan 26 09:41:26 robsvserver init: ssh state changed from stopping to killed
Jan 26 09:41:26 robsvserver init: Sending TERM signal to ssh main process (22322)
Jan 26 09:41:31 robsvserver init: Sending KILL signal to ssh main process (22322)

*** hangs ***

[robs (roberto-sebastiano)]

Here is the strace after "stop ssh"

root@robsvserver:~# ps aux | grep sbin/sshd
root 30785 0.0 0.2 49260 1100 ? Ss 09:58 0:00 /usr/sbin/sshd

root@robsvserver:~# strace -p 30785 -f
Process 30785 attached - interrupt to quit
select(7, [3], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
rt_sigreturn(0xf) = -1 EINTR (Interrupted system call)
socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4
connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
sendto(4, "<38>Jan 26 10:11:16 sshd[30785]:"..., 65, MSG_NOSIGNAL, NULL, 0) = 65
close(4) = 0
close(3) = 0
unlink("/var/run/sshd.pid") = 0
exit_group(255) = ?
Process 30785 detached

/var/log/daemon.log:

Jan 26 10:11:16 robsvserver init: Connection from private client
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog_2dstopped
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface_2dsecurity
Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/networking
Jan 26 10:11:16 robsvserver init: ssh goal changed from start to stop
Jan 26 10:11:16 robsvserver init: ssh state changed from running to pre-stop
Jan 26 10:11:16 robsvser...

[Scott James Remnant (scott)]

Ok, that sounds more like SIGCHLD isn't getting delivered to Upstart -
which would sound like a container bug?

On Wed, Jan 26, 2011 at 2:16 AM, robs <email address hidden> wrote:
> Here is the strace after "stop ssh"
>
> root@robsvserver:~# ps aux | grep sbin/sshd
> root     30785  0.0  0.2  49260  1100 ?        Ss   09:58   0:00 /usr/sbin/sshd
>
> root@robsvserver:~# strace -p 30785 -f
> Process 30785 attached - interrupt to quit
> select(7, [3], NULL, NULL, NULL)        = ? ERESTARTNOHAND (To be restarted)
> --- SIGTERM (Terminated) @ 0 (0) ---
> rt_sigreturn(0xf)                       = -1 EINTR (Interrupted system call)
> socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4
> connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
> sendto(4, "<38>Jan 26 10:11:16 sshd[30785]:"..., 65, MSG_NOSIGNAL, NULL, 0) = 65
> close(4)                                = 0
> close(3)                                = 0
> unlink("/var/run/sshd.pid")             = 0
> exit_group(255)                         = ?
> Process 30785 detached
>
>
> /var/log/daemon.log:
>
> Jan 26 10:11:16 robsvserver init: Connection from private client
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog
> Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/rsyslog/_
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/screen_2dcleanup
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/dbus
> Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/dbus/_
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rsyslog_2dstopped
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/ssh
> Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/ssh/_
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/control_2dalt_2ddelete
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/vserver
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dvarrun
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/rc_2dsysinit
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2ddev
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mysql
> Jan 26 10:11:16 robsvserver init: job_register: Registered instance /com/ubuntu/Upstart/jobs/mysql/_
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/mounted_2dtmp
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface
> Jan 26 10:11:16 robsvserver init: job_class_register: Registered job /com/ubuntu/Upstart/jobs/network_2dinterface_2dsecurity
> Jan 26 ...

[Jean-Baptiste Wons (wonsjb)]

It looks like I ran into the same problem.

Here is my init config file:
expect daemon
exec su debian -c 'exec /usr/bin/gpg-agent --daemon --sh --allow-preset-passphrase --write-env-file /home/debian/.gpg-agent.pid'

I also tried with expect fork, same result.

Basically, upstart gets confused on what pid the final process has.
emily:/etc/init# initctl list | grep killed
debian-agent4 stop/killed, process 5003
debian-agent5 stop/killed, process 5399
debian-agent2 stop/killed, process 4707
debian-agent stop/killed, process 3338
debian-agent3 stop/killed, process 4857

Those PID do not exist anymore, and my guess is that they where the parent process of the process I expect upstart to monitor.

I fixed my configuration file, by using a custom version of su that does not fork, but just exec what I give to it, so I have it working (with expect fork, as gpg-agent is still doing his own fork)

emily:/etc/init# initctl status debian-agent6
debian-agent6 start/running, process 11438
emily:/etc/init# ps aux | grep 11438
debian 11438 0.0 0.0 21412 512 ? Ss 21:57 0:00 /usr/bin/gpg-agent --batch --log-file /home/debian/gpg-agent.log --daemon --sh --allow-preset-passphrase --write-env-file /home/debian/.gpg-agent.pid

But still, I cannot get rid of those 5 other tasks, as upstart is waiting for a SIGCHLD for a process that do not exists anymore. A wild guess is that it started accepting somehow this signal after the process was dead, and SIGCHLD was delivered, but I would need to look at the source code to confirm it.
And as init is not something that I can restart, it looks like those ghost tasks will stay until the next reboot of that server.

Thanks,
Jean-Baptiste

[Jean-Baptiste Wons (wonsjb)]

I forgot to mention, I am not on a virtual machine, but on a regular server, running Debian/Squeeze.

[Johan Kiviniemi (ion)]

Jean-Baptiste,

You probably have a separate issue. Better not use ‘expect’ if you’re not 100 % sure of the behavior of the main process wrt. forking. Otherwise you’ll confuse Upstart’s present fork tracking code and end up in that situation.

Either reboot or use the nasty kluge at http://heh.fi/tmp/workaround-upstart-snafu (passing it the nonexistent pid from initctl status) to unconfuse Upstart.

A future release of Upstart will use a more robust method of following forks.

[Jean-Baptiste Wons (wonsjb)]

Yes indeed, that is unrelated (sorry for the confusion)
I did more digging, and the bug is this one:
https://bugs.launchpad.net/upstart/+bug/406397

Thanks for the tip though !

Regards,
Jean-Baptiste

[Grzegorz Nosek (5-root-localdomain-pl)]

Attached is a patch I made yesterday which fixes this issue.

Here's a thread about it but it's mostly my posts :/

http://list.linux-vserver.org/archive?mss:5779:201203:embicihfaemdienlcapb