Connection reset by peer #76
Comments
|
@phillipp thanks for posting this! Do you have any other sample logs like the one at the bottom of this issue? Having additional info may help a lot! |
|
Sure, here we go: This one has two frontend connections, just in case this is relevant I was noticing just now that the after_read_cb gives the -104 sometimes on the backend and sometimes on the frontend. For our log since this morning thats 832 -104 on the frontend and 154 on the backend (I would expect that the frontend has way more errors). Do you need more info? In this case a traffic dump is a bit hard, because it is a production system sending possibly sensitive data... |
|
Thank you @phillipp. I'll look into this. |
|
@phillipp do you happen to see anything like this in nginx logs? Have you tried enabling debug-level logging on nginx? (http://nginx.org/en/docs/debugging_log.html) |
|
I havent seen any PROXY related error messages in the error log. But we actually applied a patch to fix an nginx problem with the proxyline support, but I'll have to look that up. nginx debug log is now enabled. I'll post more information on backend connection resets when we have it in both logs. Here we have another one (the customer complained about this specified request, it's on the frontend side): |
|
@phillipp yeah, frontend-side is definitely unrelated to proxyline. Do you think it may be possible to obtain |
|
Do you need the strace output of bud or nginx? I have a error log of the nginx-side of a connection reset on the backend now. I fear that I have to heavily redact the log, but everything before the pasted lines seems to be internal processing anyways: |
|
@phillipp sorry, but so far nothing rings the bell... Perhaps, it may be a good idea to take a look at the tcpdumps yourself, to see what kind of data is exchanged by the sides right before this error. Maybe there is some corrupted memory, or something unrelated to bud at all! I could only say that this error is usually not a bud's fault, and means that the other side killed the connection. Very sorry to be unable to provide you any further suggestions on this. |
|
I am not as good as you two are, but it seems quite similar to my problem: #63 |
|
I go out on a limb here but memory corruption seems unlikely because this of course is server hardware wiith ECC scrubbing and occurs on multiple hardware machines. I now got lucky and intercepted a connection between bud and nginx with connection reset. nginx debug log is as follows: I can't export the wireshark trace of it for privacy reasons, but summary looks like this:
[edit] nginx error log shows no errors for that request and/or time frame. I fear I cant show the bud log because stdout isn't timestamped and our syslog for bud debug is heavily rate-limited. I'm not able to correlate client ids or process ids. I often wondered why you decided not to timestamp the stdout messages. Any good reason? |
|
@phillipp is there anything odd in wireshark? Invalid HTTP request maybe? |
|
@phillipp stupid question, but could you be running out of memory on this box? |
|
@phillipp if you have access to the HTTP request data - may I ask you to post a proxystring from it (you may redact address in it, but please make the size the same). |
|
@phillipp do you see anything like |
|
It is just pretty odd that it doesn't print It reads the data from socket, tries to parse PROXY line, and then goes straight into Btw, what nginx version are you on? |
|
Nope, wireshark has just the HTTP request and that direct ACK and then ACK, RST. nginx error logs shows exactly nothing. The server is not out of memory. And there is no tcp port reuse warning in wireshark either. The http request does not have any PROXYLINE, it's just a plain http request. That may the problem, we nginx doesn't complain because we patched that error message out, so we would see that error message but don't because we removed it (because otherwise the log would be flooded from all the errors. because bud only send the proxyline on the first request all other requests showed that error). Would that be possible, that bud didn't injext the proxyline? |
|
nginx is openresty/1.7.10.1 |
|
Yeah, right, we changed the Then the error is only logged if the header is missing and no IP address is set from previous requests. |
|
Ugh, that explains why the connection is closed. That returns NULL and NULL leads to a closed connection 😱 I'll fix that and see if that resolved the problem. |
|
With the patched/fixed nginx we still see the problem, I'll try to get more debug info why that's the case. |
|
@phillipp may I still ask you to post a PROXYLINE from that failed request? |
|
I can't, because there is none in the whole TCP connection. |
|
@phillipp oh sorry! Looks like I forgot the context when replying to this issue (switching between several projects atm). May I ask you to publish the HEX data of first TCP packet's body? |
|
Looks like our nginx problem solved the main issue, but there is still an open issue. We see regular requests from bud that are mangled in a strange way, like this: So you can see there is some stuff injected into the Cookie header. We see that around 2.000 times per day and from random clients, even from monitoring requests. The nginx server then closed the connection, which leads to the connection reset by perr backend message. We previously ignored all these errors but we see them again after we fixed our nginx patch. A possible next step here would be to compile with address sanitizer (may be a memory corruption) and dump the original request in bud so we can check the incoming buffer against what's going out. Any other ideas? |
|
@phillipp this sounds like a good plan. I hope ASAN will give us more information. Thanks for the follow-up! |
|
Starting bud with ASAN makes it hang. strace shows the following: Compiled with |
|
@phillipp does debug log print anything at all? |
|
Nope, nothing. CPU is stuck @ ~ 100%. |
|
@phillipp very interesting... May I ask you to try |
|
Very strange. I tried bud with ASAN on two machines and on both it generates a lot of bud processes and basically kills the system by forking. What works is starting a new docker container (based on ubuntu:trusty tag), compiling and running. Perf on the forking version shows 26k cycles and 0 events. Does that help? |
|
And what exactly is the difference? |
|
It is built using |
|
Alright, got that running now, with ASAN and some more debug output. I added a log of the buffer after SSL_read at client.c ~ L630 so I can see the buffer after it read from the connection. I noticed that there are requests that don't get a PROXYLINE and now I can see the content in bud: Notice that there are two ^M (carriage returns). Possible the x-forward.c doesn't handle injection of the header correctly in that case? There are plenty of clients that send that. I can see if I can find out what is causing the garbled requests, because it looks like some other parts of the buffer are written to the backend as well, but I haven't figured out how. |
|
Oh gosh! Yeah, this is quite unexpected. I guess I will just add support for this, thank you for figuring it out @phillipp ! |
|
@phillipp thinking more about, I don't think that much servers accept two CRs as CRLF. Just tried it on google, and node.js, and it doesn't seem to be working at all. I will definitely make x-forward thing less strict, by just looking at following sequence |
|
@phillipp you may use this snippet to log data that is being written to backend: diff --git a/src/client.c b/src/client.c
index e6da79a..a8a6c49 100644
--- a/src/client.c
+++ b/src/client.c
@@ -727,8 +727,11 @@ bud_client_error_t bud_client_send(bud_client_t* client,
DBG(side, "uv_write(%ld) iovcnt: %ld", side->write_size, count);
side->write_req.data = client;
- for (i = 0; i < count; i++)
+ for (i = 0; i < count; i++) {
+ if (side == &client->backend)
+ fprintf(stderr, "\"%.*s\"\n", size[i], out[i]);
buf[i] = uv_buf_init(out[i], size[i]);
+ }
/* Try writing without queueing first */
r = uv_try_write((uv_stream_t*) &side->tcp, buf, count); |
|
Actually even |
|
Ok, pushed out the fix for x-forwarded-for. Unfortunately, it won't help your case, though. |
|
I have found a fix for the garbled requests but I couldn't figure out WHY the fix works exactly. I figured out now that the bud_client_send sends more data than the client_read: (dbg) [2331] client 0xd92230 on frontend SSL_read() => 518 Which is okay, because the PROXYLINE should be prepended. SHOULD is important, because nginx cleary shows that there is no PROXYLINE. So I added debug output to check out how long that PROXYLINE is, and the size matches exactly the difference between the SSL_read() and uv_write. That is to be expected. But then when I see the request nginx is receiving there are these garbled headers at the end and the size of them is exactly the number of bytes that should be the size of the PROXYLINE. So I figured that maybe the proxyline is written to the ringbuffer but the pointer is somehow advanced in a wrong way or something, couldn't figure that out yet. But it is clear from inspecting the buffer SSL_read() reads into that the bytes from the garbled requests are leftovers from previous requests. What I did is I replaced the Maybe you can figure out what could be the problem? |
|
BTW: looks like that only happens when the SSL handshake fires an SNI request. |
|
Very interesting! I will review the ringbuffer code, thanks for the tip and thorough investigation! |
|
@phillipp while I look into it - may I ask you to give a try to this patch? diff --git a/deps/ringbuffer/ringbuffer.c b/deps/ringbuffer/ringbuffer.c
index 0f3341e..fac2c28 100644
--- a/deps/ringbuffer/ringbuffer.c
+++ b/deps/ringbuffer/ringbuffer.c
@@ -287,6 +287,8 @@ char* ringbuffer_write_ptr(ringbuffer* rb, size_t* length) {
int ringbuffer_write_append(ringbuffer* rb, size_t length) {
rb->write_head->write_pos += length;
rb->length += length;
+ if (rb->write_head->write_pos > RING_BUFFER_LEN)
+ abort();
assert(rb->write_head->write_pos <= RING_BUFFER_LEN);
/* Allocate new buffer if write head is full, |
|
Gosh, disregard this patch. The fix is: diff --git a/deps/ringbuffer/ringbuffer.c b/deps/ringbuffer/ringbuffer.c
index 0f3341e..c609f71 100644
--- a/deps/ringbuffer/ringbuffer.c
+++ b/deps/ringbuffer/ringbuffer.c
@@ -315,6 +315,7 @@ int ringbuffer_insert(ringbuffer* rb,
bufent* start;
size_t left;
size_t offset;
+ size_t to_alloc;
int r;
assert(length < RING_BUFFER_LEN);
@@ -334,9 +335,18 @@ int ringbuffer_insert(ringbuffer* rb,
b = rb->write_head;
/* Ensure that we have enough space for shift */
- r = ringbuffer_write_append(rb, length);
- if (r != 0)
- return r;
+ to_alloc = length;
+ while (to_alloc != 0) {
+ size_t avail;
+
+ avail = to_alloc;
+ ringbuffer_write_ptr(rb, &avail);
+ r = ringbuffer_write_append(rb, avail);
+ if (r != 0)
+ return r;
+
+ to_alloc -= avail;
+ }
next = rb->write_head;
while (left > 0) {Please let me know if it works for you. |
|
No, I fear that doesn't fix the problem. Still the same symptoms, like the ring buffers current read position is off by the size of the proxyline. |
|
If that helps: the code path is that the |
|
Oh, never mind. that's not the case. |
|
@phillipp thanks, looking further |
|
@phillipp are you using sni-based backend selection? |
|
@phillipp what about this patch? diff --git a/deps/ringbuffer/ringbuffer.c b/deps/ringbuffer/ringbuffer.c
index 0f3341e..862a8ab 100644
--- a/deps/ringbuffer/ringbuffer.c
+++ b/deps/ringbuffer/ringbuffer.c
@@ -315,6 +315,7 @@ int ringbuffer_insert(ringbuffer* rb,
bufent* start;
size_t left;
size_t offset;
+ size_t to_alloc;
int r;
assert(length < RING_BUFFER_LEN);
@@ -334,9 +335,18 @@ int ringbuffer_insert(ringbuffer* rb,
b = rb->write_head;
/* Ensure that we have enough space for shift */
- r = ringbuffer_write_append(rb, length);
- if (r != 0)
- return r;
+ to_alloc = length;
+ while (to_alloc != 0) {
+ size_t avail;
+
+ avail = to_alloc;
+ ringbuffer_write_ptr(rb, &avail);
+ r = ringbuffer_write_append(rb, avail);
+ if (r != 0)
+ return r;
+
+ to_alloc -= avail;
+ }
next = rb->write_head;
while (left > 0) {
@@ -373,7 +383,7 @@ int ringbuffer_insert(ringbuffer* rb,
delta = off + length - RING_BUFFER_LEN;
memcpy(start->data + off, data, length - delta);
- memcpy(next->data, data + length - delta, delta);
+ memcpy(start->next->data, data + length - delta, delta);
} else {
memcpy(start->data + off, data, length);
} |
|
I have a clue about that's going on. The ringbuffer is accessed concurrently: I added some log statements in the client.c and this is my output for a failed request: So:
That would explain why the workaround (sending the ring buffer) works, because the buffer is okay, just SSL_read overwrites the PROXYLINE data because the write pouinter is stale. Do you see any easy fix for that or is sending the data just fine? |
|
Aaargh. You're so right about it, I'll create a fix in a bit. |
|
@phillipp I have pushed both fixes to master, may I ask you to give them a try before I will release? |
|
Great, could not reproduce the problem with your master :-) |
|
Ok, published as 1.3.5 . Thank you so much! You nailed most of the problem! |
|
I mean, all of it :) |
|
What's your twitter handle? |
|
Great, thanks for the fast reponse and great software! And I thought I was going crazy because nobody else reported the problem. My twitter handle is: https://twitter.com/phillipp |
|
Thank you! |
Hi,
we have bud in production for quite some time now and we're pretty happy with it (still waiting for a core dump on #74).
There is one customer who complains about regular "Connection reset by peer" errors. We were unable to reproduce that with our monitoring, but our monitoring is not a demanding as a browser.
I'm pretty clueless how we could best debug this. There are quite some -104 errors in the logs:
When I see that correctly the client and/or bud closes or drops the connection and then bud tries to communicate on that connection, gets the -104 error and forcefully closes the client and backend connection.
I checked with nginx (backend):
I'm pretty baffled because on plain HTTP we don't see any connection resets by nginx and I can't find any clues in the nginx logs. Dropped connections by iptables or conntrack etc is unlikely because we monitor the relevant stats. Timing from the logs (everything from backend connect and frontend new to the force close happens in the same second) suggests that no timeouts are involved.
Sample los:
Any ideas how to debug this further?
The text was updated successfully, but these errors were encountered: