[SERVER-37318] POD can't start in a kubernetes replicaset Created: 26/Sep/18  Updated: 27/Dec/18  Resolved: 25/Oct/18

Status: Closed
Project: Core Server
Component/s: Replication, Stability, WiredTiger
Affects Version/s: 4.0.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Mauro Tintori Assignee: Kelsey Schubert
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

Hi,

we have an environment made up of at least 3 preemptible nodes (max 5 nodes) running with Kubernetes on Google Cloud Platform.

Over that we were working with a MongoDB replicaset made up of 3 PODs, version 3.6 docker image.

Now we are testing MongoDB version 4.0.2 docker image.

Yesterday we done a lot of tests without problems, also with different resources (CPU and memory limits) and different Kubernetes node types: these operations required to update, recreate and move PODs from nodepools and other ones. All tests yesterday was ok.

Today the first POD go always to CrashLoopBackOff, others 2 PODs are secondary.

In the logs we found this:

2018-09-26T08:09:00.028+0000 I CONTROL [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2018-09-26T08:09:00.028+0000 I CONTROL [main] note: noprealloc may hurt performance in many applications
2018-09-26T08:09:00.034+0000 I CONTROL [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host="xxx"
2018-09-26T08:09:00.034+0000 I CONTROL [initandlisten] db version v4.0.2
2018-09-26T08:09:00.034+0000 I CONTROL [initandlisten] git version: fc1573ba18aee42f97a3bb13b67af7d837826b47
2018-09-26T08:09:00.034+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.2g 1 Mar 2016
2018-09-26T08:09:00.034+0000 I CONTROL [initandlisten] allocator: tcmalloc
2018-09-26T08:09:00.035+0000 I CONTROL [initandlisten] modules: none
2018-09-26T08:09:00.035+0000 I CONTROL [initandlisten] build environment:
2018-09-26T08:09:00.035+0000 I CONTROL [initandlisten] distmod: ubuntu1604
2018-09-26T08:09:00.035+0000 I CONTROL [initandlisten] distarch: x86_64
2018-09-26T08:09:00.035+0000 I CONTROL [initandlisten] target_arch: x86_64
2018-09-26T08:09:00.035+0000 I CONTROL [initandlisten] options: { net:

{ bindIp: "0.0.0.0" }

, replication: { replSet: "xxx" }, storage: { mmapv1:

{ preallocDataFiles: false, smallFiles: true }

} }
2018-09-26T08:09:00.035+0000 W STORAGE [initandlisten] Detected unclean shutdown - /data/db/mongod.lock is not empty.
2018-09-26T08:09:00.035+0000 I STORAGE [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2018-09-26T08:09:00.035+0000 W STORAGE [initandlisten] Recovering data from the last clean checkpoint.
2018-09-26T08:09:00.035+0000 I STORAGE [initandlisten]
2018-09-26T08:09:00.035+0000 I STORAGE [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2018-09-26T08:09:00.035+0000 I STORAGE [initandlisten] ** See http://dochub.mongodb.org/core/prodnotes-filesystem
2018-09-26T08:09:00.035+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7010M,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),statistics_log=(wait=0),verbose=(recovery_progress),
2018-09-26T08:09:00.920+0000 I STORAGE [initandlisten] WiredTiger message [1537949340:920297][1:0x7f093a5bca00], txn-recover: Main recovery loop: starting at 358/256
2018-09-26T08:09:00.920+0000 I STORAGE [initandlisten] WiredTiger message [1537949340:920849][1:0x7f093a5bca00], txn-recover: Recovering log 358 through 359
2018-09-26T08:09:01.018+0000 I STORAGE [initandlisten] WiredTiger message [1537949341:18578][1:0x7f093a5bca00], txn-recover: Recovering log 359 through 359
2018-09-26T08:09:01.113+0000 I STORAGE [initandlisten] WiredTiger message [1537949341:113092][1:0x7f093a5bca00], txn-recover: Set global recovery timestamp: 5baa520500000001
2018-09-26T08:09:01.127+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(1537888773, 1)
2018-09-26T08:09:01.127+0000 I STORAGE [initandlisten] Triggering the first stable checkpoint. Initial Data: Timestamp(1537888773, 1) PrevStable: Timestamp(0, 0) CurrStable: Timestamp(1537888773, 1)
2018-09-26T08:09:01.336+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2018-09-26T08:09:01.337+0000 I STORAGE [initandlisten] The size storer reports that the oplog contains 18753157 records totaling to 4939639735 bytes
2018-09-26T08:09:01.337+0000 I STORAGE [initandlisten] Sampling from the oplog between Sep 25 12:59:40:46211 and Sep 25 15:18:21:1 to determine where to place markers for truncation
2018-09-26T08:09:01.337+0000 I STORAGE [initandlisten] Taking 993 samples and assuming that each section of oplog contains approximately 188664 records totaling to 49694682 bytes
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 12:59:53:9643
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:00:07:2576
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:03:27:27632
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:03:44:4341
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:03:47:47383
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:03:51:33808
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:03:55:21357
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:03:59:7729
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:04:32:23512
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:05:40:4956
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:05:45:5332
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:05:59:23243
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:06:03:28610
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:06:07:34419
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:06:11:38253
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:06:15:39932
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:06:32:45647
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:48:49:15931
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:48:55:2698
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:00:30146
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:06:26530
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:12:18860
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:18:12411
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:29:10614
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:35:1915
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:40:33321
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:46:28232
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:52:25477
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:49:58:21096
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:50:25:736
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:50:30:35534
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:50:36:30659
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:50:42:28853
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:50:48:25546
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 13:51:23:25962
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:17:10717
2018-09-26T08:09:01.405+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:23:19423
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:35:35771
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:41:6549
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:45:7728
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:49:5615
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:53:3866
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:12:57:11428
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:13:01:5984
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:15:1151
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:19:1424
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:22:32516
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:26:26611
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:30:29725
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:34:26472
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:38:20402
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:42:21922
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:17:46:20812
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:29:35488
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:33:34887
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:37:28908
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:41:28395
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:45:32895
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:50:794
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:53:32253
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:20:57:32519
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:31:04:10062
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:34:29:10436
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:34:36:14880
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:34:46:5600
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:34:57:8110
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:35:08:9095
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:35:19:7910
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:35:59:12359
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:36:10:12750
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:36:21:14260
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:36:32:18461
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:36:43:15327
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:36:54:10347
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:37:11:6788
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:43:17:17640
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:43:28:16675
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:43:40:368
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:43:51:2300
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:44:02:2576
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:46:34:7711
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:46:45:13268
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:46:56:18566
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:47:07:16849
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:47:18:18226
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 14:47:30:1623
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:10:46:9019
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:11:09:4009
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:11:32:6258
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:11:57:5684
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:12:20:6362
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:12:44:1273
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:13:07:3997
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:13:35:2151
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:14:59:7291
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:15:27:5583
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:15:50:6116
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:16:12:4857
2018-09-26T08:09:01.406+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 25 15:16:32:351
2018-09-26T08:09:01.421+0000 W STORAGE [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger
2018-09-26T08:09:01.421+0000 I CONTROL [initandlisten]
2018-09-26T08:09:01.421+0000 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2018-09-26T08:09:01.421+0000 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2018-09-26T08:09:01.421+0000 I CONTROL [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2018-09-26T08:09:01.422+0000 I CONTROL [initandlisten]
2018-09-26T08:09:01.422+0000 I CONTROL [initandlisten]
2018-09-26T08:09:01.422+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2018-09-26T08:09:01.422+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2018-09-26T08:09:01.422+0000 I CONTROL [initandlisten]
2018-09-26T08:09:01.720+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
2018-09-26T08:09:01.723+0000 I REPL [initandlisten] Rollback ID is 28
2018-09-26T08:09:01.723+0000 I REPL [initandlisten] Recovering from stable timestamp: Timestamp(1537888773, 1) (top of oplog: { ts: Timestamp(1537888701, 1), t: 27 }, appliedThrough: { ts: Timestamp(1537888773, 1), t: 28 }, TruncateAfter: Timestamp(0, 0))
2018-09-26T08:09:01.723+0000 I REPL [initandlisten] Starting recovery oplog application at the stable timestamp: Timestamp(1537888773, 1)
2018-09-26T08:09:01.723+0000 F REPL [initandlisten] Applied op { : Timestamp(1537888773, 1) } not found. Top of oplog is { : Timestamp(1537888701, 1) }.
2018-09-26T08:09:01.723+0000 F - [initandlisten] Fatal Assertion 40313 at src/mongo/db/repl/replication_recovery.cpp 345
2018-09-26T08:09:01.723+0000 F - [initandlisten]

***aborting after fassert() failure

 

 We can't access to the POD so we can read files or db.

How can we resolve our problem?

Thank you

Mauro



 Comments   
Comment by Joachim Aumann [ 27/Dec/18 ]

I have the same issue. Described in this stackoverflow post: https://stackoverflow.com/questions/53835384/mongodb-statefulset-on-kubernetes-is-not-working-anymore-after-kubernetes-update

 

Comment by Rakesh [ 22/Dec/18 ]

I have two kubernetes pods with volumes attached to the pods. I am trying to bring up new set of pods with same volumes mounted but it fails with the above error message

Comment by Rakesh [ 22/Dec/18 ]

2018-12-21T11:16:58.229+0000 I STORAGE  [initandlisten] Starting OplogTruncaterThread local.oplog.rs

2018-12-21T11:16:58.229+0000 I STORAGE  [initandlisten] The size storer reports that the oplog contains 2025121 records totaling to 604496199 bytes

2018-12-21T11:16:58.229+0000 I STORAGE  [initandlisten] Sampling from the oplog between Dec 18 11:39:22:1 and Dec 21 05:36:47:1 to determine where to place markers for truncation

2018-12-21T11:16:58.229+0000 I STORAGE  [initandlisten] Taking 355 samples and assuming that each section of oplog contains approximately 57012 records totaling to 17018013 bytes

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:40:54:18

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:46:41:36

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:49:47:2813

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:49:59:4034

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:50:13:2095

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:50:26:492

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:50:39:2504

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:50:52:3292

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 11:51:07:138

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 12:44:45:5

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 12:49:59:1376

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 12:50:14:1380

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 12:50:29:731

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 12:50:43:2800

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 14:00:06:712

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 18 14:00:14:7234

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 00:00:32:278

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 00:08:41:2867

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 00:09:00:524

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 00:09:18:898

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 00:09:36:2022

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 04:00:10:1282

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 19 19:00:05:26

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 20 00:08:05:2452

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 20 00:08:24:2759

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 20 00:08:43:2092

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 20 00:09:02:4478

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 20 00:15:15:1648

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 20 16:45:05:30

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 21 00:00:15:2940

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 21 00:08:57:1666

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 21 00:09:21:296

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 21 00:09:41:2525

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 21 00:10:04:709

2018-12-21T11:16:58.254+0000 I STORAGE  [initandlisten] Placing a marker at optime Dec 21 00:15:14:1988

2018-12-21T11:16:58.268+0000 W STORAGE  [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger

2018-12-21T11:16:58.268+0000 I CONTROL  [initandlisten]

2018-12-21T11:16:58.268+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.

2018-12-21T11:16:58.268+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.

2018-12-21T11:16:58.268+0000 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.

2018-12-21T11:16:58.268+0000 I CONTROL  [initandlisten]

2018-12-21T11:16:58.880+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'

2018-12-21T11:16:58.884+0000 I REPL     [initandlisten] Rollback ID is 2

2018-12-21T11:16:58.885+0000 I REPL     [initandlisten] Recovering from stable timestamp: Timestamp(1545370895, 1) (top of oplog: { ts: Timestamp(1545370607, 1), t: 8 }, appliedThrough: { ts: Timestamp(0, 0), t: -1 }, TruncateAfter: Timestamp(0, 0))

2018-12-21T11:16:58.885+0000 I REPL     [initandlisten] Starting recovery oplog application at the stable timestamp: Timestamp(1545370895, 1)

2018-12-21T11:16:58.885+0000 F REPL     [initandlisten] Applied op { : Timestamp(1545370895, 1) } not found. Top of oplog is { : Timestamp(1545370607, 1) }.

2018-12-21T11:16:58.887+0000 F -        [initandlisten] Fatal Assertion 40313 at src/mongo/db/repl/replication_recovery.cpp 361

2018-12-21T11:16:58.887+0000 F -        [initandlisten]

 

***aborting after fassert() failure

 

Comment by Rakesh [ 22/Dec/18 ]

@Mauro - Even I am facing the same issue. How did you resolve it ?

Comment by Kelsey Schubert [ 25/Oct/18 ]

Hi maurotintori,

We haven’t heard back from you for some time, so I’m going to mark this ticket as resolved. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Regards,
Kelsey

Comment by Nick Brewer [ 28/Sep/18 ]

maurotintori A resync is likely going to be the most effective way to get this node up and running again.

From the log lines provided, it appears that the node may not have been shut down properly - was there an unexpected shutdown, or was the mongod process manually killed for some reason?

-Nick

Comment by Mauro Tintori [ 28/Sep/18 ]

Hi nick,

thank you.

This is files list I can see in the dbpath:

WiredTiger
WiredTiger.lock
WiredTiger.turtle
WiredTiger.wt
WiredTigerLAS.wt
_mdb_catalog.wt
collection-0-5558028197058210355.wt
collection-100-5558028197058210355.wt
collection-102-5558028197058210355.wt
collection-105-5558028197058210355.wt
collection-110-5558028197058210355.wt
collection-118-5558028197058210355.wt
collection-120-5558028197058210355.wt
collection-123-5558028197058210355.wt
collection-127-5558028197058210355.wt
collection-133-5558028197058210355.wt
collection-135-5558028197058210355.wt
collection-139-5558028197058210355.wt
collection-14-5558028197058210355.wt
collection-142-5558028197058210355.wt
collection-145-5558028197058210355.wt
collection-149-5558028197058210355.wt
collection-15-5558028197058210355.wt
collection-155-5558028197058210355.wt
collection-159-5558028197058210355.wt
collection-164-5558028197058210355.wt
collection-166-5558028197058210355.wt
collection-17-5558028197058210355.wt
collection-172-5558028197058210355.wt
collection-178-5558028197058210355.wt
collection-181-5558028197058210355.wt
collection-187-5558028197058210355.wt
collection-19-5558028197058210355.wt
collection-190-5558028197058210355.wt
collection-196-5558028197058210355.wt
collection-198-5558028197058210355.wt
collection-2-5558028197058210355.wt
collection-200-5558028197058210355.wt
collection-205-5558028197058210355.wt
collection-21-5558028197058210355.wt
collection-24-5558028197058210355.wt
collection-26-5558028197058210355.wt
collection-28-5558028197058210355.wt
collection-30-5558028197058210355.wt
collection-33-5558028197058210355.wt
collection-4-5558028197058210355.wt
collection-43-5558028197058210355.wt
collection-45-5558028197058210355.wt
collection-48-5558028197058210355.wt
collection-51-5558028197058210355.wt
collection-55-5558028197058210355.wt
collection-58-5558028197058210355.wt
collection-6-5558028197058210355.wt
collection-62-5558028197058210355.wt
collection-65-5558028197058210355.wt
collection-67-5558028197058210355.wt
collection-73-5558028197058210355.wt
collection-76-5558028197058210355.wt
collection-79-5558028197058210355.wt
collection-8-5558028197058210355.wt
collection-81-5558028197058210355.wt
collection-83-5558028197058210355.wt
collection-85-5558028197058210355.wt
collection-88-5558028197058210355.wt
collection-90-5558028197058210355.wt
collection-92-5558028197058210355.wt
collection-94-5558028197058210355.wt
collection-96-5558028197058210355.wt
collection-98-5558028197058210355.wt
diagnostic.data
index-1-5558028197058210355.wt
index-101-5558028197058210355.wt
index-103-5558028197058210355.wt
index-104-5558028197058210355.wt
index-106-5558028197058210355.wt
index-107-5558028197058210355.wt
index-108-5558028197058210355.wt
index-109-5558028197058210355.wt
index-111-5558028197058210355.wt
index-112-5558028197058210355.wt
index-113-5558028197058210355.wt
index-114-5558028197058210355.wt
index-115-5558028197058210355.wt
index-116-5558028197058210355.wt
index-117-5558028197058210355.wt
index-119-5558028197058210355.wt
index-121-5558028197058210355.wt
index-122-5558028197058210355.wt
index-124-5558028197058210355.wt
index-125-5558028197058210355.wt
index-126-5558028197058210355.wt
index-128-5558028197058210355.wt
index-129-5558028197058210355.wt
index-130-5558028197058210355.wt
index-131-5558028197058210355.wt
index-132-5558028197058210355.wt
index-134-5558028197058210355.wt
index-136-5558028197058210355.wt
index-137-5558028197058210355.wt
index-138-5558028197058210355.wt
index-140-5558028197058210355.wt
index-141-5558028197058210355.wt
index-143-5558028197058210355.wt
index-144-5558028197058210355.wt
index-146-5558028197058210355.wt
index-147-5558028197058210355.wt
index-148-5558028197058210355.wt
index-150-5558028197058210355.wt
index-151-5558028197058210355.wt
index-152-5558028197058210355.wt
index-153-5558028197058210355.wt
index-154-5558028197058210355.wt
index-156-5558028197058210355.wt
index-157-5558028197058210355.wt
index-158-5558028197058210355.wt
index-16-5558028197058210355.wt
index-160-5558028197058210355.wt
index-161-5558028197058210355.wt
index-162-5558028197058210355.wt
index-163-5558028197058210355.wt
index-165-5558028197058210355.wt
index-167-5558028197058210355.wt
index-168-5558028197058210355.wt
index-169-5558028197058210355.wt
index-170-5558028197058210355.wt
index-171-5558028197058210355.wt
index-173-5558028197058210355.wt
index-174-5558028197058210355.wt
index-175-5558028197058210355.wt
index-176-5558028197058210355.wt
index-177-5558028197058210355.wt
index-179-5558028197058210355.wt
index-18-5558028197058210355.wt
index-180-5558028197058210355.wt
index-182-5558028197058210355.wt
index-183-5558028197058210355.wt
index-184-5558028197058210355.wt
index-185-5558028197058210355.wt
index-186-5558028197058210355.wt
index-188-5558028197058210355.wt
index-189-5558028197058210355.wt
index-191-5558028197058210355.wt
index-192-5558028197058210355.wt
index-193-5558028197058210355.wt
index-194-5558028197058210355.wt
index-195-5558028197058210355.wt
index-197-5558028197058210355.wt
index-199-5558028197058210355.wt
index-20-5558028197058210355.wt
index-201-5558028197058210355.wt
index-202-5558028197058210355.wt
index-203-5558028197058210355.wt
index-204-5558028197058210355.wt
index-206-5558028197058210355.wt
index-22-5558028197058210355.wt
index-23-5558028197058210355.wt
index-25-5558028197058210355.wt
index-27-5558028197058210355.wt
index-29-5558028197058210355.wt
index-3-5558028197058210355.wt
index-31-5558028197058210355.wt
index-32-5558028197058210355.wt
index-34-5558028197058210355.wt
index-35-5558028197058210355.wt
index-36-5558028197058210355.wt
index-37-5558028197058210355.wt
index-38-5558028197058210355.wt
index-39-5558028197058210355.wt
index-40-5558028197058210355.wt
index-41-5558028197058210355.wt
index-42-5558028197058210355.wt
index-44-5558028197058210355.wt
index-46-5558028197058210355.wt
index-47-5558028197058210355.wt
index-49-5558028197058210355.wt
index-5-5558028197058210355.wt
index-50-5558028197058210355.wt
index-52-5558028197058210355.wt
index-53-5558028197058210355.wt
index-54-5558028197058210355.wt
index-56-5558028197058210355.wt
index-57-5558028197058210355.wt
index-59-5558028197058210355.wt
index-60-5558028197058210355.wt
index-61-5558028197058210355.wt
index-63-5558028197058210355.wt
index-64-5558028197058210355.wt
index-66-5558028197058210355.wt
index-68-5558028197058210355.wt
index-69-5558028197058210355.wt
index-7-5558028197058210355.wt
index-70-5558028197058210355.wt
index-71-5558028197058210355.wt
index-72-5558028197058210355.wt
index-74-5558028197058210355.wt
index-75-5558028197058210355.wt
index-77-5558028197058210355.wt
index-78-5558028197058210355.wt
index-80-5558028197058210355.wt
index-82-5558028197058210355.wt
index-84-5558028197058210355.wt
index-86-5558028197058210355.wt
index-87-5558028197058210355.wt
index-89-5558028197058210355.wt
index-9-5558028197058210355.wt
index-91-5558028197058210355.wt
index-93-5558028197058210355.wt
index-95-5558028197058210355.wt
index-97-5558028197058210355.wt
index-99-5558028197058210355.wt
journal
lost+found
mongod.lock
sizeStorer.wt
storage.bson

All tests are made using the same set of dbpath data and we didn't try to do resync.

What do you suggest?

Thank you,

 Mauro

Comment by Nick Brewer [ 26/Sep/18 ]

maurotintori Thanks for your report. I have a few questions:

  • Your mongod appears to be configured to use the MMAP storage engine - can you confirm that your dbpath contains only WiredTiger files?
  • Was the same set of dbpath data used in all of your tests?
  • Have you tried to resync the node entirely?

-Nick

Generated at Thu Feb 08 04:45:39 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.