WARN Two requests without a Response

Elastic Stack Beats
1

Getting the following message from the packetbeat log repeatedly (about every second or so):

"WARN Two requests without a Response. Dropping old request"

Just looking for a little clarification as to what this means. Is it on a certain type of traffic/port? What triggers this warning?

Thanks!
-James

2

this log is generated by some protocol analyzer for correlating requests to responses. But can not tell the protocol type from this message. Which protocols have you configured? What's your packetbeat config saying?

3

This is a web server that connects to a mongo db. I disabled mongo in the packetbeat config, and these logs went away, so it must have been mongo traffic generating this warning. This server's connection to the mongo db seems to be solid though, so not sure why packetbeat is having a hard time with it. Any suggestions? Thanks!

4

Interesting. You can get debug output on mongodb protocol support by starting packetbeat with -d 'mongodb'. Any errors from packetbeat in logs?

5

Here's a snippet from the log with debug turned on for mongodb. Most of this looks like normal stuff, except for the WARN message. Also not sure about the line that says "Prepare to read 0 document from reply":

WARN Two requests without a Response. Dropping old request
DBG  Parse method triggered
DBG  opCode = OP_REPLY
DBG  Prepare to read 1 document from reply
DBG  Parse 993 bytes document from remaining 993 bytes
DBG  MongoDB message complete
DBG  MongoDB response message
DBG  Mongodb transaction completed: {}
DBG  Parse method triggered
DBG  opCode = OP_QUERY
DBG  Parse 176 bytes document from remaining 176 bytes
DBG  MongoDB message complete
DBG  MongoDB request message
DBG  Initialize new transaction from request
DBG  Parse method triggered
DBG  MongoDB wait for more data before parsing message
DBG  Parse method triggered
DBG  opCode = OP_QUERY
DBG  Parse 177 bytes document from remaining 177 bytes
DBG  MongoDB message complete
DBG  MongoDB request message
DBG  Initialize new transaction from request
DBG  Parse method triggered
DBG  opCode = OP_REPLY
DBG  Prepare to read 0 document from reply
DBG  MongoDB message complete
DBG  MongoDB response message
DBG  Mongodb transaction completed: {}
DBG  Parse method triggered
DBG  opCode = OP_QUERY
DBG  Parse 177 bytes document from remaining 177 bytes
DBG  MongoDB message complete
DBG  MongoDB request message
DBG  Initialize new transaction from request
DBG  Parse method triggered
DBG  opCode = OP_REPLY
DBG  Prepare to read 0 document from reply
DBG  MongoDB message complete
DBG  MongoDB response message
DBG  Mongodb transaction completed: {}
DBG  Parse method triggered
DBG  opCode = OP_QUERY
DBG  Parse 224 bytes document from remaining 224 bytes
DBG  MongoDB message complete
DBG  MongoDB request message
WARN Two requests without a Response. Dropping old request
6

How many mongodb connections are you monitoring? From log it seems like multiple connections are used. makes it difficult to follow or tell which OP_QUERY messages are send on same TCP connection.

Not knowing mongodb in detail yet, one of the problems producing this warning might be either a client piping requests (sending multiple requests, before seeing first response). For example in async usage? Or a message type not requiring a response not being handled correctly by correlator (but OP_QUERY requires a response).

Checking mongodb wire protocol and mongodb code correlations do not take the query its requestID into account when looking up the connection. The wire protocol seems to support out of order responses + piping is always possible.
Additional some request types (e.g. OP_UPDATE) do not have any kind of response. For example if your connection has one UPDATE followed by a QUERY you will get this message, but can be ignored.

Still would be helpful if we can isolate the connection errors happen on for verifying my assumptions. E.g. get a pcap with tcpdump. packetbeat provides a debug mode for reading from pcap (-N path/to/trace.pcap). Having a pcap and using tshark/wireshark connections can be isolated.

Please follow this issue on github

7

So I ran a capture and checked it out in wireshark. Most stuff looks fairly normal, however, I keep seeing requests of type "Unknown":

Pasted image1359×428 296 KB

Not quite sure what to make of these. Is that something wireshark can't interpret, or Mongo itself? Not sure. Anyway, I wonder if this is what is triggering the "requests without a Response" message in the packetbeat log.

8

Hmmm.... this is weird. Maybe a bug in wireshark and packet contains data part of package being sent before? Frame number 16422 is a data response? What's the message length of frame 16422 vs. packet size (TCP payload size)?

is 10.65.53.146 your client talking to the server? Does the trace really contain just one TCP stream?