bzr hangs (deadlock) on push/pull/merge

!!!!!!!!!!!!!
It now hangs between 2 1.17 versions too!
!!!!!!!!!!!!!

The server bt after a kill -QUIT:
-bash-3.00$ bzr serve --directory /media/d02/bzr --allow-writes
listening on port: 4155
** SIGQUIT received, entering debugger
** Type 'c' to continue or 'q' to stop the process
** Or SIGQUIT again to quit (and possibly dump core)
> /usr/local/lib/python2.4/site-packages/bzrlib/breakin.py(33)_debug()
-> signal.signal(signal.SIGQUIT, _debug)
(Pdb) bt
  /usr/local/bin/bzr(142)?()
-> exit_val = bzrlib.commands.main()
  /usr/local/lib/python2.4/site-packages/bzrlib/commands.py(1108)main()
-> ret = run_bzr_catch_errors(argv)
  /usr/local/lib/python2.4/site-packages/bzrlib/commands.py(1120)run_bzr_catch_errors()
-> return exception_to_return_code(run_bzr, argv)
  /usr/local/lib/python2.4/site-packages/bzrlib/commands.py(835)exception_to_return_code()
-> return the_callable(*args, **kwargs)
  /usr/local/lib/python2.4/site-packages/bzrlib/commands.py(1030)run_bzr()
-> ret = run(*run_argv)
  /usr/local/lib/python2.4/site-packages/bzrlib/commands.py(647)run_argv_aliases()
-> return self.run(**all_cmd_args)
  /usr/local/lib/python2.4/site-packages/bzrlib/builtins.py(4725)run()
-> protocol(transport, host, port, inet)
  /usr/local/lib/python2.4/site-packages/bzrlib/smart/server.py(342)serve_bzr()
-> smart_server.serve()
  /usr/local/lib/python2.4/site-packages/bzrlib/smart/server.py(121)serve()
-> conn, client_addr = self._server_socket.accept()
> /usr/local/lib/python2.4/site-packages/bzrlib/breakin.py(33)_debug()
-> signal.signal(signal.SIGQUIT, _debug)
(Pdb)

The kill -QUIT with bt on the client at this point:
jo@seahorse:~/bzr/vp-trunk$ bzr merge bzr://bzr.hosts.itris.nl/vp-trunk
** SIGQUIT received, entering debuggerB/s | Fetching revisions:Inserting
stream
** Type 'c' to continue or 'q' to stop the process
** Or SIGQUIT again to quit (and possibly dump core)
> /usr/lib/python2.5/site-packages/bzrlib/breakin.py(33)_debug()
-> signal.signal(signal.SIGQUIT, _debug)
(Pdb) bt
  /usr/bin/bzr(142)<module>()
-> exit_val = bzrlib.commands.main()
  /usr/lib/python2.5/site-packages/bzrlib/commands.py(1108)main()
-> ret = run_bzr_catch_errors(argv)
  /usr/lib/python2.5/site-packages/bzrlib/commands.py(1120)run_bzr_catch_errors()
-> return exception_to_return_code(run_bzr, argv)
  /usr/lib/python2.5/site-packages/bzrlib/commands.py(835)exception_to_return_code()
-> return the_callable(*args, **kwargs)
  /usr/lib/python2.5/site-packages/bzrlib/commands.py(1030)run_bzr()
-> ret = run(*run_argv)
  /usr/lib/python2.5/site-packages/bzrlib/commands.py(647)run_argv_aliases()
-> return self.run(**all_cmd_args)
  /usr/lib/python2.5/site-packages/bzrlib/builtins.py(3683)run()
-> location, revision, remember, possible_transports, pb)
  /usr/lib/python2.5/site-packages/bzrlib/builtins.py(3790)_get_merger_from_branch()
-> other_revision_id, base_revision_id, other_branch, base_branch)
  /usr/lib/python2.5/site-packages/bzrlib/merge.py(204)from_revision_ids()
-> merger.set_other_revision(other, other_branch)
  /usr/lib/python2.5/site-packages/bzrlib/merge.py(343)set_other_revision()
-> self._maybe_fetch(other_branch, self.this_branch, self.other_rev_id)
  /usr/lib/python2...

Unfortunately SIGQUIT won't be readily useful on TCP "bzr serve" servers, because the interesting thread is not the main thread, and I don't think pdb provides any way to get a backtrace for a non-main thread. The server is definitely the interesting side of this; the client is simply waiting for the server to send it more data.

An strace of the server process may be more revealing. Or, if you have gdb installed on the server (and maybe the python debugging symbols too?) you can try using the gdbinit file linked from http://wiki.python.org/moin/DebuggingWithGdb and use the "pystack" macro on the appropriate thread. Actually, even a regular "thread apply all bt" in gdb might help.

Depending on what has gone wrong, there might be a backtrace lurking in ~/.bzr.log on the server too, although in this case I'm guessing there won't be. (If the server is behaving well enough to log errors, it should be behaving well enough to return an error to the client too.)

I have an strace of the server *after* it hangs, not before it:
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAKE, 1) = 1
poll([{fd=4, events=POLLIN}], 1, 1000) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAKE, 1) = 1
poll([{fd=4, events=POLLIN}], 1, 1000) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAKE, 1) = 1
poll([{fd=4, events=POLLIN}], 1, 1000) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
futex(0x937a5a8, FUTEX_WAKE, 1) = 1
poll([{fd=4, events=POLLIN}], 1, 1000) = 0

