[JAVA-4210] MongoDb returns message length larger than the max message length Created: 27/Jun/21 Updated: 15/Mar/23 Resolved: 15/Sep/21 |
|
| Status: | Closed |
| Project: | Java Driver |
| Component/s: | None |
| Affects Version/s: | None |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | 运军 蒋 | Assignee: | Valentin Kavalenka |
| Resolution: | Won't Do | Votes: | 0 |
| Labels: | external-user | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||||||||||
| Case: | (copied to CRM) | ||||||||||||||||||||||||||||
| Documentation Changes: | Not Needed | ||||||||||||||||||||||||||||
| Description |
|
Hi guys, We are facing an issue that happened several times a day. Our java driver version is 4.0.5 and Mongo DB version is 4.0.9. We have 2 routers and several nodes. And we are using reactive stream. This issue only happens in our production env. It usually first occurred while MongodbHealthIndicator checking the connections with mongo db. Please see the stacktrace as below:
*The responseTo is always smaller than the request id * The full stack trace is
I investigated the related source code, I guess that when the first error happened. It seems that mongo has replied an unknown message to the driver. When the driver decode the message follow the wire protocol, it found that the message length is too big(reading the first 16 bytes from the stream) and throw an exception then ignored the rest bytes. The following requests will keep doing the same until meeting the first correct reply message but the responseTo in the reply message will be smaller than the current request id. I can't reproduce this on my laptop. I'm wondering why the driver needs to check the message size or the responseTo is matching the request id. Is there a concern regarding this? Why not check if the reply message is matching the wire protocol? |
| Comments |
| Comment by 运军 蒋 [ 22/Sep/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi, Valentin Kavalenka, Thanks for your effort on this. Just want you to know that I have done another two experiment to see how our service will behave.
I also captured the packages to find out the corruptions, but I failed to find any corrupted packages in Wireshark. Wireshark can identify all the packages send from Mongodb to our service are valid mongo wire protocol ones. Both the NettyStream and AsynchronousChannelStream are back by JDK NIO. I don't know if NeuVector is just a trigger that caused this error. Now we do have a workaround if the NeuVector team identifies that this is not an issue from their side. I understand nothing that MongoDB driver could do to help this. Just want you to know about this in case other Mongo users meet the same issue. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 15/Sep/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Enabling TLS in the MongoDB driver will allow to detect corruption of the data coming from a TCP socket earlier. This means you will start seeing errors different from those you are currently observing, and will probably not have a situation when the driver sometimes attempts to use a TCP connection after failing to read from it (it is still the case in 4.0.5, but is fixed in 4.4.0). However, this will not hide the errors caused by the data corruption from your application, which means it is not a workaround. I am closing this report as "declined" because the evidence suggests the driver is not the culprit. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 15/Sep/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
We are seeking help from NeuVector team. But I'm still thinking is there a workaround as we can't rely on NeuVector to fix this in a short period of time? Can we enable TLS to avoid message corruption? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 02/Sep/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for conducting the experiment one more time. From the data gathered I can see, that you are not using TLS, and the junk header appears to be actually coming from a TCP stream as opposed to be a result of the driver reading from an incorrect position in a TCP stream. Here are highlights from the combined history (the history of TCP stream operations combined with the history of higher-level operations) captured in first_error.log
In this history we can see that the first captured message header was read after reading 1190278 bytes from the TCP stream. It specifies message length of 15613 bytes, which includes the length of the header itself. This means that the next header is expected to be read after reading 1190278 + 15613 = 1205891 bytes, and this matches what we see for the second captured DECODE_MESSAGE_HEADER event. The second header specifies message length of 15758 bytes, hence the next (third) header must be read after reading 1205891 + 15758 = 1221649 bytes, which is exactly what we see in the history. I.e., the driver did read the third captured header from the right position in the TCP stream, but it contains junk in all four of its 4-byte fields:
Taking the above analysis and your observation about Neuvector into account, I do not see a reason to think that the problem is in the driver. The problem is likely caused by something, e.g., Neuvector, which I am not familiar with, that corrupts inbound TCP data. I will merge the fix of a bug when the driver does not close a TCP connection is some cases when failing to read from it, that was discovered earlier. Other than this, it does not seem like there is something else to do in the driver with regard to the problem. You may want to contact the Neuvector's support. Additionally, enabling TLS in the Java driver should detect situations when inbound TCP data is corrupted, i.e., it may be used to further confirm the hypothesis. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 31/Aug/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Here is the first error log using the updated driver first_error.log | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 27/Aug/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you for the attached log messages. They all belong to different TCP connections. error_2.log Of all the messages, only error_0.log For error_0.log As a result of analyzing the data you provided, I did the following:
Here is how we may proceed further:
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 20/Aug/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Valentin, we have applied this driver to our production env and collect 3 types of error logs. After several these logs, the debugger logs the 3rd type of log. Hopes these logs could help. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 09/Aug/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
We'll use this version to do the debugging and upload the logs. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 06/Aug/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you for your willingness to help us by collecting additional data. mongodb-driver-core-4.0.5-JAVA-4210.jar When you enable the debugger as specified here, you can confirm that the debugger is actually active by observing a single message "Reporting mode changed from OFF to LOG" logged by the org.mongodb.driver.connection.debugger logger. We are interested in messages and stack traces logged by the org.mongodb.driver.connection.debugger logger, but if you are be able to provide complete driver logs, MongoDB server logs corresponding to the time intervals when errors happen, that would be even more valuable. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 02/Aug/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Yeah, we still use this version. We'd like to do the debugging if you can provide a custom driver build. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 29/Jul/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I do not have a working hypothesis of what specific bug may cause the errors, you may find the details in the comment above. Having more detailed data may help with developing a hypothesis, so I wrote debugging code that gathers more data while likely having negligible overhead. Would you be willing to try using a custom driver build in the environment where the reported errors are reproducible, with the debugging code enabled to help us gather more data? The debugging code is enabled by setting the level of the org.mongodb.driver.connection.debugger logger to DEBUG. If any of the reported errors happen with the debugger enabled, the debugger logs an ERROR-level message that contains both the additional data and the stack trace. Enabling the debugging code should not change the driver's behavior, and the exceptions you reported are still expected to be thrown. Please note again that it is not guaranteed that the data gathered by the debugger will necessarily help us to come up with a plausible hypothesis, and that the build we will provide would not be a released version of the Java driver. If you are willing to participate, could you please confirm that you are still using org.mongodb:mongodb-driver-reactivestreams:4.0.5? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 29/Jul/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
@Valentin Kavalenka Any good news on this? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 14/Jul/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Analysis of the data at handErrorsThe errors
from this bug report and the errors
error from
Reason 3 is unlikely as all drivers would have experienced the bug. Reason 2 is even less likely because even more people would have experienced the bug, which means it would have been likely fixed. Reason 1 is the most likely reason so far. Other observationsSince the reporter of the current bug report uses NettyStream, and the reporter of
The fact that both this bug report and Failing to come up with a working hypothesisSo far I expressed that I think reason 1 is the most likely reason of reading junk and that it is likely caused by a bug in InternalStreamConnection or above and is related to asynchronous API. Not closing a Stream after failing to do I/OI checked the code to make sure we always close the stream if we fail to asynchronously read from or write to it--we do. This is easy to check and I rely on the result. If we were to continue to use a stream after failing to read from it, then this would be what causes us to read MsgHeader bytes from an incorrect position in the TCP stream (reason 1). However, now I can remove this possibility from the equation. Reading concurrently from the same StreamAnother way to read MsgHeader bytes from an incorrect position in the TCP stream is to have more than one outstanding read operation on the same Stream. Stream.readAsync is a stateful operation, and multiple outstanding read operations may (and most likely will) corrupt each other's state unless the implementation does preventive checks and rejects to initiate multiple outstanding operations. Neither NettyStream nor AsynchronousChannelStream has such checks (neither in r4.0.5 nor in the current master), which makes multiple outstanding read operations possible. However, AsynchronousChannelStream further delegates the operation to either AsynchronousSocketChannel (JDK) or AsynchronousTlsChannel (tls-channel). AsynchronousSocketChannel.read throws ReadPendingException if a read operation is already in progress on the channel. So if the driver indeed sometimes does concurrent reads on the same Stream, users that use AsynchronousSocketChannel should sometimes observe ReadPendingException, yet it has never been reported. Also, since AsynchronousTlsChannel is used in However much I would like this hypothesis to be plausible, it does not fit the data we have. Introducing a mechanism to gather more dataIt is difficult to gather useful data when there is no hypothesis one would like to check. As a result, the additional data we gather may help getting new ideas and coming up with a plausible hypothesis that we then may have to check by gathering more data, now with the hypothesis in mind. I.e., this may result in a multi-step investigation process, and does not guarantee a successful outcome. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 29/Jun/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I copy the log from our Kibana.
The request id not matching error log is:
The minimumReadableBytes error log is as below:
These errors throw every day by the MongoReactiveHealthIndicator. Since we haven't had much production traffic, rarely customers will meet the 500 error on our website or IOS app. Our pod will restart after detecting this error consecutively three times. Hope these logs can help. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by 运军 蒋 [ 29/Jun/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I found another error related to this:
I guess that when the max message length error happened, this connection will be polluted. If no more traffic on this polluted connection, this error will be thrown out when the "message length"(first 4 bytes) is lukily less than the max message length. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Valentin Kavalenka [ 29/Jun/21 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for reporting this issue, gloojiang86@gmail.com. We will investigate the problem and come back to you with the findings. Since the problem happens only in production, and you cannot reproduce it in other environments, I am guessing it is not possible to provide client logs with TRACE level. Could you please attach relevant client logs from the environment where the error is reproducible? |