Uploaded image for project: 'Java Driver'
  1. Java Driver
  2. JAVA-3970

Investigate change streams test time out

    XMLWordPrintable

    Details

    • Type: Task
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: None
    • Fix Version/s: None
    • Labels:
      None

      Description

      One example: https://evergreen.mongodb.com/task/mongo_java_driver_tests_jdk_secure__version~latest_os~linux_topology~replicaset_auth~auth_ssl~ssl_jdk~jdk11_test_017bf9a94398abf40ffbd33de51cbbb0d7e16e47_21_01_27_02_36_05

      [2021/01/27 02:49:50.685] com.mongodb.reactivestreams.client.ChangeStreamsTest > shouldPassAllOutcomes[change-streams-resume-errorLabels.json: change stream resumes after NotMasterOrSecondary] STANDARD_OUT
      [2021/01/27 02:49:50.685]     02:49:50.645 [async-channel-group-27-handler-executor] INFO  org.mongodb.driver.connection - Closed connection [connectionId{localValue:334, serverValue:1758}] to localhost:27018 because the pool has been closed.
      [2021/01/27 02:49:50.685]     02:49:50.668 [Test worker] INFO  org.mongodb.driver.cluster - Cluster created with settings {hosts=[localhost:27017, localhost:27018, localhost:27019], mode=MULTIPLE, requiredClusterType=REPLICA_SET, serverSelectionTimeout='30000 ms', requiredReplicaSetName='repl0'}
      [2021/01/27 02:49:50.685]     02:49:50.668 [Test worker] INFO  org.mongodb.driver.cluster - Adding discovered server localhost:27017 to client view of cluster
      [2021/01/27 02:49:50.685]     02:49:50.672 [Test worker] INFO  org.mongodb.driver.cluster - Adding discovered server localhost:27018 to client view of cluster
      [2021/01/27 02:49:50.685]     02:49:50.675 [Test worker] INFO  org.mongodb.driver.cluster - Adding discovered server localhost:27019 to client view of cluster
      [2021/01/27 02:49:50.785]     02:49:50.701 [Test worker] INFO  org.mongodb.driver.cluster - No server chosen by com.mongodb.reactivestreams.client.internal.ClientSessionHelper$$Lambda$279/0x0000000800426c40@27ff8323 from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=localhost:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=localhost:27018, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=localhost:27019, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
      [2021/01/27 02:49:50.785]     02:49:50.721 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27017] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:335, serverValue:1199}] to localhost:27017
      [2021/01/27 02:49:50.785]     02:49:50.721 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27017] INFO  org.mongodb.driver.cluster - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=12, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=49290816, setName='repl0', canonicalAddress=localhost:27017, hosts=[localhost:27018, localhost:27017, localhost:27019], passives=[], arbiters=[], primary='localhost:27018', tagSet=TagSet{[Tag{name='dc', value='ny'}, Tag{name='ordinal', value='one'}]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6010d2a68b46ff3d4e96958d, counter=25}, lastWriteDate=Wed Jan 27 02:49:50 UTC 2021, lastUpdateTimeNanos=2353866285536}
      [2021/01/27 02:49:50.785]     02:49:50.727 [cluster-rtt-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27017] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:336, serverValue:1200}] to localhost:27017
      [2021/01/27 02:49:50.785]     02:49:50.728 [cluster-6010d4ce23e14c2f2679ad98] INFO  org.mongodb.driver.cluster - No server chosen by ReadPreferenceServerSelector{readPreference=primary} from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=localhost:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=12, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=49290816, setName='repl0', canonicalAddress=localhost:27017, hosts=[localhost:27018, localhost:27017, localhost:27019], passives=[], arbiters=[], primary='localhost:27018', tagSet=TagSet{[Tag{name='dc', value='ny'}, Tag{name='ordinal', value='one'}]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6010d2a68b46ff3d4e96958d, counter=25}, lastWriteDate=Wed Jan 27 02:49:50 UTC 2021, lastUpdateTimeNanos=2353866285536}, ServerDescription{address=localhost:27018, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=localhost:27019, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
      [2021/01/27 02:49:50.785]     02:49:50.747 [cluster-rtt-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27019] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:340, serverValue:1009}] to localhost:27019
      [2021/01/27 02:49:50.785]     02:49:50.747 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27019] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:339, serverValue:1008}] to localhost:27019
      [2021/01/27 02:49:50.785]     02:49:50.748 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27019] INFO  org.mongodb.driver.cluster - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27019, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=12, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=53309211, setName='repl0', canonicalAddress=localhost:27019, hosts=[localhost:27018, localhost:27017, localhost:27019], passives=[], arbiters=[], primary='localhost:27018', tagSet=TagSet{[]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6010d2be345c267c5228cf24, counter=4}, lastWriteDate=Wed Jan 27 02:49:50 UTC 2021, lastUpdateTimeNanos=2353893211234}
      [2021/01/27 02:49:50.785]     02:49:50.752 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27018] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:337, serverValue:1759}] to localhost:27018
      [2021/01/27 02:49:50.785]     02:49:50.752 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Monitor thread successfully connected to server with description ServerDescription{address=localhost:27018, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=12, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=76410134, setName='repl0', canonicalAddress=localhost:27018, hosts=[localhost:27018, localhost:27017, localhost:27019], passives=[], arbiters=[], primary='localhost:27018', tagSet=TagSet{[Tag{name='dc', value='pa'}, Tag{name='ordinal', value='two'}]}, electionId=7fffffff0000000000000004, setVersion=1, topologyVersion=TopologyVersion{processId=6010d2b8922ef809c0bb0539, counter=8}, lastWriteDate=Wed Jan 27 02:49:50 UTC 2021, lastUpdateTimeNanos=2353897388116}
      [2021/01/27 02:49:50.785]     02:49:50.752 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Setting max election id to 7fffffff0000000000000004 from replica set primary localhost:27018
      [2021/01/27 02:49:50.785]     02:49:50.752 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Setting max set version to 1 from replica set primary localhost:27018
      [2021/01/27 02:49:50.785]     02:49:50.752 [cluster-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27018] INFO  org.mongodb.driver.cluster - Discovered replica set primary localhost:27018
      [2021/01/27 02:49:50.785]     02:49:50.758 [cluster-rtt-ClusterId{value='6010d4ce23e14c2f2679ad98', description='null'}-localhost:27018] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:338, serverValue:1760}] to localhost:27018
      [2021/01/27 02:49:50.885]     02:49:50.822 [async-channel-group-28-handler-executor] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:341, serverValue:1761}] to localhost:27018
      [2021/01/27 02:49:51.065]     02:49:50.893 [async-channel-group-28-handler-executor] INFO  org.mongodb.driver.connection - Opened connection [connectionId{localValue:342, serverValue:1762}] to localhost:27018
      [2021/01/27 03:37:49.990] Command stopped early: context canceled
      [2021/01/27 03:37:50.023] Running task-timeout commands.
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned Unassigned
              Reporter:
              jeff.yemin Jeffrey Yemin
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: