[SERVER-50147] Cannot start mongo after upgrading to 4.2 Created: 06/Aug/20  Updated: 24/Sep/21  Resolved: 22/Nov/20

Status: Closed
Project: Core Server
Component/s: Upgrade/Downgrade
Affects Version/s: 4.2.8
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Hussam Jarrah Assignee: Dmitry Agranat
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-52961 Fail MongoDB FCV upgrade 3.6 if local... Closed
Related
related to SERVER-30556 remove old OplogDeleteFromPoint from ... Closed
Operating System: ALL
Sprint: Repl 2020-08-24, Repl 2020-09-07, Repl 2020-09-21, Repl 2020-10-05, Repl 2020-10-19, Repl 2020-11-02, Repl 2020-11-16, Repl 2020-11-30
Participants:
Case:

 Description   

I cannot run mongod after upgrading the version from 4.0 to 4.2

Here is the full log:

 

2020-08-06T19:27:58.761+0300 I CONTROL [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2020-08-06T19:27:58.764+0300 W ASIO [main] No TransportLayer configured during NetworkInterface startup
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] MongoDB starting : pid=23491 port=27017 dbpath=/var/lib/mongodb-dir/mongodb 64-bit host=ip-10-19-2-62
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] db version v4.2.8
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] git version: 43d25964249164d76d5e04dd6cf38f6111e21f5f
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.2g 1 Mar 2016
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] allocator: tcmalloc
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] modules: none
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] build environment:
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] distmod: ubuntu1604
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] distarch: x86_64
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] target_arch: x86_64
2020-08-06T19:27:58.765+0300 I CONTROL [initandlisten] options: { net:

{ bindIp: "127.0.0.1", port: 27017 }

, storage: { dbPath: "/var/lib/mongodb-dir/mongodb" } }
2020-08-06T19:27:58.765+0300 I STORAGE [initandlisten] Detected data files in /var/lib/mongodb-dir/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2020-08-06T19:27:58.765+0300 I STORAGE [initandlisten]
2020-08-06T19:27:58.765+0300 I STORAGE [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2020-08-06T19:27:58.765+0300 I STORAGE [initandlisten] ** See http://dochub.mongodb.org/core/prodnotes-filesystem
2020-08-06T19:27:58.765+0300 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7363M,cache_overflow=(file_max=0M),session_max=33000,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,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress],
2020-08-06T19:27:59.293+0300 I STORAGE [initandlisten] WiredTiger message [1596731279:293988][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21946 through 21947
2020-08-06T19:27:59.366+0300 I STORAGE [initandlisten] WiredTiger message [1596731279:366478][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21947 through 21947
2020-08-06T19:27:59.584+0300 I STORAGE [initandlisten] WiredTiger message [1596731279:584064][23491:0x7fbcb1e5fb40], txn-recover: Main recovery loop: starting at 21946/896 to 21947/256
2020-08-06T19:27:59.677+0300 I STORAGE [initandlisten] WiredTiger message [1596731279:677909][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21946 through 21947
2020-08-06T19:27:59.734+0300 I STORAGE [initandlisten] WiredTiger message [1596731279:734517][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21947 through 21947
2020-08-06T19:27:59.780+0300 I STORAGE [initandlisten] WiredTiger message [1596731279:780025][23491:0x7fbcb1e5fb40], txn-recover: Set global recovery timestamp: (0, 0)
2020-08-06T19:27:59.817+0300 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2020-08-06T19:27:59.823+0300 I STORAGE [initandlisten] Starting OplogTruncaterThread local.oplog.rs
2020-08-06T19:27:59.823+0300 I STORAGE [initandlisten] The size storer reports that the oplog contains 10042717 records totaling to 4979072257 bytes
2020-08-06T19:27:59.823+0300 I STORAGE [initandlisten] Sampling the oplog to determine where to place markers for truncation
2020-08-06T19:27:59.824+0300 I STORAGE [initandlisten] Sampling from the oplog between Oct 9 14:20:42:66427 and Oct 29 12:32:50:1 to determine where to place markers for truncation
2020-08-06T19:27:59.824+0300 I STORAGE [initandlisten] Taking 996 samples and assuming that each section of oplog contains approximately 100746 records totaling to 49948795 bytes
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:43:84392
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:44:99923
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:46:15530
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:47:35372
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:48:83427
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:50:54090
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:52:27733
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:53:80049
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:55:43626
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:57:27324
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:20:58:76415
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:00:11944
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:02:8643
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:03:54378
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:04:114630
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:06:60031
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:08:6412
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:09:62141
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:11:24255
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:12:85915
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:14:50783
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:15:93740
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:20:16792
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:21:72211
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:23:42994
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:21:25:12173
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 14:30:32:791
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 15:37:04:114
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 16:00:06:20
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 16:28:07:906
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 17:02:57:112
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 17:23:12:16
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 19:14:02:93
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 9 23:57:04:3
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 10 09:48:01:8
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 10 12:38:27:205
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 10 13:47:58:1
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 10 17:18:04:35
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 10 23:36:03:34
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 11:29:01:222
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 12:07:47:98
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 13:38:02:128
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 15:03:10:894
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 16:03:54:52
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 16:21:03:36
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 11 21:17:08:3
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 12 11:05:40:435
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 12 11:07:41:127
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 12 11:55:20:75
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 12 15:37:30:116
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 13 12:00:02:53
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 15 12:11:22:267
2020-08-06T19:28:00.174+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 16 15:08:18:2015
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 16 19:32:04:14
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 17 12:32:56:204
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 17 17:51:01:63
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 18 10:13:07:322
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 18 13:08:40:225
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 18 13:21:17:243
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 18 15:02:21:1
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 18 16:56:31:149
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 18 19:11:03:19
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 19 07:24:03:72
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 19 12:24:04:1465
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 19 13:36:25:368
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 19 15:18:03:15
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 19 17:32:03:55
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 20 04:05:15:60
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 20 11:38:20:126
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 20 15:25:17:1
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 20 18:24:16:11
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 20 21:06:02:11
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 21 00:40:01:5
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 21 20:15:02:16
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 22 11:28:15:11
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 22 19:52:02:42
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 10:18:23:37
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 12:36:01:69
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 13:19:06:2
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 15:27:08:91
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 16:27:02:69
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 16:47:58:59
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 17:11:01:2
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 23 18:25:24:27
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 09:11:49:8
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 10:36:23:152
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 11:04:24:46
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 13:00:01:88
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 15:57:53:51
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 17:33:51:1
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 24 19:50:04:50
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 25 08:32:11:1
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 25 11:53:14:150
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 25 14:21:02:81
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 25 22:42:07:99
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 26 11:13:50:151
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 26 15:44:07:155
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 26 18:23:02:6148
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] Placing a marker at optime Oct 27 22:24:01:11
2020-08-06T19:28:00.175+0300 I STORAGE [initandlisten] WiredTiger record store oplog processing took 351ms
2020-08-06T19:28:00.233+0300 I STORAGE [initandlisten] Timestamp monitor starting
2020-08-06T19:28:00.235+0300 I CONTROL [initandlisten]
2020-08-06T19:28:00.235+0300 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2020-08-06T19:28:00.235+0300 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2020-08-06T19:28:00.235+0300 I CONTROL [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2020-08-06T19:28:00.235+0300 I CONTROL [initandlisten]
2020-08-06T19:28:00.434+0300 I SHARDING [initandlisten] Marking collection local.system.replset as collection version: <unsharded>
2020-08-06T19:28:00.438+0300 I STORAGE [initandlisten] exception in initAndListen: Location40415: BSON field 'MinValidDocument.oplogDeleteFromPoint' is an unknown field., terminating
2020-08-06T19:28:00.438+0300 I NETWORK [initandlisten] shutdown: going to close listening sockets...
2020-08-06T19:28:00.438+0300 I - [initandlisten] Stopping further Flow Control ticket acquisitions.
2020-08-06T19:28:00.438+0300 I STORAGE [initandlisten] Deregistering all the collections
2020-08-06T19:28:00.438+0300 I STORAGE [WTOplogJournalThread] Oplog journal thread loop shutting down
2020-08-06T19:28:00.439+0300 I STORAGE [initandlisten] Timestamp monitor shutting down
2020-08-06T19:28:00.439+0300 I STORAGE [initandlisten] WiredTigerKVEngine shutting down
2020-08-06T19:28:00.439+0300 I STORAGE [initandlisten] Shutting down session sweeper thread
2020-08-06T19:28:00.439+0300 I STORAGE [initandlisten] Finished shutting down session sweeper thread
2020-08-06T19:28:00.439+0300 I STORAGE [initandlisten] Shutting down journal flusher thread
2020-08-06T19:28:00.517+0300 I STORAGE [initandlisten] Finished shutting down journal flusher thread
2020-08-06T19:28:00.517+0300 I STORAGE [initandlisten] Shutting down checkpoint thread
2020-08-06T19:28:00.518+0300 I STORAGE [initandlisten] Finished shutting down checkpoint thread
2020-08-06T19:28:00.518+0300 I STORAGE [initandlisten] Downgrading WiredTiger datafiles.
2020-08-06T19:28:00.542+0300 I STORAGE [initandlisten] WiredTiger message [1596731280:542751][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21947 through 21948
2020-08-06T19:28:00.590+0300 I STORAGE [initandlisten] WiredTiger message [1596731280:590306][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21948 through 21948
2020-08-06T19:28:00.809+0300 I STORAGE [initandlisten] WiredTiger message [1596731280:809571][23491:0x7fbcb1e5fb40], txn-recover: Main recovery loop: starting at 21947/2176 to 21948/256
2020-08-06T19:28:00.900+0300 I STORAGE [initandlisten] WiredTiger message [1596731280:900535][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21947 through 21948
2020-08-06T19:28:00.956+0300 I STORAGE [initandlisten] WiredTiger message [1596731280:956212][23491:0x7fbcb1e5fb40], txn-recover: Recovering log 21948 through 21948
2020-08-06T19:28:01.001+0300 I STORAGE [initandlisten] WiredTiger message [1596731281:1548][23491:0x7fbcb1e5fb40], txn-recover: Set global recovery timestamp: (0, 0)
2020-08-06T19:28:01.063+0300 I STORAGE [initandlisten] shutdown: removing fs lock...
2020-08-06T19:28:01.063+0300 I CONTROL [initandlisten] now exiting
2020-08-06T19:28:01.063+0300 I CONTROL [initandlisten] shutting down with code:100



 Comments   
Comment by Dmitry Agranat [ 22/Nov/20 ]

Hi hussam.jarrah00@gmail.com, we've created SERVER-52961 to track and address this issue. Please add yourself to "Watchers" to follow the updates.

Comment by Hussam Jarrah [ 09/Aug/20 ]

Thank you Sir!

I just found the solution here: https://developer.mongodb.com/community/forums/t/failed-to-start-mongo-service-after-update-from-4-0-to-4-2/7640/4 

Comment by Dmitry Agranat [ 09/Aug/20 ]

Hi hussam.jarrah00@gmail.com,

In order for us to investigate this issue, could you please provide the following information:

  • The output from the following command:

     db.getSiblingDB("local").getCollection("replset.minvalid").find() 

  • Your upgrade path, as detailed as possible. From as early as MongoDB 3.2.
  • Was this node ever a part of a replica set?
  • Full mongod log covering the time of the upgrade, you can upload it into this secure portal

Thanks,
Dima

Comment by Hussam Jarrah [ 06/Aug/20 ]

I am using a standalone server, no replication no sharding

Generated at Thu Feb 08 05:21:52 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.