Fatal error in GNU libmicrohttpd daemon.c

[austinmarkus]

Hi,

While I think this is a duplicate of #212, that has been closed with the bug still remaining. Janus crashes with a "Fatal error in GNU libmicrohttpd daemon.c:3092: Close socket failed."

Steps to duplicate:

1. Start multiple streams using the streaming plugin (Clients authenticated using token auth added through http admin API)
2. Open the streams in multiple browser windows
3. Let the streams run for at least 10-15 minutes
4. Stop the streams and remove the token (First detach all clients)
5. Crash

I can duplicate using both the thread pool (256 threads) and thread per connection, using both http and https on the admin and client side.
I am running libmicrohttpd 0.9.59 built from source.
Gdb trace: https://pastebin.com/vYapYPQh (thread per connection)

Log snippet (verbosity=7) leading up to the crash
https://pastebin.com/P2rYvvB7
and the backtrace after https://pastebin.com/EJgNrRa5 (This using a thread pool)

I'm happy to add any additional information required to help get to the bottom of this.

Thank you,

-Austin

[lminiero]

If it's happening deep in the library, I don't think there's anything we can do. I'm definitely not an expert of the library internals. You may want to check with the MHD developers instead for some insight: in case it turns out we're doing something wrong, they may have info for us on where to look.

[austinmarkus]

I can add a bit more color to the issue with the hope that it will help you track it down. I'm still not sure that it isn't an underlying libmicrohttpd issue. The issue seems to be caused by post data overflowing its memory allocation. It only seems to be triggered on on stream close when closing more than one stream in quick succession.

In looking to track down the bug I added a bit of additional debug output to the janus_http_handler function and had it dump the upload_data to the log as soon as it was received. Normally upload_data's size matches the size of upload_data_size and upload_data contains just the posted json. However when it is about to crash extra data is passed along with the actual json exceeding the upload_data_size. When Janus copies the raw upload_data it ignores the extra garbage on the end but this extra data seems to be causing, or is a symptom of, some sort of memory leak.

A broken request looks like this:

