8 minute Upstart delay during LTSP client boot

Mon Nov 12 10:33:05 UTC 2012

After successfully using LTSP on a Ubuntu Lucid server running Natty clients, I'm now trying to get LTSP going on a Precise Pangolin Ubuntu 12.04 server with 12.04 clients. At first I thought the boot was hanging completely, but by accident I discovered that if I just wait enough the X11 login screen eventually comes up.

LTSP uses an nbd filesystem for root. As far as I can tell, nbd root is present and working.

In order to track this bug down I had to worm my way through all the scripts in the boot process, starting in the LTSP initramfs image. I have discovered that the delay occurs after the boot image has handed over control to the system on the nbd filesystem. The /sbin/init-ltsp script runs completely and the problem is when it passes control over to /sbin/init, in other words upstart. 

I modified /sbin/init-ltsp to start /sbin/init with --verbose as well as with --debug. I have discovered that after starting mountall, hostname, plymouth and hwclock there is a delay, apparently almost exactly 480 seconds (8 minutes) before things start up again.

I then modified /sbin/init-ltsp to start /bin/sh instead of /sbin/init so I could open up a tty in the second console. This shell worked fine, thus implying that the nbd root filesystem is alright. I then started upstart without triggering the startup event so I could use initctl to trigger individual events. No matter what event I triggered - mountall, hwclock, startup, whatever - I first get a delay (again, I believe always 8 minutes) before any activity starts.

I'm not sure whether this is an upstart problem or an ltsp problem. I posted this problem on the lstp list last Friday but as of yet have received not reponse.

I'm hoping somebody here might have an idea or steer me in a direction as to how to proceed with debugging the problem.

Here is the boot log. Note the delay between second 15.06 and second 493.59. I am not including the messages prior to the nbd line.

