Closed LiuZHolmes closed 2 years ago
@LiuZHolmes .. hmm.. seems mongodb did something after "wiredtiger_open" ..
is this the long running example?
@LiuZHolmes .. hmm.. seems mongodb did something after "wiredtiger_open" ..
is this the long running example?
Yes, the test kept waiting at this log.
@LiuZHolmes .. is there any special config for your mongodb? i dont know why mongodb stalls after wiredtiger_open for 25s..
can you provide a log where it does not stick?
@LiuZHolmes .. is there any special config for your mongodb? i dont know why mongodb stalls after wiredtiger_open for 25s..
can you provide a log where it does not stick?
We don't have any special config and in fact it stalls like forever. When this occurs, we can do nothing but retry the test job. Normal log like:
2022-05-23 00:38:32.805 INFO 72 --- [ main] o.a.c.c.C.[Tomcat-1].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2022-05-23 00:38:32.806 INFO 72 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1501 ms
2022-05-23 00:38:33.429 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : note: noprealloc may hurt performance in many applications
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] MongoDB starting : pid=282 port=44869 dbpath=/tmp/embedmongo-db-6d230a03-3ace-4dc3-9632-74bc62fc64ce 64-bit host=runner-8wxs7zsz-project-52-concurrent-0
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] db version v3.5.5
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] git version: 98515c812b6fa893613f063dae568ff8319cbfbd
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] allocator: tcmalloc
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] modules: none
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] build environment:
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] distarch: x86_64
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] target_arch: x86_64
2022-05-23 00:38:33.444 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.443+0000 I CONTROL [initandlisten] options: { net: { bindIp: "127.0.0.1", http: { enabled: false }, port: 44869 }, security: { authorization: "disabled" }, storage: { dbPath: "/tmp/embedmongo-db-6d230a03-3ace-4dc3-9632-74bc62fc64ce", journal: { enabled: false }, mmapv1: { preallocDataFiles: false, smallFiles: true }, syncPeriodSecs: 0.0 } }
2022-05-23 00:38:33.453 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.448+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=6723M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=0,log_size=2GB),statistics_log=(wait=0),verbose=(recovery_progress),,log=(enabled=false),
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.835+0000 W STORAGE [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.835+0000 I CONTROL [initandlisten]
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.835+0000 I CONTROL [initandlisten] ** NOTE: This is a development version (3.5.5) of MongoDB.
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.835+0000 I CONTROL [initandlisten] ** Not recommended for production.
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.835+0000 I CONTROL [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.835+0000 I CONTROL [initandlisten]
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten]
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten]
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2022-05-23 00:38:33.836 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.836+0000 I CONTROL [initandlisten]
2022-05-23 00:38:33.959 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:33.958+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/tmp/embedmongo-db-6d230a03-3ace-4dc3-9632-74bc62fc64ce/diagnostic.data'
2022-05-23 00:38:34.196 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.195+0000 I INDEX [initandlisten] build index on: admin.system.version properties: { v: 2, key: { version: 1 }, name: "incompatible_with_version_32", ns: "admin.system.version" }
2022-05-23 00:38:34.196 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.195+0000 I INDEX [initandlisten] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2022-05-23 00:38:34.206 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.206+0000 I INDEX [initandlisten] build index done. scanned 0 total records. 0 secs
2022-05-23 00:38:34.207 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.207+0000 I COMMAND [initandlisten] setting featureCompatibilityVersion to 3.4
2022-05-23 00:38:34.207 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.207+0000 I NETWORK [thread1] waiting for connections on port 44869
2022-05-23 00:38:34.210 INFO 72 --- [ main] d.f.embed.mongo.MongodExecutable : start MongodConfig{version=Version{3.5.5}, timeout=de.flapdoodle.embed.mongo.config.Timeout@1a7186ef, net=de.flapdoodle.embed.mongo.config.Net@5f6da867, cmdOptions=MongoCmdOptions{syncDelay=0, useDefaultSyncDelay=false, isVerbose=false, useNoPrealloc=true, useSmallFiles=true, useNoJournal=true, enableTextSearch=false, auth=false, master=false}, password=, userName=, replication=de.flapdoodle.embed.mongo.config.Storage@1227013b, isConfigServer=false, isShardServer=false, processListener=de.flapdoodle.embed.mongo.config.processlistener.NoopProcessListener@53a95744, params={}, args={}, pidFile=mongod.pid, supportConfig=de.flapdoodle.embed.mongo.config.SupportConfig@45f9f520}
2022-05-23 00:38:34.294 INFO 72 --- [ main] org.mongodb.driver.cluster : Cluster created with settings {hosts=[localhost:44869], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms'}
2022-05-23 00:38:34.317 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.316+0000 I NETWORK [thread1] connection accepted from 127.0.0.1:37982 #1 (1 connection now open)
2022-05-23 00:38:34.318 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.317+0000 I NETWORK [conn1] received client metadata from 127.0.0.1:37982 conn1: { driver: { name: "mongo-java-driver|sync|spring-boot", version: "4.4.2" }, os: { type: "Linux", name: "Linux", architecture: "amd64", version: "3.10.0-1160.36.2.el7.x86_64" }, platform: "Java/Oracle Corporation/11.0.10+9" }
2022-05-23 00:38:34.318 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.318+0000 I NETWORK [thread1] connection accepted from 127.0.0.1:37984 #2 (2 connections now open)
2022-05-23 00:38:34.318 INFO 72 --- [ Thread-10] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:38:34.318+0000 I NETWORK [conn2] received client metadata from 127.0.0.1:37984 conn2: { driver: { name: "mongo-java-driver|sync|spring-boot", version: "4.4.2" }, os: { type: "Linux", name: "Linux", architecture: "amd64", version: "3.10.0-1160.36.2.el7.x86_64" }, platform: "Java/Oracle Corporation/11.0.10+9" }
2022-05-23 00:38:34.343 INFO 72 --- [localhost:44869] org.mongodb.driver.connection : Opened connection [connectionId{localValue:4, serverValue:2}] to localhost:44869
2022-05-23 00:38:34.343 INFO 72 --- [localhost:44869] org.mongodb.driver.cluster : Monitor thread successfully connected to server with description ServerDescription{address=localhost:44869, type=STANDALONE, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=5, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=null, roundTripTimeNanos=2760062}
2022-05-23 00:38:34.349 INFO 72 --- [localhost:44869] org.mongodb.driver.connection : Opened connection [connectionId{localValue:3, serverValue:1}] to localhost:44869
[Log About Running Test Omitted]
2022-05-23 00:39:13.365 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.365+0000 I NETWORK [thread1] connection accepted from 127.0.0.1:36170 #3 (3 connections now open)
2022-05-23 00:39:13.531 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.530+0000 I - [conn2] end connection 127.0.0.1:36074 (3 connections now open)
2022-05-23 00:39:13.531 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.531+0000 I - [conn1] end connection 127.0.0.1:36072 (2 connections now open)
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.652+0000 I COMMAND [conn3] terminating, shutdown command received
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.652+0000 I NETWORK [conn3] shutdown: going to close listening sockets...
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.652+0000 I NETWORK [conn3] closing listening socket: 7
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.652+0000 I NETWORK [conn3] closing listening socket: 8
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.652+0000 I NETWORK [conn3] removing socket file: /tmp/mongodb-40338.sock
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.653+0000 I NETWORK [conn3] shutdown: going to flush diaglog...
2022-05-23 00:39:13.653 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.653+0000 I FTDC [conn3] Shutting down full-time diagnostic data capture
2022-05-23 00:39:13.655 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.654+0000 I STORAGE [conn3] WiredTigerKVEngine shutting down
2022-05-23 00:39:13.910 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.909+0000 I STORAGE [conn3] shutdown: removing fs lock...
2022-05-23 00:39:13.910 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.909+0000 I CONTROL [conn3] now exiting
2022-05-23 00:39:13.910 INFO 72 --- [ Thread-4] o.s.b.a.mongo.embedded.EmbeddedMongo : 2022-05-23T00:39:13.909+0000 I CONTROL [conn3] shutting down with code:0
@LiuZHolmes can you see if you can add a sample to this project: https://github.com/flapdoodle-oss/de.flapdoodle.embed.mongo.canary
@LiuZHolmes .. is this still an issue? i will close this .. reopen if needed.
Facing the same issue in MacOs M1 Chip
It was working fine till last week Suddenly it is getting hung up for infinite time at
[mongod output] 2023-07-17T17:59:02.944+0530 I INDEX [LogicalSessionCacheRefresh] building index using bulk method; build may temporarily use up to 500 megabytes of RAM [mongod output] 2023-07-17T17:59:03.014+0530 I INDEX [LogicalSessionCacheRefresh] build index done. scanned 0 total records. 0 secs [mongod output] 2023-07-17T17:59:03.014+0530 I COMMAND [LogicalSessionCacheRefresh] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], $db: "config" } numYields:0 reslen:114 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { W: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 2174ms [mongod output] 2023-07-17 17:59:37.535 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : note: noprealloc may hurt performance in many applications 2023-07-17 17:59:37.536 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.536+0530 I CONTROL machdep.cpu.extfeatures unavailable 2023-07-17 17:59:37.540 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.540+0530 I CONTROL [initandlisten] MongoDB starting : pid=2222 port=55782 dbpath=/var/folders/s9/8g2300wj1bj4r9p44ljj4z800000gq/T/embedmongo-db-fc3a0c77-4e20-4afe-aac7-a683a0f3b24c 64-bit host=197NODMB36475.local 2023-07-17 17:59:37.540 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.540+0530 I CONTROL [initandlisten] db version v3.0.0 2023-07-17 17:59:37.540 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.540+0530 I CONTROL [initandlisten] git version: a841fd6394365954886924a35076691b4d149168 2023-07-17 17:59:37.540 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.540+0530 I CONTROL [initandlisten] build info: Darwin bs-osx108-1 12.5.0 Darwin Kernel Version 12.5.0: Sun Sep 29 13:33:47 PDT 2013; root:xnu-2050.48.12~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49 2023-07-17 17:59:37.540 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.540+0530 I CONTROL [initandlisten] allocator: system 2023-07-17 17:59:37.541 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.540+0530 I CONTROL [initandlisten] options: { net: { bindIp: "127.0.0.1", http: { enabled: false }, port: 55782 }, security: { authorization: "disabled" }, storage: { dbPath: "/var/folders/s9/8g2300wj1bj4r9p44ljj4z800000gq/T/embedmongo-db-fc3a0c77-4e20-4afe-aac7-a683a0f3b24c", journal: { enabled: false }, mmapv1: { preallocDataFiles: false, smallFiles: true }, syncPeriodSecs: 0.0 } } 2023-07-17 17:59:37.582 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.582+0530 I STORAGE [DataFileSync] warning: --syncdelay 0 is not recommended and can have strange performance 2023-07-17 17:59:37.615 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.615+0530 I INDEX [initandlisten] allocating new ns file /var/folders/s9/8g2300wj1bj4r9p44ljj4z800000gq/T/embedmongo-db-fc3a0c77-4e20-4afe-aac7-a683a0f3b24c/local.ns, filling with zeroes... 2023-07-17 17:59:37.768 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.768+0530 I STORAGE [FileAllocator] allocating new datafile /var/folders/s9/8g2300wj1bj4r9p44ljj4z800000gq/T/embedmongo-db-fc3a0c77-4e20-4afe-aac7-a683a0f3b24c/local.0, filling with zeroes... 2023-07-17 17:59:37.768 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.768+0530 I STORAGE [FileAllocator] creating directory /var/folders/s9/8g2300wj1bj4r9p44ljj4z800000gq/T/embedmongo-db-fc3a0c77-4e20-4afe-aac7-a683a0f3b24c/_tmp 2023-07-17 17:59:37.794 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.794+0530 I STORAGE [FileAllocator] done allocating datafile /var/folders/s9/8g2300wj1bj4r9p44ljj4z800000gq/T/embedmongo-db-fc3a0c77-4e20-4afe-aac7-a683a0f3b24c/local.0, size: 16MB, took 0.025 secs 2023-07-17 17:59:37.811 INFO 1920 --- [ Thread-36] o.s.b.a.mongo.embedded.EmbeddedMongo : 2023-07-17T17:59:37.811+0530 I NETWORK [initandlisten] waiting for connections on port 55782
@aayushmall which spring version do you use?
Facing same issue with Springboot 2.6.3 jdk 11
@PradeepaSoundar do you have any logging? Stacktrace?
@PradeepaSoundar please open an new issue and don't write comments on a closed one:)
When running mongo test in SpringBoot 2.6.6, we found the test stuck on 'waiting for connections on port' for a very lone time. But sometime it runs successfully without sticking. Example log: