Uploaded image for project: 'Go Driver'
  1. Go Driver
  2. GODRIVER-1875

Investigate frequent TestPool test timeout

    • Type: Icon: Task Task
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 1.4.7
    • Affects Version/s: None
    • Component/s: Testing
    • Labels:
      None

      It appears to be a deadlock. This may likely be a test-only issue.

      Example task failure

      This is the relevant log output:

      === RUN   TestPool
       === RUN   TestPool/newPool
       === RUN   TestPool/newPool/should_be_connected
       === RUN   TestPool/closeConnection
       === RUN   TestPool/closeConnection/can't_put_connection_from_different_pool
       === RUN   TestPool/disconnect
       === RUN   TestPool/disconnect/cannot_close_twice
       === RUN   TestPool/disconnect/closes_idle_connections
       === RUN   TestPool/disconnect/closes_all_connections_currently_in_pool_and_closes_all_remaining_connections
       === RUN   TestPool/disconnect/properly_sets_the_connection_state_on_return
       === RUN   TestPool/disconnect/no_race_if_connections_are_also_connecting
          pool_test.go:237: Unexpected error: connection() error occured during connection handshake: dial tcp 127.0.0.1:44591: connect: connection refused
       panic: test timed out after 30m0s
       
       goroutine 20227705 [running]:
       testing.(*M).startAlarm.func1()
       	/opt/golang/go1.15/src/testing/testing.go:1609 +0xe5
       created by time.goFunc
       	/opt/golang/go1.15/src/time/sleep.go:167 +0x45
       
       goroutine 1 [chan receive, 29 minutes]:
       testing.(*T).Run(0xc000102480, 0xb1782e, 0x8, 0xb454c0, 0x493001)
       	/opt/golang/go1.15/src/testing/testing.go:1160 +0x3ad
       testing.runTests.func1(0xc000001c80)
       	/opt/golang/go1.15/src/testing/testing.go:1430 +0x78
       testing.tRunner(0xc000001c80, 0xc0001a5de0)
       	/opt/golang/go1.15/src/testing/testing.go:1108 +0xef
       testing.runTests(0xc00000f4e0, 0x1191500, 0x15, 0x15, 0xbfff3f0f80ed1b8c, 0x1a3188a5e37, 0x11e1240, 0x4109d0)
       	/opt/golang/go1.15/src/testing/testing.go:1428 +0x2e8
       testing.(*M).Run(0xc000042300, 0x0)
       	/opt/golang/go1.15/src/testing/testing.go:1338 +0x245
       main.main()
       	_testmain.go:83 +0x138
       
       goroutine 894 [chan receive, 29 minutes]:
       testing.(*T).Run(0xc000103080, 0xb18947, 0xa, 0xb45408, 0x8d3003a801)
       	/opt/golang/go1.15/src/testing/testing.go:1160 +0x3ad
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool(0xc000102480)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:58 +0xae
       testing.tRunner(0xc000102480, 0xb454c0)
       	/opt/golang/go1.15/src/testing/testing.go:1108 +0xef
       created by testing.(*T).Run
       	/opt/golang/go1.15/src/testing/testing.go:1159 +0x386
       
       goroutine 963 [chan receive, 29 minutes]:
       testing.(*T).Run(0xc00064a300, 0xb316c7, 0x2a, 0xb45400, 0x8d3006d901)
       	/opt/golang/go1.15/src/testing/testing.go:1160 +0x3ad
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3(0xc000103080)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:201 +0x10c
       testing.tRunner(0xc000103080, 0xb45408)
       	/opt/golang/go1.15/src/testing/testing.go:1108 +0xef
       created by testing.(*T).Run
       	/opt/golang/go1.15/src/testing/testing.go:1159 +0x386
       
       goroutine 1005 [chan receive, 29 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3.5.1(0xcd67c0, 0xc0001260e8)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:204 +0x33
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.bootstrapConnections.func1
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection_test.go:888 +0x52
       
       goroutine 1003 [chan receive]:
       net.(*netFD).connect.func1(0xc000756000, 0xc000756060, 0xc0005e73a0, 0xc0004fe000)
       	/opt/golang/go1.15/src/net/fd_unix.go:106 +0x4f
       net.(*netFD).connect(0xc0004fe000, 0xcd1c00, 0xc00080e240, 0x0, 0x0, 0xcc77e0, 0xc000494000, 0x0, 0x0, 0xcc7720, ...)
       	/opt/golang/go1.15/src/net/fd_unix.go:165 +0x353
       net.(*netFD).dial(0xc0004fe000, 0xcd1c00, 0xc00080e240, 0xcd3d60, 0x0, 0xcd3d60, 0xc0004bc840, 0x0, 0xc000274401, 0xc0005e74d0)
       	/opt/golang/go1.15/src/net/sock_posix.go:149 +0x108
       net.socket(0xcd1c00, 0xc00080e240, 0xb16344, 0x3, 0x2, 0x1, 0x0, 0x0, 0xcd3d60, 0x0, ...)
       	/opt/golang/go1.15/src/net/sock_posix.go:70 +0x1c5
       net.internetSocket(0xcd1c00, 0xc00080e240, 0xb16344, 0x3, 0xcd3d60, 0x0, 0xcd3d60, 0xc0004bc840, 0x1, 0x0, ...)
       	/opt/golang/go1.15/src/net/ipsock_posix.go:141 +0x145
       net.(*sysDialer).doDialTCP(0xc000373f80, 0xcd1c00, 0xc00080e240, 0x0, 0xc0004bc840, 0xa8f860, 0x12136b0, 0x0)
       	/opt/golang/go1.15/src/net/tcpsock_posix.go:65 +0xc5
       net.(*sysDialer).dialTCP(0xc000373f80, 0xcd1c00, 0xc00080e240, 0x0, 0xc0004bc840, 0xc0005e7710, 0x408890, 0x60)
       	/opt/golang/go1.15/src/net/tcpsock_posix.go:61 +0xd7
       net.(*sysDialer).dialSingle(0xc000373f80, 0xcd1c00, 0xc00080e240, 0xccab40, 0xc0004bc840, 0x0, 0x0, 0x0, 0x0)
       	/opt/golang/go1.15/src/net/dial.go:580 +0x5e5
       net.(*sysDialer).dialSerial(0xc000373f80, 0xcd1c00, 0xc00080e240, 0xc00048fa90, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
       	/opt/golang/go1.15/src/net/dial.go:548 +0x152
       net.(*Dialer).DialContext(0xc00027b140, 0xcd1c00, 0xc00080e240, 0xb16344, 0x3, 0xc000384290, 0xf, 0x0, 0x0, 0x0, ...)
       	/opt/golang/go1.15/src/net/dial.go:425 +0x6e5
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*dialer).DialContext(0xc0003e5110, 0xcd1c00, 0xc00080e240, 0xb16344, 0x3, 0xc000384290, 0xf, 0x0, 0x0, 0x0, ...)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection_test.go:934 +0xf0
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*connection).connect(0xc0004c7180, 0xcd1c00, 0xc00080e240)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection.go:140 +0x251
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).get(0xc0004c4540, 0xcd1c80, 0xc000449d40, 0xcd1c80, 0xc000449d40, 0xc00048fa40)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:433 +0x565
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3.5.3(0xc000388fc0, 0xc000389020, 0xcd1c00, 0xc00010e3c0, 0xc0004c4540)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:229 +0x9c
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3.5
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:221 +0x41e
       
       goroutine 999 [chan receive, 29 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3.5(0xc00064a300)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:244 +0x48b
       testing.tRunner(0xc00064a300, 0xb45400)
       	/opt/golang/go1.15/src/testing/testing.go:1108 +0xef
       created by testing.(*T).Run
       	/opt/golang/go1.15/src/testing/testing.go:1159 +0x386
       
       goroutine 981 [chan receive, 29 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3.5.1(0xcd67c0, 0xc0004a0058)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:204 +0x33
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.bootstrapConnections.func1
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection_test.go:888 +0x52
       
       goroutine 975 [chan receive, 29 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestPool.func3.5.1(0xcd67c0, 0xc000586040)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool_test.go:204 +0x33
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.bootstrapConnections.func1
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection_test.go:888 +0x52
       
       goroutine 995 [IO wait, 29 minutes]:
       internal/poll.runtime_pollWait(0x7f48906fcb18, 0x72, 0x0)
       	/opt/golang/go1.15/src/runtime/netpoll.go:220 +0x55
       internal/poll.(*pollDesc).wait(0xc00033ac18, 0x72, 0x0, 0x0, 0xb1723a)
       	/opt/golang/go1.15/src/internal/poll/fd_poll_runtime.go:87 +0x45
       internal/poll.(*pollDesc).waitRead(...)
       	/opt/golang/go1.15/src/internal/poll/fd_poll_runtime.go:92
       internal/poll.(*FD).Accept(0xc00033ac00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
       	/opt/golang/go1.15/src/internal/poll/fd_unix.go:394 +0x1fc
       net.(*netFD).accept(0xc00033ac00, 0x37e11d600, 0x0, 0x0)
       	/opt/golang/go1.15/src/net/fd_unix.go:172 +0x45
       net.(*TCPListener).accept(0xc0004a66c0, 0xc000082f58, 0xc000082f60, 0x10)
       	/opt/golang/go1.15/src/net/tcpsock_posix.go:139 +0x32
       net.(*TCPListener).Accept(0xc0004a66c0, 0xc0003bc5e0, 0xcd67c0, 0xc0005060f8, 0x0)
       	/opt/golang/go1.15/src/net/tcpsock.go:261 +0x65
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.bootstrapConnections.func1(0x3, 0xcd09c0, 0xc0004a66c0, 0xc00064a180, 0xc0003bc5e0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection_test.go:884 +0x82
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.bootstrapConnections
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection_test.go:882 +0x126
       
       goroutine 12105590 [chan send, 12 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.runCMAPTest.func4.1(0xc00058af00)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/CMAP_spec_test.go:116 +0x45
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).makeNewConnection(0xc0004c40e0, 0x0, 0xc00035d900, 0xcd1c40, 0xc000026098, 0x0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:283 +0x370
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).connectionInitFunc(0xc0004c40e0, 0xaf8b01, 0xc0003c4320)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:124 +0x2f
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*resourcePool).add(0xc0004c4150, 0x0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/resource_pool.go:102 +0xeb
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*resourcePool).Maintain(0xc0004c4150)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/resource_pool.go:210 +0x10d
       created by time.goFunc
       	/opt/golang/go1.15/src/time/sleep.go:167 +0x45
       
       goroutine 12105596 [chan send, 12 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.runCMAPTest.func4.1(0xc00080e480)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/CMAP_spec_test.go:116 +0x45
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).clear(0xc0004c40e0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:550 +0xc2
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*Server).ProcessHandshakeError(0xc0004c20f0, 0xcc8120, 0xc00080e440, 0x12)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/server.go:285 +0x151
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*connection).processInitializationError(0xc00035d680, 0xcc73e0, 0xc00029e320)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection.go:106 +0xfb
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*connection).connect(0xc00035d680, 0xcd1c00, 0xc00058af80)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection.go:142 +0xb25
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).connectionInitFunc
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:129 +0x8d
       
       goroutine 12105597 [chan send, 12 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.runCMAPTest.func4.1(0xc0007ea580)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/CMAP_spec_test.go:116 +0x45
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).clear(0xc0004c40e0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:550 +0xc2
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*Server).ProcessHandshakeError(0xc0004c20f0, 0xcc8120, 0xc0007ea540, 0x12)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/server.go:285 +0x151
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*connection).processInitializationError(0xc00035d900, 0xcc73e0, 0xc000698000)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection.go:106 +0xfb
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*connection).connect(0xc00035d900, 0xcd1c00, 0xc00058afc0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/connection.go:142 +0xb25
       created by go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).connectionInitFunc
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:129 +0x8d
       
       goroutine 20212540 [runnable]:
       net.(*netFD).connect.func2(0xcd1c00, 0xc00080e240, 0xc0004fe000, 0xc000756060, 0xc000756000)
       	/opt/golang/go1.15/src/net/fd_unix.go:117
       created by net.(*netFD).connect
       	/opt/golang/go1.15/src/net/fd_unix.go:117 +0x234
       
       goroutine 3988045 [chan send, 23 minutes]:
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.TestCMAPProse.func1.2(0xc000691b80)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/cmap_prose_test.go:37 +0xce
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).makeNewConnection(0xc000390150, 0x44530e, 0xc00016fee8, 0x46aa80, 0xc00016ff30, 0xc00016ff38)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:283 +0x370
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).connectionInitFunc(0xc000390150, 0x9c30fa, 0xc000000008)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/pool.go:124 +0x2f
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*resourcePool).add(0xc0003901c0, 0x0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/resource_pool.go:102 +0xeb
       go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*resourcePool).Maintain(0xc0003901c0)
       	/data/mci/0f5533bdae7b8e1e5c636608be56dee0/src/go.mongodb.org/mongo-driver/x/mongo/driver/topology/resource_pool.go:210 +0x10d
       created by time.goFunc
       	/opt/golang/go1.15/src/time/sleep.go:167 +0x45
       FAIL	go.mongodb.org/mongo-driver/x/mongo/driver/topology	1800.012s
       FAIL
      

            Assignee:
            isabella.siu@mongodb.com Isabella Siu (Inactive)
            Reporter:
            kevin.albertson@mongodb.com Kevin Albertson
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: