test_sigint_exits_cleanly breaks

[Gavin Panella]

Failure in test test_sigint_exits_nicely (bzrlib.plugins.lpserve.test_lpserve.TestLPServiceInSubprocess)
Traceback (most recent call last):
_StringException: log: {{{
81.104 started lp-service subprocess
82.772 Listening on socket: /tmp/tmp-lp-service-4yBbLy.sock

82.772 sending 'fork rocks\n' to socket /tmp/tmp-lp-service-4yBbLy.sock
82.805 response: 'ok\n12949\n/tmp/lp-forking-service-child-v1rit0\n'
82.805 getting handles for: /tmp/lp-forking-service-child-v1rit0
82.849 sending 'quit\n' to socket /tmp/tmp-lp-service-4yBbLy.sock
}}}

server-log: {{{
this is a debug log for diagnosing/reporting problems in bzr
you can delete or truncate this file, or include sections in
bug reports to https://bugs.launchpad.net/bzr/+filebug

Thu 2012-01-05 15:55:13 +0530
1.193 bazaar version: 2.5.0dev2-r6152
1.193 bzr arguments: [u'lp-service', u'--path', u'/tmp/tmp-lp-service-4yBbLy.sock', u'--no-preload', u'--children-timeout=1']
1.195 looking for plugins in /srv/buildbot/slaves/launchpad/lucid-devel/build/bzrplugins
1.234 looking for plugins in /srv/buildbot/slaves/launchpad/lucid-devel/build/orig_sourcecode/eggs/bzr-2.5.0dev2_r6152-py2.6-linux-x86_64.egg/bzrlib/plugins
1.238 encoding stdout as osutils.get_user_encoding() 'ANSI_X3.4-1968'
1.238 set socket timeout to: 1.0
[12908] 2012-01-05 15:55:14.492 INFO: Listening on socket: /tmp/tmp-lp-service-4yBbLy.sock
1.249 [] connected
1.250 [] request: 'fork rocks\n'
1.270 12949 spawned
[12908] 2012-01-05 15:55:14.526 INFO: Shutting down. Waiting up to 1s for 0 child processes
[12908] 2012-01-05 15:55:14.527 INFO: Exiting
1.274 return code 0
0.000 12949 starting [u'rocks']
0.001 bazaar version: 2.5.0dev2-r6152
0.001 bzr arguments: [u'rocks']
0.004 encoding stdout as osutils.get_user_encoding() 'ANSI_X3.4-1968'
0.013 12949 finished [u'rocks']
}}}

Traceback (most recent call last):
  File "/srv/buildbot/slaves/launchpad/lucid-devel/build/bzrplugins/lpserve/test_lpserve.py", line 608, in test_sigint_exits_nicely
    self._check_exits_nicely(signal.SIGINT)
  File "/srv/buildbot/slaves/launchpad/lucid-devel/build/bzrplugins/lpserve/test_lpserve.py", line 600, in _check_exits_nicely
    self.assertReturnCode(0, sock)
  File "/srv/buildbot/slaves/launchpad/lucid-devel/build/bzrplugins/lpserve/test_lpserve.py", line 521, in assertReturnCode
    self.assertStartsWith(response, 'exited\n')
AssertionError: string '' does not start with 'exited\n'

[Gavin Panella (allenap)]

https://lpbuildbot.canonical.com/builders/lucid_lp/builds/1706

[Gavin Panella (allenap)]

Critical because it's blocking landings.

[William Grant (wgrant)]

buildbot was very low (possibly out) on space during the builds where it failed.

[John A Meinel (jameinel)]

Weird, given that it does say it is exiting in the log file. The mixed times is a bit hard to go through, but you can see:

[12908] 2012-01-05 15:55:14.492 INFO: Listening on socket: /tmp/tmp-lp-service-4yBbLy.sock
1.249 ... some stuff about getting a for request
...
[12908] 2012-01-05 15:55:14.526 INFO: Shutting down. Waiting up to 1s for 0 child processes
[12908] 2012-01-05 15:55:14.527 INFO: Exiting

So it started listening at 55:14.492 and shut down at 55:14.527 or about 35ms after it started it sees that it needed to shut down.

Is there something about buffering going on ?

[Launchpad QA Bot (lpqabot)]

Fixed in stable r16237 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/16237>.

[j.c.sackett (jcsackett)]

We're still seeing this failing randomly--I think this one needs to be investigated or disabled again.