Segfault, hang, or libc “malloc(): memory corruption” if you open and close enough sockets

[brandon-rhodes]

Attached is a minimal test case for a failure that hit my appilcation. In the real app, various server threads have XREP sockets opened, and my front-end web threads open REQ sockets to send request messages that help them build their HTTP response content. After enough socket opens and closings — actually, only one or two (!) in the real app, presumably because so much more is going on in a real app — the application dies with, variously, a segmentation fault (usually in the zmq “recv” function), a hang, or an interesting message (and accompanying libc stack trace!) about “malloc(): memory corruption.”

As you can see, all that seems necessary to kill ØMQ is to open and close enough incoming sockets toward the XREP, and ØMQ will die and take the application with it.

Since I cannot find any record of anyone else ever hitting this problem — whereas it happened for me the very first time that I ever put ØMQ under the demand of two web server threads at once — I would also love to hear whether I am completely wrong to be creating and closing sockets using these calls. It would be great to learn how everyone else is using ØMQ without crashes!

[brandon-rhodes]

Well — okay, I do not see an attachments button. :) Here is my fatal test case, inline:

#!/usr/bin/env python

# Ubuntu python-zmq 2.0.10.1-1: hangs forever
# Ubuntu pyzmq-static 2.0.8: hangs forever
# Ubuntu pyzmq-static against zmq trunk: *** glibc detected *** venv/bin/python:
#     malloc(): memory corruption: 0x099c02d0 ***

from Queue import Queue
import threading
import time
import zmq

def listen(q):
    """Open an XREP socket."""
    socket = zcontext.socket(zmq.XREP)
    socket.bind('tcp://127.0.0.1:7777')
    q.put('ready!')
    time.sleep(100)

def worker():
    while True:
        print 'Opening'
        sock = zcontext.socket(zmq.REQ)
        print 'Connecting'
        sock.connect('tcp://127.0.0.1:7777')
        print 'Closing'
        sock.close()

if __name__ == '__main__':
    zcontext = zmq.Context()
    q = Queue()
    threading.Thread(name='listener', target=listen, args=(q,)).start()
    assert q.get() == 'ready!'
    threading.Thread(name='worker', target=worker).start()

[brandon-rhodes]

[brandon-rhodes]

Oh, wow, I can replicate the failure in C. I guess that means I get to take this bug over to the main project, don't I?

#include <zmq.h>
#include <stdio.h>
#include <unistd.h>
#include <string.h>

int main (void)
{
     void *context = zmq_init(1);

     //  Socket to talk to clients
     void *responder = zmq_socket(context, ZMQ_XREP);
     zmq_bind(responder, "tcp://127.0.0.1:5555");

     while (1) {
          void *requestor = zmq_socket(context, ZMQ_REQ);
          zmq_connect(requestor, "tcp://127.0.0.1:5555");
          zmq_close(requestor);
          requestor = 0;
     }
     //  We never get here but if we did, this would be how we end
     zmq_close(responder);
     zmq_term(context);
     return 0;
}

When compiled against the zmq that comes with Ubuntu 11.04, this results in:

$ ./a.out
Bad file descriptor
rc != -1 (epoll.cpp:83)
zsh: abort      ./a.out

[minrk]

I've been testing this out in C and it is certainly not unique to pyzmq. There are at least two issues here.

First, if you open/close sockets fast enough in your main thread, then the reaper doesn't get a chance to cleanup the file descriptor, and you will run out of fds (hence, Bad file descriptor). This may be a libzmq bug. I'm not sure if there is a way to ensure that zmq_close() waits for the FDs to be cleaned up (it is difficult, since there can still be pending events after the socket closes). You can see this effect by adding:

int fd;
size_t sz=sizeof(int);
zmq_getsockopt(requestor, ZMQ_FD, &fd, &sz);
printf("%d\n",fd);

If the numbers keep growing, the reaper isn't doing its job fast enough. Adding a usleep(1000) in the loop was enough to ensure that the reaper got called every time for me, but 100 seems to protect the example from ulimit. Note that it is your connectors that are having this problem, not the receiver, so if the connectors came from another process, that would crash and the xrep process would not.

