[SERVER-47519] Connection closures are not logged when server shuts down Created: 14/Apr/20 Updated: 06/Dec/22 Resolved: 21/Apr/20 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Logging, Networking |
| Affects Version/s: | 4.3.6 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Minor - P4 |
| Reporter: | Oleg Pudeyev (Inactive) | Assignee: | Backlog - Service Architecture |
| Resolution: | Won't Fix | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||
| Assigned Teams: |
Service Arch
|
||||
| Operating System: | ALL | ||||
| Steps To Reproduce: |
|
||||
| Participants: | |||||
| Description |
|
When a client connects to the server and subsequently disconnects, the mongod log includes line items showing the connection being established and closed:
When a client connects to the server and the server shuts down (I used shutdown:1 command), it appears that the server is not creating a corresponding log entry for the connections being closed. For example, in https://gist.github.com/p-mongo/a6976d218e2eb1140b1bac0f95415306 there is no log entry for closing conn136. I expected the server to log all connection closures, whether those are initiated by the client or the server. |
| Comments |
| Comment by Oleg Pudeyev (Inactive) [ 24/Apr/20 ] |
|
Thank you for the explanation. |
| Comment by Mira Carey [ 24/Apr/20 ] |
|
The problem is that there is no single coherent view point observing the difference between set 1 and set 2. After we kill all operations, all the various client threads will, at some point, discover they've been interrupted and begin unwinding their stacks. These stacks are unwound by separate threads that perform no synchronizing operations on close. So the shutting down thread, which is racing towards quickExit, has no idea how many sockets have already been closed and/or have logged. And the threads themselves have no idea if they're going to manage to close their sockets, or if the OS will do it for them. To provide what you're asking for would involve either: 1. handling all socket closures from the shutdown thread Unfortunately it's not an easy change. It would involve either a slower shutdown path, or substantially changing how we do socket closure on shutdown. Given competing priorities, we're not going to work on this at this time |
| Comment by Oleg Pudeyev (Inactive) [ 22/Apr/20 ] |
|
What I am saying is IF mongod behaves as follows:
AND there is a point where the server knows all members of set 2 (assuming it already knows all members of set 1 and prints log messages for those connections) THEN the server could, for each connection in set 2, print a message like "abandoning connection X". This message doesn't have to match the closure of the connection timing-wise, and these messages don't need to be produced in the order of connections being closed/cleaned up by the OS. These messages are just an indicator that the server will no longer read/write on connections, and should still be helpful as approximate lifetime indicators for users trying to debug their connection issues. |
| Comment by Mira Carey [ 22/Apr/20 ] |
|
Specifically during shutdown, depending on ordering, sometimes we're not manually closing these sockets. The process itself is going away and the OS is closing them for us after process death. There's not an opportunity to print a log message for connections closed in that way |
| Comment by Oleg Pudeyev (Inactive) [ 21/Apr/20 ] |
|
How about logging that a connection has been given up on and will not be further used? |
| Comment by Mira Carey [ 21/Apr/20 ] |
|
This isn't possible, many of those connections aren't being close by the mongo process, but instead by the operating systems |