...
kernel: [    1.987255] nbd: registered device at major 43
kernel: [    1.990881] squashfs: version 4.0 (2009/01/31) Phillip Lougher
kernel: [    1.996740] aufs 3.2-20120109
kernel: [    3.006856] tg3 0000:3f:00.0: irq 41 for MSI/MSI-X
kernel: [    3.052654] ADDRCONF(NETDEV_UP): eth0: link is not ready
kernel: [    4.624404] tg3 0000:3f:00.0: eth0: Link is up at 100 Mbps, full duplex
kernel: [    4.624542] tg3 0000:3f:00.0: eth0: Flow control is on for TX and on for RX
kernel: [    4.625218] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
kernel: [    6.261805]  nbd0: unknown partition table
kernel: [   10.256505] Adding 2088412k swap on /dev/mapper/swap0.  Priority:-1 extents:1 across:2088412k 
kernel: [   10.389703] init: Handling startup event
kernel: [   10.393293] init: mountall goal changed from stop to start
kernel: [   10.396876] init: mountall state changed from waiting to starting
kernel: [   10.400445] init: hostname goal changed from stop to start
kernel: [   10.404063] init: hostname state changed from waiting to starting
kernel: [   10.407725] init: Handling starting event
kernel: [   10.411441] init: plymouth goal changed from stop to start
kernel: [   10.415123] init: plymouth state changed from waiting to starting
kernel: [   10.418895] init: hwclock goal changed from stop to start
kernel: [   10.422685] init: hwclock state changed from waiting to starting
kernel: [   10.426515] init: Handling starting event
kernel: [   10.430429] init: hostname state changed from starting to pre-start
kernel: [   10.434270] init: hostname state changed from pre-start to spawned
kernel: [   10.440758] init: hostname main process (490)
kernel: [   10.444736] init: hostname state changed from spawned to post-start
kernel: [   10.448705] init: hostname state changed from post-start to running
kernel: [   10.452715] init: Handling starting event
kernel: [   10.456890] init: plymouth state changed from starting to pre-start
kernel: [   10.461012] init: plymouth state changed from pre-start to spawned
kernel: [   10.466298] init: plymouth main process (491)
kernel: [   10.470492] init: Handling starting event
kernel: [   10.474789] init: hwclock state changed from starting to pre-start
kernel: [   10.479044] init: hwclock state changed from pre-start to spawned
kernel: [   10.484489] init: hwclock main process (492)
kernel: [   10.488817] init: hwclock state changed from spawned to post-start
kernel: [   10.493164] init: hwclock state changed from post-start to running
kernel: [   10.497484] init: Handling started event
kernel: [   10.501877] init: Handling started event
kernel: [   10.506297] init: hostname main process (490) exited normally
kernel: [   10.510710] init: hostname goal changed from start to stop
kernel: [   10.515092] init: hostname state changed from running to stopping
kernel: [   10.520518] init: Handling stopping event
kernel: [   10.525093] init: hostname state changed from stopping to killed
kernel: [   10.529660] init: hostname state changed from killed to post-stop
kernel: [   10.534122] init: hostname state changed from post-stop to waiting
kernel: [   10.538680] init: Handling stopped event
kernel: [   10.543398] init: hwclock main process (492) exited normally
kernel: [   10.548032] init: hwclock goal changed from start to stop
kernel: [   10.552674] init: hwclock state changed from running to stopping
kernel: [   10.557371] init: plymouth main process (491) executable changed
kernel: [   10.562082] init: Handling stopping event
kernel: [   10.566772] init: hwclock state changed from stopping to killed
kernel: [   10.571571] init: hwclock state changed from killed to post-stop
kernel: [   10.576347] init: hwclock state changed from post-stop to waiting
kernel: [   10.581083] init: Handling stopped event
kernel: [   10.585794] init: plymouth main process (491) became new process (493)
kernel: [   10.590500] init: plymouth state changed from spawned to post-start
kernel: [   10.596985] init: plymouth post-start process (494)
kernel: [   10.602007] init: plymouth post-start process (494) exited normally
kernel: [   10.606621] init: plymouth state changed from post-start to running
kernel: [   10.611110] init: mountall state changed from starting to pre-start
kernel: [   10.615586] init: mountall state changed from pre-start to spawned
kernel: [   10.620646] init: mountall main process (495)
kernel: [   10.625214] init: Handling started event
kernel: [   10.631363] init: mountall main process (495) became new process (496)
kernel: [   10.640544] init: mountall main process (496) executable changed
kernel: [   10.645152] init: mountall state changed from spawned to post-start
kernel: [   10.649727] init: mountall state changed from post-start to running
kernel: [   10.654354] init: Handling started event
kernel: [   10.715882] init: Connection from private client
kernel: [   15.064034] eth0: no IPv6 routers present
kernel: [  493.598743] init: Handling mounted event
kernel: [  493.647087] init: Handling all-swaps event
kernel: [  493.651883] init: Handling mounted event
kernel: [  493.656689] init: Handling mounted event
kernel: [  493.661594] init: Handling mounted event
kernel: [  493.666240] init: Handling mounted event
kernel: [  493.670835] init: Handling mounted event
kernel: [  493.675233] init: resolvconf goal changed from stop to start
kernel: [  493.679567] init: resolvconf state changed from waiting to starting
kernel: [  493.683991] init: container-detect goal changed from stop to start
kernel: [  493.688387] init: container-detect state changed from waiting to starting
kernel: [  493.692797] init: Handling starting event
kernel: [  493.697132] init: resolvconf state changed from starting to pre-start
kernel: [  493.702753] init: resolvconf pre-start process (508)
kernel: [  493.707193] init: Handling starting event
kernel: [  493.711676] init: container-detect state changed from starting to pre-start
kernel: [  493.717341] init: container-detect pre-start process (509)
kernel: [  493.771816] init: Connection from private client
kernel: [  493.776902] init: Handling not-container event
kernel: [  493.791768] init: Connection from private client
kernel: [  493.796800] init: container-detect goal changed from start to stop
kernel: [  493.811683] init: container-detect pre-start process (509) exited normally
kernel: [  493.816350] init: container-detect state changed from pre-start to stopping
kernel: [  493.821047] init: Handling stopping event
kernel: [  493.825634] init: container-detect state changed from stopping to killed
kernel: [  493.830191] init: container-detect state changed from killed to post-stop
kernel: [  493.834859] init: container-detect state changed from post-stop to waiting
kernel: [  493.839442] init: Handling stopped event
kernel: [  494.252831] init: resolvconf pre-start process (508) exited normally
kernel: [  494.257459] init: resolvconf state changed from pre-start to spawned
kernel: [  494.262055] init: resolvconf state changed from spawned to post-start
kernel: [  494.266640] init: resolvconf state changed from post-start to running
kernel: [  494.271226] init: Handling started event
kernel: [  494.275953] init: Handling mounted event
kernel: [  494.280751] init: Handling mounted event
kernel: [  494.285477] init: Handling mountallServer event
kernel: [  494.289945] init: Handling mounting event
kernel: [  494.297648] init: Handling mounted event
kernel: [  494.302384] init: Handling mounting event
kernel: [  494.309646] init: Handling mounted event
kernel: [  494.314213] init: Handling mounting event
kernel: [  494.321429] init: Handling mounted event
kernel: [  494.325932] init: Handling mounting event
kernel: [  494.330175] init: Handling mounted event
kernel: [  494.334430] init: Handling mounting event
kernel: [  494.341479] init: Handling mounted event
kernel: [  494.345782] init: Handling mounting event
kernel: [  494.352776] init: Handling mounted event
kernel: [  494.356992] init: Handling virtual-filesystems event

...