However, even if you resolve this you will run into the issue being discussed today on the list of message buffers overflowing when there are too many simultaneously pending actions on the XREP socket.

That said, I can't think of a reason for your application to open a new socket for every request - why doesn't it just keep one socket, rather than allocating/deallocating/handshaking/etc. on every request? That just seems to add unnecessary latency.

I also could not manage to cause a crash with anything less than 300 sockets - nothing close to one or two.

[brandon-rhodes]

Well, drat! If you are correct, this means that, during the log arduous march in which I commented out more and more of my application to try to produce a publishable test case, I must have switched over at some point from generating the actual error — that kills my application after a handful of operations — to a quite different (and trivial) crash mode that has nothing to do with my problem.

So I might be back to the drawing board in terms of getting my app working — or having to try a different mechanism than a message queue — or else adding more and more debug statements to ØMQ that I can actually trace where it goes off of the rails for me.

But as for your claim that I am running out of file descriptors: are you sure about that? For one thing, half the time this small sample program of mine simply hangs, which is not what I would expect from simple file descriptor exhaustion. For another, if I run the program under "strace", then I don't see more than a handful of open() or dup() or socket() or pipe() calls (is there another way to create an fd that I'm forgetting?) during the whole program run, much less enough to have claimed 1,024 descriptors (nor, at first glance, do I see system calls returning increasing integers that approach that limit). And for another thing: if I run the program under gdb, so that I get control when the rc != -1 and the program aborts, and then check it with "lsof", I see only 14 file descriptors opened — not hundreds.

But I am quite new to ØMQ and might be misunderstanding. I will try the sample code snippet you've offered and see what sense I can make of its output.

Oh: and, thank you for jumping in to help out here, and for spending your own time to take a look at this!

[brandon-rhodes]

Would it be okay if I record a few findings here about my “main” problem, just as scratch space, even though I conflated my actual problem with what might be a trivial resource-exhaustion test case? I can cause a crash in my app 100% of the time; here are a few of the causes of death, with exactly the same app running over and over again and then hitting it with 1 or 2 web requests:

Program received signal SIGSEGV, Segmentation fault.
src/ctx.cpp:225
225         slots [tid_]->send (command_);
The problem seems to be that tid_ = 137663456 which is a bit large;
it looks to me like this is usually supposed to be a small integer.
On another run where the app died here, tid_ was 137130172.
On another run, 4294967294.

Assertion failed: nbytes == sizeof (command_t) (src/mailbox.cpp:247)
This is a frequent cause of death; nbytes in these cases is always 0.
This is odd, since block_ is set to true, and therefore recv() under Linux
should perhaps not have returned 0 bytes — but maybe things are wonky
enough by the time this is thrown that the value has been interfered with
from elsewhere in the code?

Program received signal SIGFPE, Arithmetic exception.
at src/lb.cpp:113
113             current = (current + 1) % active;
The problem is that "active" here is zero.

These do not quite add up to a picture of what is going wrong yet, but, then, I am a bit bleary-eyed by this point. Do they look like anything familiar to you — a failure mode of any sort that you have encountered before?

[minrk]

Yes, it's fine to scratch here, but opening an issue on the ØMQ Jira page or posting to the ØMQ list would probably get more informed eyeballs on it - especially with the assertions. I'm not especially well experienced with the inner workings of libzmq. I assume you are using up to date zeromq 2.1.7? If not, that should be step 1.

On your segfault - the only thing of note to me is that the last number (4294967294) is 2**32-2, which is indicative of overflow or wraparound.

The other two are new to me (I have seen the nbytes assertion hit, but nbytes has always been 32 when I check, indicating mailbox buffer overflow).

Per your earlier question, I'm not certain your application is running out of FDs - it may well not be, but I am pretty confident that your test case is - each open zmq socket causes two, I believe.

Can you explain why you are creating a new socket for every request, rather than keeping a single socket for the application? After your reports, I'm definitely not sure that this is your problem.

