Socket TIME_WAIT state: Too many C++ driver connections dropping and reconnecting

[Pieter Jordaan]

Hi mongodb-user

I am using C++ and ScopedDbConnection in a multithreaded environment. For my current testing purposes I have a single machine replica set with a single node. I have high volume writes into the database. I see hundreds of new connections and dropped connections in mongodb's log file. This seems irregular for a connection pool. I am appending the excerpt of the log file for reference. I use it as follows on multiple threads:

boost::scoped_ptr<mongo::ScopedDbConnection> connect(mongo::ScopedDbConnection::getScopedDbConnection("myset/127.0.0.1:27017");
...
connect->done();

This problem leads to thousands of TIME_WAIT sockets and eventually the client driver and other applications dropping connections with errors like: socket exception [CONNECT_ERROR] for myset/127.0.0.1:27017
Is this related to the C++ driver or internals of the mongod process?

Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49893 #688766 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49894 #688767 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49895 #688768 (25 connections now open)
Sat Sep 29 01:51:13 [conn688761] end connection 127.0.0.1:49888 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49896 #688769 (25 connections now open)
Sat Sep 29 01:51:13 [conn688768] end connection 127.0.0.1:49895 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49897 #688770 (25 connections now open)
Sat Sep 29 01:51:13 [conn688767] end connection 127.0.0.1:49894 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49898 #688771 (25 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49899 #688772 (26 connections now open)
Sat Sep 29 01:51:13 [conn688765] end connection 127.0.0.1:49892 (25 connections now open)
Sat Sep 29 01:51:13 [conn688762] end connection 127.0.0.1:49889 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49900 #688773 (25 connections now open)
Sat Sep 29 01:51:13 [conn688764] end connection 127.0.0.1:49891 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49901 #688774 (25 connections now open)
Sat Sep 29 01:51:13 [conn688769] end connection 127.0.0.1:49896 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49902 #688775 (25 connections now open)
Sat Sep 29 01:51:13 [conn688766] end connection 127.0.0.1:49893 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49903 #688776 (25 connections now open)
Sat Sep 29 01:51:13 [conn688772] end connection 127.0.0.1:49899 (24 connections now open)
Sat Sep 29 01:51:13 [conn688763] end connection 127.0.0.1:49890 (23 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49904 #688777 (25 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49905 #688778 (26 connections now open)
Sat Sep 29 01:51:13 [conn688778] end connection 127.0.0.1:49905 (24 connections now open)
Sat Sep 29 01:51:13 [conn688773] end connection 127.0.0.1:49900 (23 connections now open)
Sat Sep 29 01:51:13 [conn688771] end connection 127.0.0.1:49898 (23 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49906 #688779 (25 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49907 #688780 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49908 #688781 (25 connections now open)
Sat Sep 29 01:51:13 [conn688770] end connection 127.0.0.1:49897 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49909 #688782 (26 connections now open)
Sat Sep 29 01:51:13 [conn688774] end connection 127.0.0.1:49901 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49910 #688783 (25 connections now open)
Sat Sep 29 01:51:13 [conn688780] end connection 127.0.0.1:49907 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49911 #688784 (25 connections now open)
Sat Sep 29 01:51:13 [conn688781] end connection 127.0.0.1:49908 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49912 #688785 (26 connections now open)
Sat Sep 29 01:51:13 [conn688776] end connection 127.0.0.1:49903 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49913 #688786 (27 connections now open)
Sat Sep 29 01:51:13 [conn688782] end connection 127.0.0.1:49909 (24 connections now open)
Sat Sep 29 01:51:13 [initandlisten] connection accepted from 127.0.0.1:49914 #688787 (26 connections now open)
Sat Sep 29 01:51:13 [conn688779] end connection 127.0.0.1:49906 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49915 #688788 (26 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49916 #688789 (26 connections now open)
Sat Sep 29 01:51:14 [conn688777] end connection 127.0.0.1:49904 (25 connections now open)
Sat Sep 29 01:51:14 [conn688783] end connection 127.0.0.1:49910 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49917 #688790 (25 connections now open)
Sat Sep 29 01:51:14 [conn688786] end connection 127.0.0.1:49913 (24 connections now open)
Sat Sep 29 01:51:14 [conn688788] end connection 127.0.0.1:49915 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49918 #688791 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49919 #688792 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49920 #688793 (26 connections now open)
Sat Sep 29 01:51:14 [conn688784] end connection 127.0.0.1:49911 (24 connections now open)
Sat Sep 29 01:51:14 [conn688785] end connection 127.0.0.1:49912 (24 connections now open)
Sat Sep 29 01:51:14 [conn688775] end connection 127.0.0.1:49902 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49921 #688794 (27 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49922 #688795 (26 connections now open)
Sat Sep 29 01:51:14 [conn688792] end connection 127.0.0.1:49919 (24 connections now open)
Sat Sep 29 01:51:14 [conn688787] end connection 127.0.0.1:49914 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49923 #688796 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49924 #688797 (25 connections now open)
Sat Sep 29 01:51:14 [conn688790] end connection 127.0.0.1:49917 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49925 #688798 (25 connections now open)
Sat Sep 29 01:51:14 [conn688789] end connection 127.0.0.1:49916 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49926 #688799 (25 connections now open)
Sat Sep 29 01:51:14 [conn688791] end connection 127.0.0.1:49918 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49927 #688800 (25 connections now open)
Sat Sep 29 01:51:14 [conn688795] end connection 127.0.0.1:49922 (24 connections now open)
Sat Sep 29 01:51:14 [conn688793] end connection 127.0.0.1:49920 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49928 #688801 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49929 #688802 (25 connections now open)
Sat Sep 29 01:51:14 [conn688794] end connection 127.0.0.1:49921 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49930 #688803 (26 connections now open)
Sat Sep 29 01:51:14 [conn688800] end connection 127.0.0.1:49927 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49931 #688804 (25 connections now open)
Sat Sep 29 01:51:14 [conn688796] end connection 127.0.0.1:49923 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49932 #688805 (25 connections now open)
Sat Sep 29 01:51:14 [conn688801] end connection 127.0.0.1:49928 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49933 #688806 (25 connections now open)
Sat Sep 29 01:51:14 [conn688798] end connection 127.0.0.1:49925 (24 connections now open)
Sat Sep 29 01:51:14 [conn688799] end connection 127.0.0.1:49926 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49934 #688807 (24 connections now open)
Sat Sep 29 01:51:14 [conn688797] end connection 127.0.0.1:49924 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49935 #688808 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49936 #688809 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49937 #688810 (26 connections now open)
Sat Sep 29 01:51:14 [conn688802] end connection 127.0.0.1:49929 (22 connections now open)
Sat Sep 29 01:51:14 [conn688805] end connection 127.0.0.1:49932 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49938 #688811 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49939 #688812 (26 connections now open)
Sat Sep 29 01:51:14 [conn688803] end connection 127.0.0.1:49930 (24 connections now open)
Sat Sep 29 01:51:14 [conn688804] end connection 127.0.0.1:49931 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49940 #688813 (25 connections now open)
Sat Sep 29 01:51:14 [conn688807] end connection 127.0.0.1:49934 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49941 #688814 (26 connections now open)
Sat Sep 29 01:51:14 [conn688806] end connection 127.0.0.1:49933 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49942 #688815 (25 connections now open)
Sat Sep 29 01:51:14 [conn688810] end connection 127.0.0.1:49937 (24 connections now open)
Sat Sep 29 01:51:14 [conn688808] end connection 127.0.0.1:49935 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49943 #688816 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49944 #688817 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49945 #688818 (26 connections now open)
Sat Sep 29 01:51:14 [conn688809] end connection 127.0.0.1:49936 (23 connections now open)
Sat Sep 29 01:51:14 [conn688811] end connection 127.0.0.1:49938 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49946 #688819 (26 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49947 #688820 (26 connections now open)
Sat Sep 29 01:51:14 [conn688813] end connection 127.0.0.1:49940 (24 connections now open)
Sat Sep 29 01:51:14 [conn688815] end connection 127.0.0.1:49942 (24 connections now open)
Sat Sep 29 01:51:14 [conn688814] end connection 127.0.0.1:49941 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49948 #688821 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49949 #688822 (25 connections now open)
Sat Sep 29 01:51:14 [conn688816] end connection 127.0.0.1:49943 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49950 #688823 (25 connections now open)
Sat Sep 29 01:51:14 [conn688812] end connection 127.0.0.1:49939 (24 connections now open)
Sat Sep 29 01:51:14 [conn688817] end connection 127.0.0.1:49944 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49951 #688824 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49952 #688825 (26 connections now open)
Sat Sep 29 01:51:14 [conn688818] end connection 127.0.0.1:49945 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49953 #688826 (25 connections now open)
Sat Sep 29 01:51:14 [conn688821] end connection 127.0.0.1:49948 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49954 #688827 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49955 #688828 (26 connections now open)
Sat Sep 29 01:51:14 [conn688819] end connection 127.0.0.1:49946 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49956 #688829 (26 connections now open)
Sat Sep 29 01:51:14 [conn688826] end connection 127.0.0.1:49953 (24 connections now open)
Sat Sep 29 01:51:14 [conn688823] end connection 127.0.0.1:49950 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49957 #688830 (25 connections now open)
Sat Sep 29 01:51:14 [conn688820] end connection 127.0.0.1:49947 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49958 #688831 (25 connections now open)
Sat Sep 29 01:51:14 [conn688827] end connection 127.0.0.1:49954 (24 connections now open)
Sat Sep 29 01:51:14 [conn688825] end connection 127.0.0.1:49952 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49959 #688832 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49960 #688833 (25 connections now open)
Sat Sep 29 01:51:14 [conn688822] end connection 127.0.0.1:49949 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49961 #688834 (25 connections now open)
Sat Sep 29 01:51:14 [conn688829] end connection 127.0.0.1:49956 (24 connections now open)
Sat Sep 29 01:51:14 [conn688824] end connection 127.0.0.1:49951 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49962 #688835 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49963 #688836 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49964 #688837 (26 connections now open)
Sat Sep 29 01:51:14 [conn688828] end connection 127.0.0.1:49955 (25 connections now open)
Sat Sep 29 01:51:14 [conn688831] end connection 127.0.0.1:49958 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49965 #688838 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49966 #688839 (26 connections now open)
Sat Sep 29 01:51:14 [conn688833] end connection 127.0.0.1:49960 (24 connections now open)
Sat Sep 29 01:51:14 [conn688832] end connection 127.0.0.1:49959 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49967 #688840 (25 connections now open)
Sat Sep 29 01:51:14 [conn688830] end connection 127.0.0.1:49957 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49968 #688841 (25 connections now open)
Sat Sep 29 01:51:14 [conn688837] end connection 127.0.0.1:49964 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49969 #688842 (26 connections now open)
Sat Sep 29 01:51:14 [conn688835] end connection 127.0.0.1:49962 (25 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49970 #688843 (26 connections now open)
Sat Sep 29 01:51:14 [conn688839] end connection 127.0.0.1:49966 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49971 #688844 (25 connections now open)
Sat Sep 29 01:51:14 [conn688836] end connection 127.0.0.1:49963 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49972 #688845 (26 connections now open)
Sat Sep 29 01:51:14 [conn688838] end connection 127.0.0.1:49965 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49973 #688846 (25 connections now open)
Sat Sep 29 01:51:14 [conn688841] end connection 127.0.0.1:49968 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49974 #688847 (26 connections now open)
Sat Sep 29 01:51:14 [conn688840] end connection 127.0.0.1:49967 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49975 #688848 (25 connections now open)
Sat Sep 29 01:51:14 [conn688834] end connection 127.0.0.1:49961 (24 connections now open)
Sat Sep 29 01:51:14 [conn688842] end connection 127.0.0.1:49969 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49976 #688849 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49977 #688850 (25 connections now open)
Sat Sep 29 01:51:14 [conn688843] end connection 127.0.0.1:49970 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49978 #688851 (25 connections now open)
Sat Sep 29 01:51:14 [conn688845] end connection 127.0.0.1:49972 (24 connections now open)
Sat Sep 29 01:51:14 [conn688846] end connection 127.0.0.1:49973 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49979 #688852 (24 connections now open)
Sat Sep 29 01:51:14 [conn688844] end connection 127.0.0.1:49971 (23 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49980 #688853 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49981 #688854 (25 connections now open)
Sat Sep 29 01:51:14 [conn688848] end connection 127.0.0.1:49975 (24 connections now open)
Sat Sep 29 01:51:14 [initandlisten] connection accepted from 127.0.0.1:49982 #688855 (25 connections now open)

[Pieter Jordaan]

Netstat result:
$ netstat -tn | sed -n '/:27017.*TIME_WAIT/p' | wc -l
28234

This means mongo client connections leave 28234 sockets in TIME_WAIT. This is unacceptable.

[Pieter Jordaan]

This is due to my own bas usage of the pool.

[Stephen Steneker]

On Sunday, September 30, 2012 8:32:11 PM UTC+10, Pieter Jordaan wrote:

This is due to my own bas usage of the pool.

Hi Pieter,

Can you clarify your last comment .. was that meant to be "bad usage" of the pool (i.e. you've found the problem)?

Cheers,

Stephen

 

[Pieter Jordaan]

Hi Stephen

Yes that was a typo.

I apologize for the brevity of my comment. I've found that using queries with SlaveOkay set, while there is only a single node in the replica set (ie. only one member -> the master there are no slaves set up in the set) the connections go crazy in the mongodb log file. Disconnects and connects as shown in my first post. I'm about to test this with two nodes (ie. one master and one slave).

I'm unsure if this condition should be tested by the client driver. Please advise if I should create a Jira.

[Pieter Jordaan]

I can now confirm this does not happen when there is a slave in the set.