Processing HTTP POST request on /janus upload_data= {"plugin":null,"token":"6ODt6sFGbfN91ld1OMgOiixng","body":null,"janus":"create","transaction":"PPHFxS5VjGwC"}�)��*ƶjq��[M�p�<Q�sKD�����o�� ��PY�g�H���[��O{~���*"x������D�}˵���!of�g�����i SG"��д[��ZY�@;��@o3�\�B��hx Ή�@�BGi��&ƹ��Vr�й�o7i��Bfe���^:p�&��j��-�;Tq}�z�u�;�k�E
9vw@�{W�
;ٙC�z��'8�D!
w��.:��
[Fri Feb 16 10:29:24 2018] -- Data we have now (109 bytes)
[Fri Feb 16 10:29:24 2018]`

Whereas a clean request looks like this:

Processing HTTP POST request on /janus upload_data= {"plugin":null,"token":"IBNP5NV6A1U7E1piYx7bCaCeO","body":null,"janus":"create","transaction":"9Tv66Va1yDIK"} [Thu Feb 15 10:23:27 2018] -- Data we have now (109 bytes)

I hope this helps.

[lminiero]

Maybe a buffer overflow somewhere, and the file descriptor the library thinks it's closing is actually random data not corresonding to a socket which is why it fails? Just thinking out loud.

[lminiero]

The data we have now part comes from here:

if(*upload_data_size != 0) {
	msg->payload = g_realloc(msg->payload, msg->len+*upload_data_size+1);
	memcpy(msg->payload+msg->len, upload_data, *upload_data_size);
	msg->len += *upload_data_size;
	memset(msg->payload + msg->len, '\0', 1);
	JANUS_LOG(LOG_DBG, "  -- Data we have now (%zu bytes)\n", msg->len);
	*upload_data_size = 0;	/* Go on */
	ret = MHD_YES;
	goto done;
}

I'm wondering if the if(*upload_data_size != 0) check shouldn't actually be if(*upload_data_size > 0): not sure if the MHD callback can ever pass us a negative size, there, and if that can be a cause of issues.

[lminiero]

@austinmarkus can you let me know if the above commit fixes it for you? In theory, it should just print a warning (we now register our own "panic" handler to pring the message but NOT abort) and then go on. Of course, if the error was masking some other problem it will die anyway, but let's make one step at a time.

[austinmarkus]

Thank you!
I will test this today and will get back in a few hours.

[austinmarkus]

You seem to be on the right track as now I'm getting different errors, but unfortunately it is still crashing and now the backtrace is even less helpful.
https://pastebin.com/iuykga2D
I should note that it now no longer crashes on stream stop but on the next time I try to start the stream back up, so possibly it is a different issue but it is certainly related.

[lminiero]

You probably need to compile the library in debug mode, as otherwise you'll miss the necessary symbols to debug. Compiling Janus with libasan support might also help.

[austinmarkus]

First off my apologies fro not following up on this sooner, but I haven't had much to report that can be of any help. I tried compiling with libasan and there were nothing new in the back traces and while I don't think you can build libmicrohttpd in debug mode (please correct me if I'm wrong) I did add MHD_USE_DEBUG to everywhere that it was initialized in janus_http and that too revealed little of note.

I finally did come across something that seemed to fix or at least mitigate the issue a large extent. Running both the http and admin transports both with threads = 1 seemed to prevent the crash. In order to make this work I switched the clients from http to websockets and only use the http interface for daemon to daemon communication thus minimizing the number of simultaneous calls.

While the bug persists, this workaround is good enough for now so if you want to close the issue feel free.

[lminiero]

That's not really a fix though... it just means single thread instead of a thread per connection or thread pool! 🙂 While I'd like to start using MHD with a single thread, we're not there yet (a lot of refactoring needed for the suspend/resume stuff), so as you pointed out it's not really usable that way. I'll keep this open just a little while longer as a memo, so that I can look into this later on.

[lminiero]

Can you let me know if #1173 fixes it for you? It uses a single thread for HTTP.

[austinmarkus]

Will do. Do I need to do anything from a config perspective or is the threads= line deprecated?

[lminiero]

Yes, threads is now deprecated, so there's nothing you need to do config-wise.

[austinmarkus]

It is definitely an improvement over the multi-threaded code but I was still able to get it to crash using my normal stress test of 4 simultaneous streams to 3 different browsers. Again it crashed with the not so helpful https://pastebin.com/7UXTZznu.

But interestingly right before the crash I got this.
[Mon Mar 12 17:02:35 2018] [(null)] Returning error 454 (JSON error: on line 1: '[' or '{' expected near 'POST') [Mon Mar 12 17:02:35 2018] Got an admin/monitor HTTP nnection: request on keep-alive... [Mon Mar 12 17:02:35 2018] [ERR] [transports/janus_http.c:janus_http_admin_handler:1502] Unsupported method...

I have been logging all of the requests that my server makes to Janus and the JSON that I sent is fine.
{"janus":"add_token","token":"ItsbEcO9wTM1FojUVmpp6CvNW","plugins":["janus.plugin.streaming","janus.plugin.audiobridge"],"transaction":"3hb0D11KenlO","admin_secret":""} so somewhere in between the request being sent and received it was corrupted. The only time I see this corruption is right before a crash.

My current theory is that there is a leak somewhere in the ice thread that corrupts the memory of the http thread. The ice thread it too sometimes crashes (particularly when libasan was compiled in to both Janus and libmicrohttpd), and I only get a crash on the http thread if there are lots of streams running for a long time. As the calls to http are only made at stream startup and destruction it doesn't make sense to me that the time a stream is running would have any impact on the http thread. It is just a guess and I don't have the c programming chops to track it down.

I'm going to run a tshark session and make absolutely certain that corruption isn't happening at the network layer (unlikely as it is on the same physical server) and will report back my results.

Thanks again for all of your help.

[lminiero]

In the HTTP plugin, the keep-alive is typically only originated by the plugin itself (janus.js only sends them for websockets), as a way to have long polls (which never get to the core) act as application level keepalives, so it may be something breaking there. Can you try changing char tr[12]; to char tr[13]; here:

https://github.com/meetecho/janus-gateway/blob/master/transports/janus_http.c#L1319

and let me know if this fixes it for you? It might be a buffer overflow thing when we generate a random string in a buffer that might be too tight.

[austinmarkus]

Will do. It takes me a while to get the crash to happen so it might be a while before I respond.

[lminiero]

Definitely looks like a buffer overflow somewhere, anyway, as the line you get:

Got an admin/monitor HTTP nnection: request on keep-alive...

comes from this line here:

JANUS_LOG(LOG_VERB, "Got an admin/monitor HTTP %s request on %s...\n", method, url);

which means the function thinks method is "nnection:", and url is "keep-alive", which obviously make no sense for the HTTP callback. Something is messing with the memory somewhere, and pointers point to garbage, hence the crash.

[lminiero]

Probably a dumb question, but are you using the latest libmicrohttpd?

[austinmarkus]

Yes, 0.9.59.

[atoppi]

@austinmarkus you mentioned some crashes with libasan-enabled binaries.
Could you reproduce the issue after compiling the sources (both Janus and MHD) with:

CFLAGS="-O0 -g -ggdb -fsanitize=address -fno-omit-frame-pointer"
LDFLAGS="-lasan"
CFLAGS=$CFLAGS LDFLAGS=$LDFLAGS ./configure

If any heap/stack overflow or use-after-free is happening here, libasan should detect it.

[austinmarkus]

Give me a moment and I will re-compile/test. As before it may take a while before I can get a crash.

[austinmarkus]

With the compile flags @atoppi suggested in for both Janus and libmicrohttpd and the small change @lminiero suggested I can no longer maintain a video stream. They start up fine but after roughly 30 seconds they freeze. Nothing is in the level 5 logs and this ">> >> Can't retransmit packet 37094, we don't have it..." is repeated over and over in the > level 6 logs with the packet numbers changing. I'm going to walk back the changes until I can get it working again.

[austinmarkus]

Please disregard my last comment. A server reboot fixed the streaming issue. I am testing now.
It is still happening it just took longer to start.

[austinmarkus]

I'm having difficulty reproducing the crash as I cannot keep streams going for long enough with libasan in, however I did just get one that I think is related. It is the ice thread crashing not httpd but if you look in the log you'll see a:
[(null)] Returning error 450 (Unsupported method text/html,)
in the second leading up to the crash. I'm including some other log data leading up to it just in case that helps. At the time I was stopping the three streams I had going (one of which had stalled).

https://pastebin.com/NWZbtRYM

[atoppi]

Unfortunately the last dump does not add anything useful.
The crash occurred in glib. We use a g_main_loop to intercept incoming events like the ones coming from ICE, custom timeouts etc.
Under Linux, glib dispatches these events with pipe file descriptors. From their doc:

The main event loop manages all the available sources of events for GLib and GTK+ applications. These events can come from any number of different types of sources such as file descriptors (plain files, pipes or sockets) and timeouts.

The raised error means that the icethread is trying to write on a pipe that has been closed, but it's unclear who closed it and why. Moreover, given that we suspect a memory leak, this might also be caused by a pointer corruption, leading to write/read on an invalid memory space in place of the previously allocated file descriptor.

@austinmarkus I noticed you are using both WebSockets and HTTP transports for your clients. I have never tested this scenario too much, maybe trying only with HTTP is worth a try.

[austinmarkus]

The mix of websockets and http are a legacy from when I was forcing a single thread by setting threads=1 in the config. As it was stalling when I had multiple clients all trying to negotiate their streams at the same time I switched it to websockets on the client side but left it http on the server side as that was a more involved re-write. It is easy enough to switch back and I can test later today. I will keep working on trying to replicate the original error with libasan in and will report back as soon as I have anything worth sharing.

[austinmarkus]

I've finally been able to get a decent backtrace of the libmicrohttpd crash. Hopefully this helps https://pastebin.com/9sR4hsxC.

In order to do this I needed to compile libmicrohttpd with sanitize=address and no-omit-frame-pointer but not Janus. When I compiled both with those flags Janus wouldn't crash, it would get into the state where it would normally crash with log statements like this
[Fri Mar 16 13:01:42 2018] Got an admin/monitor HTTP ��S._DPOST request on /admin... [Fri Mar 16 13:01:42 2018] [ERR] [transports/janus_http.c:janus_http_admin_handler:1502] Unsupported method... [Fri Mar 16 13:01:52 2018] [WARN] [janus.transport.http]: Error in GNU libmicrohttpd daemon.c:3092: Close socket failed.
but would keep on running, I'm sure if that means anything.

Let me know if there is anything else I can get to help you track this down, or if you think it is a bug in libmicrohttpd and I should take it up with them.

[atoppi]

The dump you posted is not from libasan, it is a core dump.
Did you instruct the linker to use libasan too?
LDFLAGS="-fsanitize=address" or LDFLAGS="-lasan"
Anyway, this core dump is very specific and clean but unfortunately it does not add anything to our analysis.
The SIGSEGV occurred in g_source_attach(msg->timeout, httpctx) while trying to access to the HTTP message msg. As we already knew, the message gets somehow corrupted, hence the crash.
I'm still not sure if this is our fault or a mhd bug.
Let's hope libasan do its magic next time.

What about printing the entire memoy area around msg? Given you have not changed and recompiled the source base and its dependencies, you could reuse the last core dump and print the memory around msg with the gdb x command x/nfu addr.
Note that you can specify a negative n index to examine memory backwards, f is the display format of the data (try with char to see if there's something readable) and u is simply the the unit (you might want to use byte-size).

[austinmarkus]

I think this is what you're after. It is from a different crash.
https://pastebin.com/ejNXP6wM
Or this one from another.
https://pastebin.com/YHMKWhrh
Unfortunately I don't have the core dump as I was running Janus in gdb and then restarted it losing the core in the process. I will attempt to re-crash it today and get you the results of the x command.

[austinmarkus]

Okay, that crash came with MHD compiled with libasan. The back trace that I get is this.

#0 0x0000000000000000 in ?? ()
No symbol table info available.
#1 0x00000000014397f0 in ?? ()
No symbol table info available.
#2 0x0000000000000000 in ?? ()
No symbol table info available.

I will recompile MHD with libasan and try to get it to crash again.

[atoppi]

There is no need to compile MHD with libasan. To inspect the msg memory area we just need to analyze the Janus code (janus_http.c), so only the -g -ggdb -O0 flags for Janus are truly necessary here.

[lminiero]

@austinmarkus I'd start considering reporting the issue to the MHD developers, just in case we're chasing tails here and the issue lies there instead.

[RSATom]

so only the -g -ggdb -O0 flags for Janus are truly necessary here.

Just a small related question: Am I right there are no any switch in Janus configure to enable debug build? I mean with disabled optimizations.

[lminiero]

You're right, you have to tweak the environment variables or the Makefile.am manually for that.

[atoppi]

@RSATom default CFLAGS for Janus are -g -ggdb -O2, and this should be enough to debug a core dump.
If something is getting optimized by the compiler you can try adding -O0 (replacing -O2) and -fno-omit-frame-pointer.

[RSATom]

Thank you, understood. Just don't like how it jumps between lines on step by step debugging...

[austinmarkus]

Here is what I hope you're after. Full back trace with the area around the msg after it.
https://pastebin.com/kpYsuqE2
Let me know if there is anything else you would like me to relay to you, like stuff from frames other than 1. This is with libasan in MHD, as this crash happened before you told me not to use it.

I will start a bug report with MHD and will reference this thread in a couple of hours.

[austinmarkus]

Here is another, this time without libasan although it looks pretty similar to my untrained eye.
https://pastebin.com/NjMPYfXz

One thing that I think bears mentioning is that I can get similar program instability without using the http interface. I rewrote my app to use websockets (both client and server) and ran the same overnight stress test I did for http where I set 5 steams each running to 5 clients and left them go overnight. When I came back in the next day they were still running but after stopping and restarting the streams the websocket became unresponsive. This is also usually where MHD will segfault. Janus was still running, you just couldn't connect to the socket. To me this points to a issue independent of the transport but again I'm not sure.

[atoppi]

@austinmarkus please check the version of libwebsockets you are using. We recommend a recent version (e.g. 2.4), with the flag -DLWS_MAX_SMP=1 passed to cmake while building. This is to avoid potential deadlocks.
Are you testing a commit after the refcount merging? The unresponsive transport might be also a regression introduced after 0.4.0.

EDIT: you're testing the http-single-thread branch, so you're behind the refcount merging.

[atoppi]

Anyway, if you are still testing a pre-0.4.0 master with a recommended lws version, then this could point to a transport independent issue, arising in long lived connections, just like you said.

[austinmarkus]

I'm on vacation this week. But will try out the change first thing next week. -Austin

…

On April 9, 2018 1:45:28 AM PDT, Alessandro Toppi ***@***.***> wrote: Anyway, if you are still testing a pre-`0.4.0` master with a recommended lws version, then this could point to a transport independent issue, arising in long lived connections, just like you said. -- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: #1154 (comment)

[atoppi]

Ok @austinmarkus .
Meanwhile I want to try replicate your scenario. Can you confirm that the steps described in the original message are still valid, and are exactly the same you are doing in order to replicate the issue?

[austinmarkus]

First off my apologies for not getting back to you sooner, I was out of cell phone range.

First off the libwebsockets I am running is from git and was pretty out of date (commit a663aefebd3ea8397cfa4ac409b9fb8e089fe35f from Feb 14) It was after the 2.4 branch but I will try the 2.4 stable release anyway to see if that makes a difference. I used this cmake line from your install instructions so I should be okay on that front.
cmake -DLWS_MAX_SMP=1 -DCMAKE_INSTALL_PREFIX:PATH=/usr -DCMAKE_C_FLAGS="-fpic"

As for the steps to replicate the crash, I have removed token auth and all interactions with the admin interface and the crashes persist, so that can be ruled out. I should also note that it will often take far longer than 15 minutes for the stability issues to manifest, my new test is to let it run for 12+ hours overnight and then check back in in the morning. But the basic steps are the same.

1. Start multiple streams (h264/Opus fed by rtp from our server). I usually do 5 or 6.
2. Start multiple browsers each viewing all of the streams (with our web-app calling janus.js to do all the negotiations). Again I set up 5 or 6 viewers, 3 computers each running one window of Chrome and another with either Firefox, Edge, or Safari depending on the OS.
3. Let the streams run for a long time (at least an hour, often much more).
4. Stop all of the streams. Sometimes this alone will trigger the crash, if it does not restart the streams and this will usually be the trigger, if not continue starting and stopping until it crashes.

[atoppi]

@austinmarkus thanks for getting back with your scenario details.
Unfortunately we're quite busy in these weeks and we do not plan to handle this issue in the next days.
We'll eventually return tho this as soon as we have finished with our current priorities.
Meantime trying to ask to MHD devs might help spotting some light on this case, they could come up with a debugging approach we've not thought about.
Thanks again for your detailed reports.

[atoppi]

Hi @austinmarkus, we have hopefully fixed a race condition on the msg->timeout handling in http-single-thread branch. That seems to be the most frequent crash occurring in your experiments.
Could you test your scenario to see if this fix helps?

[lminiero]

Kudos to @mtdxc for debugging the issue. Anyway, I thought your recent tests were on master? So all the data you've collected so far was for the single-thread branch? I would have loved to see the way we use MHD fixed too...

[austinmarkus]

All of my recent tests were on the single-thread branch. I will update and test later today.

[lminiero]

@austinmarkus got it: then you were not really using even the same codebase as master, since we recently merged the refcount stuff and we hadn't aligned the single-thread branch yet. I aligned them today, but I didn't do much testing to assess its stability (that is, apart from the bug you were experiencing).

[austinmarkus]

I think I may have a lead although to be honest I'm not sure of anything at this point. To be totally sure that the issue wasn't with MHD I built Janus with --disable-rest and set libjanus_http.so in the disable transports section of the config and used websockets as my transport mechanisim. I ran my standard test and while it no longer segfaults it does deadlock and my thinking is that the deadlock was causing the MHD crash and it is just manifesting itself differently with websockets.

Here is a trace of the wss thread in the deadlocked state.
https://pastebin.com/iDPkpEex

As you can see the deadlock is in the audiobridge, I am going to try disabling my use of it of my code and see if I can duplicate the deadlock in the main streaming plugin. I apologize for not mentioning the audiobridge in my earlier comments I had forgotten I was even calling it.

Edit: This test was run back on trunk

[lminiero]

Notice that if you're using the streaming plugin we fixed something in there yesterday, and I fixed something in the AudioBridge plugin too, so make sure you get the latest changes before trying again.

[atoppi]

In case this is still a problem after the very recent commit @lminiero suggested, you may want to enable the locking debug in the Janus Admin.

[austinmarkus]

Over the weekend I ran a test on the previous trunk (before the changes @lminiero mentioned were in) but without any calls to the audio bridge and for the first time I experienced no crashes or deadlocks. Today I am going to run the same test but with the updated code and using the HTTP transport. If that too yields success; I will go back to using audiobridge, will enable locking debug and will try to get to the bottom of things once and for all. Thank you all for bearing with me on this, I feel like we're getting closer.

[austinmarkus]

I have been able to isolate the crash to a specific series of actions, and as such have been able to work around it.

1. Start some audiobridges.
2. Add RTP forwarders to said bridges.
3. Let them run each with a number of web clients for a long time (1-24 hours)
   -Next step is where the crash occurs-
4. Destroy the audiobridges without first stopping the the RTP forwarder.

I have tested on trunk using both websockets and using MHD with 100 threads and both have survived crash and deadlock free by simply issuing a stop_rtp_forward sleeping for a few seconds and then destroying the audiobridge.

Please let me know if you would like me to do any additional work to help track the issue down, or if you would like me to just close it, as it is something attributable to user error.

Thanks again for all of your help and patience in figuring this out.

Edit: I'm going to close my MHD bug report, as it doens't appear to be a MHD issue, unless there is any objection.

[atoppi]

You seem on the right way, go ahead closing the MHD issue!

[lminiero]

Not sure about the exact cause, but RTP forwarders use manually created sockets: it might be that some of them are incorrectly closed twice, and the second time they close a socket identifier that is now associated with a different connection (like an HTTP connection handled by MHD). This might explain the "close socket failed" error, as the plugin is closing the socket and MHD failes to close it later on. Just guessing but I'm wondering if that may be it.

[austinmarkus]

I am closing this issue as I am no longer able to reproduce it using http or websockets either closing the rtp forwarder first or not. I suspect it was a commit that you made about two weeks ago that fixed the issue and although I'm not sure of the exact fix, it does seem fixed.

Thank you for all of your help.

[lminiero]

Thanks for your patience, and especially for collecting so many info!