[GODRIVER-1875] Investigate frequent TestPool test timeout Created: 05/Feb/21  Updated: 28/Oct/23  Resolved: 19/Feb/21

Status: Closed
Project: Go Driver
Component/s: Testing
Affects Version/s: None
Fix Version/s: 1.4.7

Type: Task Priority: Major - P3
Reporter: Kevin Albertson Assignee: Isabella Siu (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

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



 Comments   
Comment by Githook User [ 19/Feb/21 ]

Author:

{'name': 'Isabella Siu', 'email': 'isabella.siu@mongodb.com', 'username': 'iwysiu'}

Message: GODRIVER-1875 reduce TestPool test timeout (#582)
Branch: release/1.4
https://github.com/mongodb/mongo-go-driver/commit/d07cbc8525b3ccf1248c6afaa5870f8ce14cd1dd

Comment by Githook User [ 19/Feb/21 ]

Author:

{'name': 'Isabella Siu', 'email': 'isabella.siu@mongodb.com', 'username': 'iwysiu'}

Message: GODRIVER-1875 reduce TestPool test timeout (#582)
Branch: release/1.5
https://github.com/mongodb/mongo-go-driver/commit/07b0039a0178a5298e3fde2f9b6d9fa8c8b3ed6a

Comment by Githook User [ 19/Feb/21 ]

Author:

{'name': 'Isabella Siu', 'email': 'isabella.siu@mongodb.com', 'username': 'iwysiu'}

Message: GODRIVER-1875 reduce TestPool test timeout (#582)
Branch: master
https://github.com/mongodb/mongo-go-driver/commit/759959eb9e3b1254fced393700548b3b4644dd05

Generated at Thu Feb 08 08:37:19 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.