Uploaded image for project: 'Python Driver'
  1. Python Driver
  2. PYTHON-1246

Test Failure - test_legacy_api.TestLegacy.test_insert_large_batch (Windows, MongoDB 2.4, sharded)

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 3.5
    • Affects Version/s: None
    • Component/s: Tests
    • None

      This test consistently fails on Windows with sharded MongoDB 2.4.

       [2017/02/27 14:24:50.102] ======================================================================
       [2017/02/27 14:24:50.102] ERROR [49.884s]: test_insert_large_batch (test_legacy_api.TestLegacy)
       [2017/02/27 14:24:50.102] ----------------------------------------------------------------------
       [2017/02/27 14:24:50.102] Traceback (most recent call last):
       [2017/02/27 14:24:50.102]   File "C:\data\mci\61d6c0b2187aff743a68d633f3df2def\src\pymongo\mongo_client.py", line 1193, in drop_database
       [2017/02/27 14:24:50.102]     parse_write_concern_error=True)
       [2017/02/27 14:24:50.102]   File "C:\data\mci\61d6c0b2187aff743a68d633f3df2def\src\pymongo\database.py", line 406, in _command
       [2017/02/27 14:24:50.102]     parse_write_concern_error=parse_write_concern_error)
       [2017/02/27 14:24:50.102]   File "C:\data\mci\61d6c0b2187aff743a68d633f3df2def\src\pymongo\pool.py", line 419, in command
       [2017/02/27 14:24:50.102]     collation=collation)
       [2017/02/27 14:24:50.102]   File "C:\data\mci\61d6c0b2187aff743a68d633f3df2def\src\pymongo\network.py", line 116, in command
       [2017/02/27 14:24:50.102]     parse_write_concern_error=parse_write_concern_error)
       [2017/02/27 14:24:50.102]   File "C:\data\mci\61d6c0b2187aff743a68d633f3df2def\src\pymongo\helpers.py", line 210, in _check_command_response
       [2017/02/27 14:24:50.102]     raise OperationFailure(msg % errmsg, code, response)
       [2017/02/27 14:24:50.102] OperationFailure: exception: DBClientBase::findN: transport error: localhost:27217 ns: test_insert_large_batch.$cmd query: { dropDatabase: 1 }
      

      The issue appears to be a race condition in database deletion and database file pre-creation on mongod that causes mongos to time out waiting for a response to the dropDatabase command. Since 2.4 is EOL there won't be a fix, so we can either work around it (the equivalent test in v2.9 passes, but is structured differently) or just skip it with this configuration.

      Log snippet from mongos:

      Mon Feb 27 19:20:40.311 [conn373] Socket recv() timeout  127.0.0.1:27217
      Mon Feb 27 19:20:40.311 [conn373] SocketException: remote: 127.0.0.1:27217 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.0.1:27217] 
      Mon Feb 27 19:20:40.311 [conn373] DBClientCursor::init call() failed
      

      Log snippet from mongod:

      Mon Feb 27 19:20:10.361 [conn8] dropDatabase test_insert_large_batch starting
      Mon Feb 27 19:20:21.806 [FileAllocator] done allocating datafile c:\data\mci\61d6c0b2187aff743a68d633f3df2def\drivers-tools\.evergreen\orchestration\db\mongo-ijwwoc\test_insert_large_batch.5, size: 2047MB,  took 12.59 secs
      Mon Feb 27 19:20:59.453 [conn8] removeJournalFiles
      Mon Feb 27 19:21:00.168 [conn8] dropDatabase test_insert_large_batch finished
      Mon Feb 27 19:21:00.168 [conn8] command test_insert_large_batch.$cmd command: { dropDatabase: 1 } ntoreturn:1 keyUpdates:0 locks(micros) W:49805428 reslen:74 49807ms
      Mon Feb 27 19:21:00.168 [conn6] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after cursors: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after indexCounters: 0, after locks: 0, after network: 0, after opcounters: 0, after opcountersRepl: 0, after recordStats: 49800, at end: 49800 }
      Mon Feb 27 19:21:00.168 [conn6] command admin.$cmd command: { serverStatus: 1 } ntoreturn:1 keyUpdates:0 locks(micros) r:30 reslen:4094 49803ms
      Mon Feb 27 19:21:00.168 [conn8] end connection 127.0.0.1:54433 (17 connections now open)
      Mon Feb 27 19:21:00.173 [conn15] CMD: drop pymongo_test.test_insert_manipulate_false
      Mon Feb 27 19:21:00.388 [conn4] allocating new ns file c:\data\mci\61d6c0b2187aff743a68d633f3df2def\drivers-tools\.evergreen\orchestration\db\mongo-ijwwoc\test_insert_large_batch.ns, filling with zeroes...
      Mon Feb 27 19:21:00.676 [conn15] build index pymongo_test.test_insert_manipulate_false { _id: 1 }
      Mon Feb 27 19:21:00.677 [conn15] build index done.  scanned 0 total records. 0 secs
      Mon Feb 27 19:21:00.681 [conn15] CMD: drop pymongo_test.test_insert_manipulate_false
      

            Assignee:
            bernie@mongodb.com Bernie Hackett
            Reporter:
            bernie@mongodb.com Bernie Hackett
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: