[SERVER-5000] Connection count is not in sync with the connection thread name Created: 17/Feb/12  Updated: 11/Jul/16  Resolved: 13/Jun/12

Status: Closed
Project: Core Server
Component/s: Networking
Affects Version/s: 2.0.2, 2.1.0
Fix Version/s: 2.1.2

Type: Bug Priority: Minor - P4
Reporter: Ben Becker Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu Linux x64, MacOS 10.7.3; likely all posix systems


Issue Links:
Depends
Operating System: ALL
Participants:

 Description   

When mongod accepts a new connection, it prints out a counter, spawns a thread, and then the new thread prints a similar counter. Because spawning a thread is an asynchronous operation, there's no guarantee the new thread will start in the time it takes to accept new connections and spawn another thread.

So essentially

connection accepted from 1.2.3.4:5678 #123

is saying 1.2.3.4:5678 established the 123rd connection.

[conn120] end connection 1.2.3.4:5678

is saying 1.2.3.4:5678 was being handled by the 120th thread to execute.

It's useful for users to know when a connection was accepted, when it did something worth logging, and when the connection ended. I would propose moving the initial 'connection accepted' log message to the connection thread (after the call to setThreadName()) to ensure both counters are in sync.



 Comments   
Comment by T. Dampier [ 14/Jun/12 ]

Nice. Simpler code AND easier-to-follow logs – this will be super helpful. Thanks, Eliot!!

TD

Comment by auto [ 13/Jun/12 ]

Author:

{u'date': u'2012-06-13T10:13:15-07:00', u'email': u'eliot@10gen.com', u'name': u'Eliot Horowitz'}

Message: SERVER-5000 only have a 1 connection id counter and pass
also allows to make setThreadName much simpler
Branch: master
https://github.com/mongodb/mongo/commit/002f57193d41f0b8499245958653aa599699b93d

Comment by Ben Becker [ 17/Feb/12 ]

The proposed fix would produce output like this:

Fri Feb 17 11:02:11 [conn1] connection accepted from 127.0.0.1:63282 (1 connection now open)
Fri Feb 17 11:02:12 [conn2] connection accepted from 127.0.0.1:63284 (2 connections now open)
Fri Feb 17 11:02:17 [conn1] end connection 127.0.0.1:63282 (1 connection now open)
Fri Feb 17 11:02:21 [conn2] end connection 127.0.0.1:63284 (0 connections now open)

with -vvv, there is a similar connection log message in initAndListen() for any future debugging of the accept/spawn/process logic:

Fri Feb 17 11:22:04 [initandlisten] connection accepted from 127.0.0.1:63765.  total accepted: 100. (63 connections now open)
Fri Feb 17 11:22:04 [conn100] connection accepted from 127.0.0.1:63765 (63 connections now open)

Generated at Thu Feb 08 03:07:35 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.