[SERVER-7700] scoped_db_conn_test unit test failing Created: 17/Nov/12  Updated: 25/Jul/13  Resolved: 19/Dec/12

Status: Closed
Project: Core Server
Component/s: Testing Infrastructure
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Ian Whalen (Inactive) Assignee: Randolph Tan
Resolution: Done Votes: 0
Labels: buildbot
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File scoped_db_conn_test (1).txt     Text File scoped_db_conn_test.txt    
Operating System: ALL
Steps To Reproduce:

http://buildlogs.mongodb.org/Windows%2064-bit/builds/5234/test/core/scoped_db_conn_test.exe

Participants:

 Comments   
Comment by Ian Whalen (Inactive) [ 22/Nov/12 ]

Failed at http://buildbot.mongodb.org/builders/Linux%2032-bit/builds/5306/steps/test_2/logs/stdio

Comment by auto [ 21/Nov/12 ]

Author:

{u'date': u'2012-11-21T19:53:01Z', u'email': u'randolph@10gen.com', u'name': u'Randolph Tan'}

Message: SERVER-7700 scoped_db_conn_test failing

Made sure that the handler object is not destroyed while there are active threads running threanRun (renamed to handleIncomingMsg)
Branch: master
https://github.com/mongodb/mongo/commit/3b563464a4cd52a32daef83ce600ffb0974d3b98

Comment by Tad Marshall [ 21/Nov/12 ]

Also failing on OS X 10.5 64-bit DUR OFF:

http://buildlogs.mongodb.org/OS%20X%2010.5%2064-bit%20DUR%20OFF/builds/1591/test/core/scoped_db_conn_test

 
Wed Nov 21 15:08:51.471 kern.sched unavailable
Wed Nov 21 15:08:51.478 [initandlisten] MongoDB starting : pid=57629 port=27999 dbpath=/data/db/sconsTests/ 64-bit host=bs-mm1.local
Wed Nov 21 15:08:51.478 [initandlisten] 
Wed Nov 21 15:08:51.478 [initandlisten] ** NOTE: This is a development version (2.3.1-pre-) of MongoDB.
Wed Nov 21 15:08:51.478 [initandlisten] **       Not recommended for production.
Wed Nov 21 15:08:51.478 [initandlisten] 
Wed Nov 21 15:08:51.478 [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 266 processes, 10240 files. Number of processes should be at least 5120 : 0.5 times number of files.
Wed Nov 21 15:08:51.478 [initandlisten] 
Wed Nov 21 15:08:51.478 [initandlisten] db version v2.3.1-pre-, pdfile version 4.5
Wed Nov 21 15:08:51.478 [initandlisten] git version: ca6b31d9d2da68bb14ea896d3db8de72fb0bed5d
Wed Nov 21 15:08:51.478 [initandlisten] build info: Darwin bs-mm1.local 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun  7 16:33:36 PDT 2011; root:xnu-1504.15.3~1/RELEASE_I386 i386 BOOST_LIB_VERSION=1_49
Wed Nov 21 15:08:51.478 [initandlisten] options: { dbpath: "/data/db/sconsTests/", port: 27999 }
Wed Nov 21 15:08:51.483 [websvr] admin web console waiting for connections on port 28999
Wed Nov 21 15:08:51.483 [initandlisten] waiting for connections on port 27999
Wed Nov 21 15:08:51.937 [initandlisten] connection accepted from 127.0.0.1:56222 #1 (1 connection now open)
Wed Nov 21 15:08:51.937 [conn1] end connection 127.0.0.1:56222 (0 connections now open)
Wed Nov 21 15:09:51.044 kern.sched unavailable
Wed Nov 21 15:09:51.044 going to run suite: DummyServerFixture
Wed Nov 21 15:09:51.044 	 going to run test: BasicScopedDbConnection
Wed Nov 21 15:09:51.044 waiting for connections on port 27017
Wed Nov 21 15:09:51.044 connection accepted from 127.0.0.1:56643 #1 (1 connection now open)
Wed Nov 21 15:09:51.045 [conn1] end connection 127.0.0.1:56643 (0 connections now open)
Wed Nov 21 15:09:51.047 closing listening socket: 6
Wed Nov 21 15:09:51.047 closing listening socket: 8
Wed Nov 21 15:09:51.047 removing socket file: /tmp/mongodb-27017.sock
Wed Nov 21 15:09:51.047 	 going to run test: InvalidateBadConnInPool
Wed Nov 21 15:09:51.048 waiting for connections on port 27017
Wed Nov 21 15:09:51.048 connection accepted from 127.0.0.1:56646 #2 (1 connection now open)
Wed Nov 21 15:09:51.049 [conn2] end connection 127.0.0.1:56646 (0 connections now open)
Wed Nov 21 15:09:51.049 connection accepted from 127.0.0.1:56647 #3 (1 connection now open)
Wed Nov 21 15:09:51.049 connection accepted from 127.0.0.1:56648 #4 (2 connections now open)
Wed Nov 21 15:09:51.050 connection accepted from 127.0.0.1:56649 #5 (3 connections now open)
Wed Nov 21 15:09:51.050 Socket say send() errno:2 No such file or directory 127.0.0.1:27017
Wed Nov 21 15:09:51.050 Detecting bad connection created at 0 microSec, clearing pool for localhost:27017
Wed Nov 21 15:09:51.050 [conn4] end connection 127.0.0.1:56648 (2 connections now open)
Wed Nov 21 15:09:51.050 [conn5] end connection 127.0.0.1:56649 (1 connection now open)
Wed Nov 21 15:09:51.050 [conn3] end connection 127.0.0.1:56647 (0 connections now open)
Wed Nov 21 15:09:51.051 connection accepted from 127.0.0.1:56650 #6 (1 connection now open)
Wed Nov 21 15:09:51.051 connection accepted from 127.0.0.1:56651 #7 (2 connections now open)
Wed Nov 21 15:09:51.051 connection accepted from 127.0.0.1:56652 #8 (3 connections now open)
Wed Nov 21 15:09:51.052 connection accepted from 127.0.0.1:56653 #9 (4 connections now open)
Wed Nov 21 15:09:51.052 connection accepted from 127.0.0.1:56654 #10 (5 connections now open)
Wed Nov 21 15:09:51.052 connection accepted from 127.0.0.1:56655 #11 (6 connections now open)
Wed Nov 21 15:09:51.052 connection accepted from 127.0.0.1:56656 #12 (7 connections now open)
Wed Nov 21 15:09:51.052 connection accepted from 127.0.0.1:56657 #13 (8 connections now open)
Wed Nov 21 15:09:51.052 connection accepted from 127.0.0.1:56658 #14 (9 connections now open)
Wed Nov 21 15:09:51.053 connection accepted from 127.0.0.1:56659 #15 (10 connections now open)
Wed Nov 21 15:09:51.053 [conn14] end connection 127.0.0.1:56658 (9 connections now open)
Wed Nov 21 15:09:51.053 [conn6] end connection 127.0.0.1:56650 (9 connections now open)
Wed Nov 21 15:09:51.053 [conn7] end connection 127.0.0.1:56651 (7 connections now open)
Wed Nov 21 15:09:51.053 [conn15] end connection 127.0.0.1:56659 (7 connections now open)
Wed Nov 21 15:09:51.053 [conn8] end connection 127.0.0.1:56652 (6 connections now open)
Wed Nov 21 15:09:51.053 [conn9] end connection 127.0.0.1:56653 (4 connections now open)
Wed Nov 21 15:09:51.053 closing listening socket: 7
Wed Nov 21 15:09:51.053 [conn10] end connection 127.0.0.1:56654 (3 connections now open)
Wed Nov 21 15:09:51.053 closing listening socket: 8
Wed Nov 21 15:09:51.053 removing socket file: /tmp/mongodb-27017.sock
Wed Nov 21 15:09:51.053 [conn11] end connection 127.0.0.1:56655 (2 connections now open)
Wed Nov 21 15:09:51.053 [conn12] end connection 127.0.0.1:56656 (1 connection now open)
Wed Nov 21 15:09:51.053 	 going to run test: DontReturnKnownBadConnToPool
Wed Nov 21 15:09:51.053 [conn13] end connection 127.0.0.1:56657 (0 connections now open)
Wed Nov 21 15:09:51.053 waiting for connections on port 27017
Wed Nov 21 15:09:51.054 connection accepted from 127.0.0.1:56660 #16 (1 connection now open)
Wed Nov 21 15:09:51.054 [conn16] end connection 127.0.0.1:56660 (0 connections now open)
Wed Nov 21 15:09:51.054 connection accepted from 127.0.0.1:56661 #17 (1 connection now open)
Wed Nov 21 15:09:51.054 connection accepted from 127.0.0.1:56662 #18 (2 connections now open)
Wed Nov 21 15:09:51.054 connection accepted from 127.0.0.1:56663 #19 (3 connections now open)
Wed Nov 21 15:09:51.054 Socket say send() errno:2 No such file or directory 127.0.0.1:27017
Wed Nov 21 15:09:51.054 Detecting bad connection created at 1353528591049914 microSec, clearing pool for localhost:27017
Wed Nov 21 15:09:51.054 [conn17] end connection 127.0.0.1:56661 (2 connections now open)
Wed Nov 21 15:09:51.054 [conn18] end connection 127.0.0.1:56662 (2 connections now open)
Wed Nov 21 15:09:51.054 [conn19] end connection 127.0.0.1:56663 (0 connections now open)
Wed Nov 21 15:09:51.055 connection accepted from 127.0.0.1:56664 #20 (1 connection now open)
Wed Nov 21 15:09:51.055 connection accepted from 127.0.0.1:56665 #21 (2 connections now open)
Wed Nov 21 15:09:51.055 connection accepted from 127.0.0.1:56666 #22 (3 connections now open)
Wed Nov 21 15:09:51.058 connection accepted from 127.0.0.1:56667 #23 (4 connections now open)
Wed Nov 21 15:09:51.059 connection accepted from 127.0.0.1:56668 #24 (5 connections now open)
Wed Nov 21 15:09:51.059 connection accepted from 127.0.0.1:56669 #25 (6 connections now open)
Wed Nov 21 15:09:51.060 connection accepted from 127.0.0.1:56670 #26 (7 connections now open)
Wed Nov 21 15:09:51.060 connection accepted from 127.0.0.1:56671 #27 (8 connections now open)
Wed Nov 21 15:09:51.060 connection accepted from 127.0.0.1:56672 #28 (9 connections now open)
Wed Nov 21 15:09:51.061 connection accepted from 127.0.0.1:56673 #29 (10 connections now open)
Wed Nov 21 15:09:51.061 [conn20] end connection 127.0.0.1:56664 (9 connections now open)
Wed Nov 21 15:09:51.061 [conn23] end connection 127.0.0.1:56667 (9 connections now open)
Wed Nov 21 15:09:51.061 [conn21] end connection 127.0.0.1:56665 (7 connections now open)
Wed Nov 21 15:09:51.061 [conn25] end connection 127.0.0.1:56669 (7 connections now open)
Wed Nov 21 15:09:51.061 [conn26] end connection 127.0.0.1:56670 (7 connections now open)
Wed Nov 21 15:09:51.061 [conn28] end connection 127.0.0.1:56672 (5 connections now open)
Wed Nov 21 15:09:51.061 closing listening socket: 7
Wed Nov 21 15:09:51.061 [conn27] end connection 127.0.0.1:56671 (7 connections now open)
Wed Nov 21 15:09:51.061 closing listening socket: 8
Wed Nov 21 15:09:51.061 removing socket file: /tmp/mongodb-27017.sock
Wed Nov 21 15:09:51.061 	 going to run test: InvalidateBadConnEvenWhenPoolIsFull
Wed Nov 21 15:09:51.061 [conn29] end connection 127.0.0.1:56673 (7 connections now open)
Wed Nov 21 15:09:51.062 waiting for connections on port 27017
Wed Nov 21 15:09:51.061 [conn24] end connection 127.0.0.1:56668 (7 connections now open)
Wed Nov 21 15:09:51.062 connection accepted from 127.0.0.1:56674 #30 (4 connections now open)
Wed Nov 21 15:09:51.061 [conn22] end connection 127.0.0.1:56666 (7 connections now open)
Wed Nov 21 15:09:51.063 [conn30] end connection 127.0.0.1:56674 (0 connections now open)
Wed Nov 21 15:09:51.063 connection accepted from 127.0.0.1:56675 #31 (1 connection now open)
Wed Nov 21 15:09:51.064 Socket say send() errno:2 No such file or directory 127.0.0.1:27017
Wed Nov 21 15:09:51.064 Detecting bad connection created at 1353528591054608 microSec, clearing pool for localhost:27017
Wed Nov 21 15:09:51.064 [conn31] end connection 127.0.0.1:56675 (0 connections now open)
Wed Nov 21 15:09:51.065 closing listening socket: 7
Wed Nov 21 15:09:51.065 closing listening socket: 8
Wed Nov 21 15:09:51.065 removing socket file: /tmp/mongodb-27017.sock
Wed Nov 21 15:09:51.065 	 going to run test: DontReturnConnGoneBadToPool
Wed Nov 21 15:09:51.065 waiting for connections on port 27017
Wed Nov 21 15:09:51.065 connection accepted from 127.0.0.1:56680 #32 (1 connection now open)
Wed Nov 21 15:09:51.066 [conn32] end connection 127.0.0.1:56680 (0 connections now open)
Wed Nov 21 15:09:51.066 connection accepted from 127.0.0.1:56681 #33 (1 connection now open)
Wed Nov 21 15:09:51.066 connection accepted from 127.0.0.1:56682 #34 (2 connections now open)
Wed Nov 21 15:09:51.066 scoped connection to localhost:27017 not being returned to the pool
Wed Nov 21 15:09:51.066 [conn34] end connection 127.0.0.1:56682 (1 connection now open)
Wed Nov 21 15:09:51.067 connection accepted from 127.0.0.1:56683 #35 (2 connections now open)
Wed Nov 21 15:09:51.067 connection accepted from 127.0.0.1:56684 #36 (3 connections now open)
Wed Nov 21 15:09:51.067 connection accepted from 127.0.0.1:56685 #37 (4 connections now open)
Wed Nov 21 15:09:51.067 connection accepted from 127.0.0.1:56686 #38 (5 connections now open)
Wed Nov 21 15:09:51.068 connection accepted from 127.0.0.1:56687 #39 (6 connections now open)
Wed Nov 21 15:09:51.068 connection accepted from 127.0.0.1:56688 #40 (7 connections now open)
Wed Nov 21 15:09:51.068 connection accepted from 127.0.0.1:56689 #41 (8 connections now open)
Wed Nov 21 15:09:51.068 connection accepted from 127.0.0.1:56690 #42 (9 connections now open)
Wed Nov 21 15:09:51.068 connection accepted from 127.0.0.1:56691 #43 (10 connections now open)
Wed Nov 21 15:09:51.068 [conn33] end connection 127.0.0.1:56681 (9 connections now open)
Wed Nov 21 15:09:51.068 [conn35] end connection 127.0.0.1:56683 (9 connections now open)
Wed Nov 21 15:09:51.069 [conn36] end connection 127.0.0.1:56684 (7 connections now open)
Wed Nov 21 15:09:51.069 [conn37] end connection 127.0.0.1:56685 (7 connections now open)
Wed Nov 21 15:09:51.069 [conn38] end connection 127.0.0.1:56686 (5 connections now open)
Wed Nov 21 15:09:51.069 closing listening socket: 7
Wed Nov 21 15:09:51.069 closing listening socket: 8
Wed Nov 21 15:09:51.069 [conn39] end connection 127.0.0.1:56687 (4 connections now open)
Wed Nov 21 15:09:51.069 removing socket file: /tmp/mongodb-27017.sock
Wed Nov 21 15:09:51.069 [conn40] end connection 127.0.0.1:56688 (3 connections now open)
Wed Nov 21 15:09:51.069 [conn41] end connection 127.0.0.1:56689 (2 connections now open)
Wed Nov 21 15:09:51.069 [conn43] end connection 127.0.0.1:56691 (2 connections now open)
Wed Nov 21 15:09:51.069 [conn42] end connection 127.0.0.1:56690 (2 connections now open)
 
Wed Nov 21 15:09:58.808 got signal 15 (Terminated), will terminate after current cmd ends
Wed Nov 21 15:09:58.808 [interruptThread] now exiting
Wed Nov 21 15:09:58.808 dbexit: 
Wed Nov 21 15:09:58.808 [interruptThread] shutdown: going to close listening sockets...
Wed Nov 21 15:09:58.808 [interruptThread] closing listening socket: 7
Wed Nov 21 15:09:58.808 [interruptThread] closing listening socket: 8
Wed Nov 21 15:09:58.808 [interruptThread] closing listening socket: 10
Wed Nov 21 15:09:58.808 [interruptThread] removing socket file: /tmp/mongodb-27999.sock
Wed Nov 21 15:09:58.808 [interruptThread] shutdown: going to flush diaglog...
Wed Nov 21 15:09:58.808 [interruptThread] shutdown: going to close sockets...
Wed Nov 21 15:09:58.808 [interruptThread] shutdown: waiting for fs preallocator...
Wed Nov 21 15:09:58.808 [interruptThread] shutdown: closing all files...
Wed Nov 21 15:09:58.808 [interruptThread] closeAllFiles() finished
Wed Nov 21 15:09:58.808 [interruptThread] shutdown: removing fs lock...
Wed Nov 21 15:09:58.808 dbexit: really exiting now

Comment by Eric Milkie [ 21/Nov/12 ]

We think this is failing for a different reason. The title of this issue is incorrect; it's on Linux machines that this is failing now. Ren is looking into it.

Comment by Ian Whalen (Inactive) [ 21/Nov/12 ]

reopening based on http://buildbot.mongodb.org/builders/Linux%2032-bit/builds/5301/steps/test_2/logs/stdio

Comment by auto [ 21/Nov/12 ]

Author:

{u'date': u'2012-11-20T19:56:24Z', u'email': u'tad@10gen.com', u'name': u'Tad Marshall'}

Message: SERVER-7700 Improve curTimeMicros64 resolution for Windows

Use QueryPerformanceCounter in combination with GetSystemTimeAsFileTime
to give curTimeMicros64() microsecond resolution on Windows.
Branch: master
https://github.com/mongodb/mongo/commit/cb14cf83102cca848e572ffd8b95c6fa35594175

Comment by Tad Marshall [ 18/Nov/12 ]

shard_conn_test has the same problem.

Comment by auto [ 18/Nov/12 ]

Author:

{u'date': u'2012-11-18T17:38:16Z', u'email': u'tad@10gen.com', u'name': u'Tad Marshall'}

Message: Revert "SERVER-7700 Use high-resolution program uptime to track socket connection time"

This reverts commit 7c8dec9a7bff471724c9cf9941650462a11bd983.
Branch: master
https://github.com/mongodb/mongo/commit/39ccb23eaf656640fe3def564c47ebbcaa003b11

Comment by auto [ 18/Nov/12 ]

Author:

{u'date': u'2012-11-18T14:17:51Z', u'email': u'tad@10gen.com', u'name': u'Tad Marshall'}

Message: SERVER-7700 Use high-resolution program uptime to track socket connection time

Switch from curTimeMicros64() to new getProgramUptimeMicros() function for
tracking socket connection time. curTimeMicros64() on Windows uses
GetSystemTimeAsFileTime(), which has a resolution of 1 to 15 milliseconds,
which is not good enough for tracking fast events. getProgramUptimeMicros()
provides program uptime instead of clock time, but uses QueryPerformanceCounter()
on Windows and so has sub-microsecond resolution.
Branch: master
https://github.com/mongodb/mongo/commit/7c8dec9a7bff471724c9cf9941650462a11bd983

Comment by Tad Marshall [ 17/Nov/12 ]

The timer being used to differentiate connections in too grainy on Windows for this purpose ... the code wants to see time durations in the 10 microsecond range, and we need to use different timing APIs to get that granularity on Windows.

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