I have a 3-member MongoDB replica set running in a Kubernetes cluster, installed from stable/mongodb-replicaset helm chart.
I tried to upgrade the cluster as:
# helm upgrade mongo-rs ~/mongodb-replicaset/ --set=image.tag="4.2"
The process started on 3rd member and failed, so 2 other members remain on 4.0. The 3rd member is running as arbiter (the chart is slightly patched to recognize that).
The error is:
Invariant failure !stableTimestamp || stableTimestamp->isNull() || appliedThrough.isNull() || *stableTimestamp == appliedThrough.getTimestamp() Stable timestamp Timestamp(1570594217, 1) does not equal appliedThrough timestamp { ts: Timestamp(1565774007, 1), t: 2 } src/mongo/db/repl/replication_recovery.cpp 263
Things tried:
- cleaned up data directory to initiate full resync
- synced time between members
- remove the 3rd member with rs.remove() from the cluster on the primary side
The replica set was prepared for the upgrade by running the command in mongo shell on all replicas:
db.adminCommand( { setFeatureCompatibilityVersion: "4.0" } )
The same error keeps persisting, and I don't quite understand the meaning behind it. The appliedThrough timestamp in the error dates back to August, when the cluster was initially setup.
The startup log from the failing replica:
2019-10-14T03:58:25.229+0000 I CONTROL [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] MongoDB starting : pid=29 port=27017 dbpath=/data/db 64-bit host=mongo-rs-mongodb-replicaset-2
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] db version v4.0.11
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] git version: 417d1a712e9f040d54beca8e4943edce218e9a8c
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.2g 1 Mar 2016
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] allocator: tcmalloc
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] modules: none
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] build environment:
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] distmod: ubuntu1604
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] distarch: x86_64
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] target_arch: x86_64
2019-10-14T03:58:25.233+0000 I CONTROL [initandlisten] options: { config: "/data/configdb/mongod.conf", net: { bindIp: "0.0.0.0", port: 27017 }, replication: { replSet: "rs0" }, storage: { dbPath: "/data/db" } }
2019-10-14T03:58:25.233+0000 W STORAGE [initandlisten] Detected unclean shutdown - /data/db/mongod.lock is not empty.
2019-10-14T03:58:25.233+0000 I STORAGE [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2019-10-14T03:58:25.233+0000 W STORAGE [initandlisten] Recovering data from the last clean checkpoint.
2019-10-14T03:58:25.233+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=3398M,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),
exception: connect failed
2019-10-14T03:58:25.998+0000 I STORAGE [initandlisten] WiredTiger message [1571025505:998372][29:0x7fad8706ca80], txn-recover: Main recovery loop: starting at 1441/256 to 1442/256
2019-10-14T03:58:25.998+0000 I STORAGE [initandlisten] WiredTiger message [1571025505:998732][29:0x7fad8706ca80], txn-recover: Recovering log 1441 through 1442
2019-10-14T03:58:26.075+0000 I STORAGE [initandlisten] WiredTiger message [1571025506:74993][29:0x7fad8706ca80], txn-recover: Recovering log 1442 through 1442
2019-10-14T03:58:26.130+0000 I STORAGE [initandlisten] WiredTiger message [1571025506:130633][29:0x7fad8706ca80], txn-recover: Set global recovery timestamp: 5d9d5da900000001
2019-10-14T03:58:26.139+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(1570594217, 1)
2019-10-14T03:58:26.139+0000 I STORAGE [initandlisten] Triggering the first stable checkpoint. Initial Data: Timestamp(1570594217, 1) PrevStable: Timestamp(0, 0) CurrStable: Timestamp(1570594217, 1)
2019-10-14T03:58:26.162+0000 I STORAGE [initandlisten] Starting OplogTruncaterThread local.oplog.rs
2019-10-14T03:58:26.162+0000 I STORAGE [initandlisten] The size storer reports that the oplog contains 118 records totaling to 13954 bytes
2019-10-14T03:58:26.162+0000 I STORAGE [initandlisten] Scanning the oplog to determine where to place markers for truncation
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten]
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten]
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten]
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten]
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2019-10-14T03:58:26.168+0000 I CONTROL [initandlisten]
2019-10-14T03:58:26.193+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
2019-10-14T03:58:26.195+0000 I REPL [initandlisten] Rollback ID is 1
2019-10-14T03:58:26.195+0000 F - [initandlisten] Invariant failure !stableTimestamp || stableTimestamp->isNull() || appliedThrough.isNull() || *stableTimestamp == appliedThrough.getTimestamp() Stable timestamp Timestamp(1570594217, 1) does not equal appliedThrough timestamp { ts: Timestamp(1565774007, 1), t: 2 } src/mongo/db/repl/replication_recovery.cpp 263
2019-10-14T03:58:26.195+0000 F - [initandlisten]
***aborting after invariant() failure
2019-10-14T03:58:26.205+0000 F - [initandlisten] Got signal: 6 (Aborted).
0x556d6222e761 0x556d6222d979 0x556d6222de5d 0x7fad857f0390 0x7fad8544a428 0x7fad8544c02a 0x556d60818325 0x556d60b12d92 0x556d60b4e23f 0x556d60b4eb17 0x556d60886c65 0x556d6088944f 0x556d6081a329 0x7fad85435830 0x556d60883dd9
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"556D5FDF9000","o":"2435761","s":"_ZN5mongo15printStackTraceERSo"},{"b":"556D5FDF9000","o":"2434979"},{"b":"556D5FDF9000","o":"2434E5D"},{"b":"7FAD857DF000","o":"11390"},{"b":"7FAD85415000","o":"35428","s":"gsignal"},{"b":"7FAD85415000","o":"3702A","s":"abort"},{"b":"556D5FDF9000","o":"A1F325","s":"_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j"},{"b":"556D5FDF9000","o":"D19D92","s":"_ZN5mongo4repl23ReplicationRecoveryImpl16recoverFromOplogEPNS_16OperationContextEN5boost8optionalINS_9TimestampEEE"},{"b":"556D5FDF9000","o":"D5523F","s":"_ZN5mongo4repl26ReplicationCoordinatorImpl21_startLoadLocalConfigEPNS_16OperationContextE"},{"b":"556D5FDF9000","o":"D55B17","s":"_ZN5mongo4repl26ReplicationCoordinatorImpl7startupEPNS_16OperationContextE"},{"b":"556D5FDF9000","o":"A8DC65"},{"b":"556D5FDF9000","o":"A9044F","s":"_ZN5mongo11mongoDbMainEiPPcS1_"},{"b":"556D5FDF9000","o":"A21329","s":"main"},{"b":"7FAD85415000","o":"20830","s":"__libc_start_main"},{"b":"556D5FDF9000","o":"A8ADD9","s":"_start"}],"processInfo":{ "mongodbVersion" : "4.0.11", "gitVersion" : "417d1a712e9f040d54beca8e4943edce218e9a8c", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "3.10.0-957.21.3.el7.x86_64", "version" : "#1 SMP Tue Jun 18 16:35:19 UTC 2019", "machine" : "x86_64" }, "somap" : [ { "b" : "556D5FDF9000", "elfType" : 3, "buildId" : "6D8C3C09B6DADA2DC89B514D21D0CBFF30B82A8E" }, { "b" : "7FFE9B4C7000", "elfType" : 3, "buildId" : "BC4D21950F4B2ADFB515DFBB0E082E2281689A0B" }, { "b" : "7FAD86BF0000", "path" : "/usr/lib/x86_64-linux-gnu/libcurl.so.4", "elfType" : 3, "buildId" : "5C1A06A89F89E1ADAAA507BC5580C0A7931B0AB2" }, { "b" : "7FAD869D5000", "path" : "/lib/x86_64-linux-gnu/libresolv.so.2", "elfType" : 3, "buildId" : "50A923F8DAFECBCD969C8573116A38C18D0E24D5" }, { "b" : "7FAD86590000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "15FFEB43278726B025F020862BF51302822A40EC" }, { "b" : "7FAD86327000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "FF69EA60EBE05F2DD689D2B26FC85A73E5FBC3A0" }, { "b" : "7FAD86123000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "37BFC3D8F7E3B022DAC7943B1A5FACD40CEBF0AD" }, { "b" : "7FAD85F1B000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "69143E8B39040C964D3958490535322675F15DD3" }, { "b" : "7FAD85C12000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "BAD67A84E56E73D031AE507261DA066B35949D34" }, { "b" : "7FAD859FC000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "68220AE2C65D65C1B6AAA12FA6765A6EC2F5F434" }, { "b" : "7FAD857DF000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "B17C21299099640A6D863E423D99265824E7BB16" }, { "b" : "7FAD85415000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "1CA54A6E0D76188105B12E49FE6B8019BF08803A" }, { "b" : "7FAD86E5F000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "C0ADBAD6F9A33944F2B3567C078EC472A1DAE98E" }, { "b" : "7FAD851E2000", "path" : "/usr/lib/x86_64-linux-gnu/libidn.so.11", "elfType" : 3, "buildId" : "E09D3783AD1D0BBCD3204FA01E4EF6D756E18F57" }, { "b" : "7FAD84FC6000", "path" : "/usr/lib/x86_64-linux-gnu/librtmp.so.1", "elfType" : 3, "buildId" : "8D1CC1204D6B6D33BD1D2C5A2A0516A2234322CF" }, { "b" : "7FAD84D7C000", "path" : "/usr/lib/x86_64-linux-gnu/libgssapi_krb5.so.2", "elfType" : 3, "buildId" : "41971A4A3CCDC54A447F41DF4BD96C948C546E0E" }, { "b" : "7FAD84B6D000", "path" : "/usr/lib/x86_64-linux-gnu/liblber-2.4.so.2", "elfType" : 3, "buildId" : "8E613D0B8D8E3537785637424782BE8502ABABD2" }, { "b" : "7FAD8491C000", "path" : "/usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2", "elfType" : 3, "buildId" : "3890D33727391E4A85DC0F819AB0AA29BB5DFC86" }, { "b" : "7FAD84702000", "path" : "/lib/x86_64-linux-gnu/libz.so.1", "elfType" : 3, "buildId" : "8D9BD4CE26E45EF16075C67D5F5EEAFD8B562832" }, { "b" : "7FAD843D2000", "path" : "/usr/lib/x86_64-linux-gnu/libgnutls.so.30", "elfType" : 3, "buildId" : "17285B5F2BCC671E0A7FA3E29CCD143509B648CD" }, { "b" : "7FAD8419F000", "path" : "/usr/lib/x86_64-linux-gnu/libhogweed.so.4", "elfType" : 3, "buildId" : "B11678F560199547DCF726384EA39153EE0DFABF" }, { "b" : "7FAD83F69000", "path" : "/usr/lib/x86_64-linux-gnu/libnettle.so.6", "elfType" : 3, "buildId" : "D6B36C5A463EE0FA84FDD6D5FD3F7726EDB90D54" }, { "b" : "7FAD83CE9000", "path" : "/usr/lib/x86_64-linux-gnu/libgmp.so.10", "elfType" : 3, "buildId" : "7B3533D5998D20EE1A1BE3F87789B69041E7F620" }, { "b" : "7FAD83A17000", "path" : "/usr/lib/x86_64-linux-gnu/libkrb5.so.3", "elfType" : 3, "buildId" : "0EEF7058B0737B68BDF89E5DC604D0AC389C8BB1" }, { "b" : "7FAD837E8000", "path" : "/usr/lib/x86_64-linux-gnu/libk5crypto.so.3", "elfType" : 3, "buildId" : "FFBA483A43D9EF73925AC116811890C037523DA1" }, { "b" : "7FAD835E4000", "path" : "/lib/x86_64-linux-gnu/libcom_err.so.2", "elfType" : 3, "buildId" : "1E16CB57F699E215A2A8D4EFEF90883BC749B12D" }, { "b" : "7FAD833D9000", "path" : "/usr/lib/x86_64-linux-gnu/libkrb5support.so.0", "elfType" : 3, "buildId" : "B789D8D4B4FC333405AB34387D9237F954060EA4" }, { "b" : "7FAD831BE000", "path" : "/usr/lib/x86_64-linux-gnu/libsasl2.so.2", "elfType" : 3, "buildId" : "87783DF8A1058CD150F8886CB36340384093C18F" }, { "b" : "7FAD82F7D000", "path" : "/usr/lib/x86_64-linux-gnu/libgssapi.so.3", "elfType" : 3, "buildId" : "1FE877BE52A424D0636AFD4D35BB330E41D6E0F3" }, { "b" : "7FAD82D19000", "path" : "/usr/lib/x86_64-linux-gnu/libp11-kit.so.0", "elfType" : 3, "buildId" : "A0E2D03FF5CF65937F4425D4EFD4D655243809EB" }, { "b" : "7FAD82B06000", "path" : "/usr/lib/x86_64-linux-gnu/libtasn1.so.6", "elfType" : 3, "buildId" : "E07E186694852D8F69459C6AB28A53F8DA3CE3B6" }, { "b" : "7FAD82902000", "path" : "/lib/x86_64-linux-gnu/libkeyutils.so.1", "elfType" : 3, "buildId" : "3364D4BF2113C4E8D17EF533867ECC99A53413D6" }, { "b" : "7FAD826F9000", "path" : "/usr/lib/x86_64-linux-gnu/libheimntlm.so.0", "elfType" : 3, "buildId" : "73A8EADBC85860662B24850E71D4AFBE22C33359" }, { "b" : "7FAD8246F000", "path" : "/usr/lib/x86_64-linux-gnu/libkrb5.so.26", "elfType" : 3, "buildId" : "59E742306A4EA2872E061ECCE92F35FADDA75357" }, { "b" : "7FAD821CD000", "path" : "/usr/lib/x86_64-linux-gnu/libasn1.so.8", "elfType" : 3, "buildId" : "E5C159E415406AE79D21056D752BA949C408B5B1" }, { "b" : "7FAD81F9A000", "path" : "/usr/lib/x86_64-linux-gnu/libhcrypto.so.4", "elfType" : 3, "buildId" : "7D15576E1F096614D360784E4A01A1F5FAF908C9" }, { "b" : "7FAD81D84000", "path" : "/usr/lib/x86_64-linux-gnu/libroken.so.18", "elfType" : 3, "buildId" : "481DB33C28D88E43DA6BED65E1A7599407D4D818" }, { "b" : "7FAD81B7C000", "path" : "/usr/lib/x86_64-linux-gnu/libffi.so.6", "elfType" : 3, "buildId" : "9D9C958F1F4894AFEF6AECD90D1C430EA29AC34F" }, { "b" : "7FAD81953000", "path" : "/usr/lib/x86_64-linux-gnu/libwind.so.0", "elfType" : 3, "buildId" : "57E25072866B2D30CF02EBE7AE623B84F96FA700" }, { "b" : "7FAD81744000", "path" : "/usr/lib/x86_64-linux-gnu/libheimbase.so.1", "elfType" : 3, "buildId" : "F6F1B4E9F89B716C4A0BA5819BDFFAF4A13EFB91" }, { "b" : "7FAD814F9000", "path" : "/usr/lib/x86_64-linux-gnu/libhx509.so.5", "elfType" : 3, "buildId" : "C60082E3BB78D0D42868D9B359B89BF66CE5A1A7" }, { "b" : "7FAD81224000", "path" : "/usr/lib/x86_64-linux-gnu/libsqlite3.so.0", "elfType" : 3, "buildId" : "3B0454E57467057071F7AD49651E0FA7B01CF5C7" }, { "b" : "7FAD80FEC000", "path" : "/lib/x86_64-linux-gnu/libcrypt.so.1", "elfType" : 3, "buildId" : "FD61CA7A6D603E94E5EFD5C88D8810AE104FCF40" } ] }}
mongod(_ZN5mongo15printStackTraceERSo+0x41) [0x556d6222e761]
mongod(+0x2434979) [0x556d6222d979]
mongod(+0x2434E5D) [0x556d6222de5d]
libpthread.so.0(+0x11390) [0x7fad857f0390]
libc.so.6(gsignal+0x38) [0x7fad8544a428]
libc.so.6(abort+0x16A) [0x7fad8544c02a]
mongod(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0x0) [0x556d60818325]
mongod(_ZN5mongo4repl23ReplicationRecoveryImpl16recoverFromOplogEPNS_16OperationContextEN5boost8optionalINS_9TimestampEEE+0x6B2) [0x556d60b12d92]
mongod(_ZN5mongo4repl26ReplicationCoordinatorImpl21_startLoadLocalConfigEPNS_16OperationContextE+0x57F) [0x556d60b4e23f]
mongod(_ZN5mongo4repl26ReplicationCoordinatorImpl7startupEPNS_16OperationContextE+0x237) [0x556d60b4eb17]
mongod(+0xA8DC65) [0x556d60886c65]
mongod(_ZN5mongo11mongoDbMainEiPPcS1_+0xEFF) [0x556d6088944f]
mongod(main+0x9) [0x556d6081a329]
libc.so.6(__libc_start_main+0xF0) [0x7fad85435830]
mongod(_start+0x29) [0x556d60883dd9]
----- END BACKTRACE -----
[2019-10-14T03:58:26,274739247+00:00] [on-start.sh] mongod shutdown unexpectedly
[2019-10-14T03:58:26,277725789+00:00] [on-start.sh] Shutting down MongoDB (force: true)...
db.shutdownServer()on all nodes before upgrading.