I think a general description of the messaging pattern in your app might help figure this out.

[brandon-rhodes]

minrk — I currently create a quick socket for each request because when I tried creating a little thread-pool of sockets to be re-used with each incoming request, ØMQ would produce a big traceback each time the web server closed down one of my server threads and took the still-open ØMQ sockets with it. And my client strongly disliked the tracebacks, so I had to take another tack if ØMQ was to stay in the project. So, in essence, I am getting these exceptions because I was trying even harder to avoid some other exceptions. Which has been more generally true of my experience with ØMQ so far. :)

I have been trying 2.0.8, 2.1.7, and (ØMQ trunk + pyzmq 2.1.7) against this particular application. I will probably take your excellent advice and, if I cannot debug this myself, go hit the ØMQ Jira. Thanks again!

[brandon-rhodes]

And a new one. :) (Sorry about the close and re-open, I'm still getting used to where the buttons are on GitHub.)

Invalid argument (mutex.hpp:97)

[minrk]

Wow, I've never seen so many errors with ØMQ! Sorry you aren't having a good time with it. You should definitely not use 2.0, as there are many issues preventing it from being used in production (among them using asserts excessively for ordinary exception states, and hard-exit on ctrl-C), particularly with high-level language bindings that expect to be able to recover from errors. This is much improved in 2.1, and 2.1.7 with pyzmq is used in production, and at pretty large scales.

As for your application - If you do have a multithreaded application, you would have to be careful with fewer Sockets, as they are not threadsafe (contexts are, though).

I asked about the messaging pattern, because I am interested in the actual send/recv pattern of these requests. Do they send one request and receive one reply, or do they last some period of time How many sends/recvs should a socket expect to make during its life? What does the XREP socket's pattern of messages look like?

[brandon-rhodes]

More possible failure modes:

nbytes != -1 (src/mailbox.cpp:190)
Assertion failed: ok (src/xrep.cpp:166)

Sometimes interspersed with actual exceptions that make it to Python instead of crashing the app immediately:

  File "/…/rpc.py", line 54, in __call__
    data = self._sock.recv()
  File "socket.pyx", line 514, in zmq.core.socket.Socket.recv (zmq/core/socket.c:4811)
  File "socket.pyx", line 548, in zmq.core.socket.Socket.recv (zmq/core/socket.c:4673)
  File "socket.pyx", line 99, in zmq.core.socket._recv_copy (zmq/core/socket.c:1344)
ZMQError: Socket operation on non-socket

The message pattern at the moment — as I have commented out much of the app right now to eliminate I/O not related to the failure — is that a server thread starts up, creates, and binds an XREP socket. In normal operation this server thread acts as a dispatcher, examining messages and forwarding them to back-end servers qualified to answer them. But at the moment, it simply responds immediately to each incoming request packet with a response sent immediately back to the same address.

The client threads create a REQ socket, connect to the tcp://localhost:NNNN/ URL of the server thread's XREP socket, send a request, wait to recv() a response, and then close their little socket.

Is there, I wonder, a switch I could throw to output a trace of exactly which ØMQ operations are occurring in what order? I wish I could write a log of such operations that would duplicate the error for everyone else. :)

[brandon-rhodes]

Should it be causing these problems that I am using TCP to communicate between my own threads? I made this decision because (a) the "inproc" mechanism, at least late last year, was giving me exceptions on Windows, (b) the docs said that "inproc" was not as mature, and (c) this makes binding and connecting symmetrical regardless of which of my processes these threads happen to live in — they do not have to detect that, "oh, I want to talk to someone else in the same process", and choose a different URL.

But if TCP back to another thread in the same process is not something that anyone else in the world does, then obviously I need to rethink my decision!

[brandon-rhodes]

Just for fun, I switched to inproc://… URLs, and am seeing exactly the same crashes. The circumstances of the crashes seem to have a different probability distribution — more hanging of the whole app, fewer "Assertion failed" messages from the C++ code — but both possibilities are still there.