In effect it is not doing anything. I'll investigate if it is possible to do a gdb; this server runs Red Head 4 (I always get a red head because it is such an unfriendly horrible Linux distro) and I had to compile Python by hand there - RHEL 3 has python 2.3 as base.

Frits Jalvingh wrote:
> I have an strace of the server *after* it hangs, not before it:
> futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
> futex(0x937a5a8, FUTEX_WAIT, 0, NULL) = 0
> futex(0x937a5a8, FUTEX_WAKE, 1) = 1
> poll([{fd=4, events=POLLIN}], 1, 1000) = 0
[etc]
> In effect it is not doing anything.

I think that's probably just the main thread, again. fd 4 seems likely to be
the listening socket (I'd expect 0, 1, 2 are stdio, and 3 to be the ~/.bzr.log).
So this thread is just polling the listening socket for new incoming
connections, I think, which is normal and correct.

Try looking in /proc/<pid>/task for PIDs of the thread(s), and stracing those.

Thanks for your persistence!

> I think that's probably just the main thread....
Yes, I know; I just gave it as an indication that it seems to do nothing at all.

> Try looking in /proc/<pid>/task for PIDs of the thread(s), and stracing those.
Good tip, I'll try to do that the next time it hangs.

> Thanks for your persistence!
Thanks *you* for helping!

I now have a server process that seems to idle, and /proc/[pid]/task/ only contains a single pid (the main thread). The log states:
[24839] 2009-08-11 13:59:05.109 WARNING: listening socket error: (11, 'Resource temporarily unavailable')
[24839] 2009-08-11 13:59:30.820 WARNING: listening socket error: (11, 'Resource temporarily unavailable')

In the meantime the client stays blocked on a recvfrom(4,...)

I logged open connections and found something very odd: the client is waiting on a connection it thinks is open:
bzr 21626 jal 4u IPv4 1165611 TCP 172.22.128.28:44635->192.168.0.110:4155 (ESTABLISHED)

The server has no task running, and actually does not have this connection anymore:
[root@mouse ~]# netstat -n | grep \.28\:
tcp 0 0 192.168.0.110:1521 172.22.126.28:1702 ESTABLISHED
tcp 0 0 192.168.0.110:1521 172.22.126.28:2176 ESTABLISHED
tcp 0 0 192.168.0.110:1521 172.22.126.28:1516 ESTABLISHED
tcp 0 0 192.168.0.110:1521 172.22.126.28:2174 ESTABLISHED
tcp 0 0 192.168.0.110:1521 172.22.126.28:2171 ESTABLISHED
tcp 0 0 192.168.0.110:1521 172.22.126.28:1127 ESTABLISHED
tcp 0 0 192.168.0.110:445 172.22.126.28:1094 ESTABLISHED
tcp 0 0 192.168.0.110:445 172.22.126.28:1098 ESTABLISHED
tcp 0 512 ::ffff:192.168.0.110:22 ::ffff:172.22.128.28:34085 ESTABLISHED

Either the connection has been idle for so long that the firewall caused a close or!?

I did a full strace on the server thread for such a run. It seems to do a lot of reading for a long, long time; then it looks like it is dying:
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8bf03a8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0

lots of repeats of this, with intermittent something like:
fstat64(5, {st_mode=S_IFREG|0664, st_size=27403786, ...}) = 0
mmap2(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x931a4000
_llseek(5, 0, [0], SEEK_SET) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
read(5, "Bazaar pack format 1 (introduced"..., 32768) = 32768
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
_llseek(5, 9961472, [9961472], SEEK_SET) = 0
read(5, "\331b\261\241\0\0\0B122\n\n\37\213\10\0\0\0\0\0\2\377\235"..., 32768) = 32768

Then near the end it goes:
futex(0x8bf03a8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8bf03a8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
mmap2(NULL, 5746688, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x8bea9000
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
send(6, "b\0\0\3|B874\ninventories\n\nknit-delt"..., 65536, 0) = 65536
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
send(6, "\313z\263|\304\325\372\31\363\242.r\17B{\2\376\355\214"..., 65536, 0) = 29648
send(6, "\242&\303}\335MV6\311&\207GJ\257\373\362\357\207\7\227"..., 35888, 0) = -1 ECONNRESET (Connection reset by peer)
futex(0x8ac2260, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/protocol.py", {st_mode=S_IFREG|0644, st_size=50748, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/message.py", {st_mode=S_IFREG|0644, st_size=13718, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/protocol.py", {st_mode=S_IFREG|0644, st_size=50748, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/protocol.py", {st_mode=S_IFREG|0644, st_size=50748, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/protocol.py", {st_mode=S_IFREG|0644, st_size=50748, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/protocol.py", {st_mode=S_IFREG|0644, st_size=50748, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/smart/medium.py", {st_mode=S_IFREG|0644, st_size=35183, ...}) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
futex(0x8c96cf8, FUTEX_WAKE, 1) = 0
stat64("/usr/local/lib/python2.4/site-packages/bzrlib/osutils.py", {st_mode=S_IFREG|0644, st_size=61815, ...}) = 0
futex(0x8c96...