[SERVER-37394] Invariant failure deadline != Date_t::max() or Invariant failure date.isFormattable() Created: 28/Sep/18  Updated: 29/Oct/23  Resolved: 09/Oct/18

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 4.0.2, 4.1.3
Fix Version/s: 4.0.4, 4.1.4

Type: Bug Priority: Critical - P2
Reporter: Asya Kamsky Assignee: Eric Milkie
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Duplicate
is duplicated by SERVER-38768 Crash: Got signal: 6 (Aborted) Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.0
Sprint: Storage NYC 2018-10-08
Participants:
Linked BF Score: 39

 Description   

This happened in association with invariant seen in SERVER-36907

 

2018-09-25T23:08:09.928+0000 I TXN      [conn14199] transaction parameters:{ lsid: { id: UUID("6c142ca8-c236-413b-9bc7-020f9e34e10f"), uid: BinData(0, F61FC3336B290B6276B4475A10D1179C7858CC3544AE78465DB782A7F2913A2F) }, txnNumber: 9, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(1537916889, 1456), keysExamined:55 docsExamined:28 nMatched:1 nModified:1 ninserted:15 keysInserted:45 keysDeleted:1 terminationCause:committed timeActiveMicros:66481 timeInactiveMicros:41055 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 9 } }, oplog: { acquireCount: { w: 1 } } } 107ms
2018-09-25T23:08:09.955+0000 F -        [conn14082] Got signal: 6 (Aborted).
 
----- BEGIN BACKTRACE -----
 mongod(_ZN5mongo15printStackTraceERSo+0x41) [0x559d411f3731]
 mongod(+0x247E949) [0x559d411f2949]
 mongod(+0x247EE2D) [0x559d411f2e2d]
 libpthread.so.0(+0xF6D0) [0x7f57dea0a6d0]
 libc.so.6(gsignal+0x37) [0x7f57de664277]
 libc.so.6(abort+0x148) [0x7f57de665968]
 mongod(_ZN5mongo22invariantFailedWithMsgEPKcRKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES1_j+0x0) [0x559d3f798dec]
 mongod(+0x2487121) [0x559d411fb121]
 mongod(_ZN5mongo20dateToISOStringLocalB5cxx11ENS_6Date_tE+0x31) [0x559d411fb881]
 mongod(+0x9E75A4) [0x559d3f75b5a4]
 mongod(_ZN5mongo9AutoGetDbC2EPNS_16OperationContextENS_10StringDataENS_8LockModeENS_6Date_tE+0x2AF) [0x559d4073be1f]
 mongod(_ZN5mongo17AutoGetCollectionC2EPNS_16OperationContextERKNS_21NamespaceStringOrUUIDENS_8LockModeES6_NS0_8ViewModeENS_6Date_tE+0x12C) [0x559d4073c10c]
 mongod(+0x109F6DA) [0x559d3fe136da]
 mongod(+0x10A0FFC) [0x559d3fe14ffc]
 mongod(_ZN5mongo12BasicCommand10Invocation3runEPNS_16OperationContextEPNS_19CommandReplyBuilderE+0xD9) [0x559d40c48359]
 mongod(+0xB40A1F) [0x559d3f8b4a1f]
 mongod(+0xB4364E) [0x559d3f8b764e]
 mongod(+0xB451A9) [0x559d3f8b91a9]
 mongod(_ZN5mongo23ServiceEntryPointCommon13handleRequestEPNS_16OperationContextERKNS_7MessageERKNS0_5HooksE+0x3D1) [0x559d3f8ba0f1]
 mongod(_ZN5mongo23ServiceEntryPointMongod13handleRequestEPNS_16OperationContextERKNS_7MessageE+0x3A) [0x559d3f8a772a]
 mongod(_ZN5mongo19ServiceStateMachine15_processMessageENS0_11ThreadGuardE+0xBA) [0x559d3f8b247a]
 mongod(_ZN5mongo19ServiceStateMachine15_runNextInGuardENS0_11ThreadGuardE+0x97) [0x559d3f8ad137]
 mongod(+0xB3C941) [0x559d3f8b0941]
 mongod(_ZN5mongo9transport26ServiceExecutorSynchronous8scheduleESt8functionIFvvEENS0_15ServiceExecutor13ScheduleFlagsENS0_23ServiceExecutorTaskNameE+0x1A2) [0x559d40a7ba72]
 mongod(_ZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS0_11ThreadGuardENS_9transport15ServiceExecutor13ScheduleFlagsENS2_23ServiceExecutorTaskNameENS0_9OwnershipE+0x15F) [0x559d3f8ab34f]
 mongod(_ZN5mongo19ServiceStateMachine15_sourceCallbackENS_6StatusE+0xAF5) [0x559d3f8ae4e5]
 mongod(_ZN5mongo19ServiceStateMachine14_sourceMessageENS0_11ThreadGuardE+0x357) [0x559d3f8ac877]
 mongod(_ZN5mongo19ServiceStateMachine15_runNextInGuardENS0_11ThreadGuardE+0x11D) [0x559d3f8ad1bd]
 mongod(+0xB3C941) [0x559d3f8b0941]
 mongod(+0x1D07FD5) [0x559d40a7bfd5]
 mongod(+0x23D8704) [0x559d4114c704]
 libpthread.so.0(+0x7E25) [0x7f57dea02e25]
 libc.so.6(clone+0x6D) [0x7f57de72cbad]
-----  END BACKTRACE  -----
2018-09-25T23:08:13.711+0000 I CONTROL  [main] ***** SERVER RESTARTED *****

In addition earlier in the logs there were a bunch of instances of this error:

2018-09-25T23:08:09.593+0000 I TXN      [conn14160] transaction parameters:{ lsid: { id: UUID("03f47376-630a-4b58-b1c3-e788fb1c0ed6"), uid: BinData(0, F61FC3336B290B6276B4475A10D1179C7858CC3544AE78465DB782A7F2913A2F) }, txnNumber: 4, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(1537916889, 714), keysExamined:8 docsExamined:1 nMatched:1 nModified:1 terminationCause:committed timeActiveMicros:5833 timeInactiveMicros:99574 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 5 } }, oplog: { acquireCount: { w: 1 } } } 105ms
2018-09-25T23:08:09.645+0000 F -        [conn14082] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.645+0000 F -        [conn14082] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.648+0000 F -        [conn14091] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.648+0000 F -        [conn14091] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.648+0000 F -        [conn14071] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.648+0000 F -        [conn14071] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.649+0000 F -        [conn13867] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.649+0000 F -        [conn13867] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.650+0000 F -        [conn13925] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.650+0000 F -        [conn13925] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.655+0000 F -        [conn13862] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.655+0000 F -        [conn13862] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.656+0000 F -        [conn14214] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.656+0000 F -        [conn14186] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.656+0000 F -        [conn14214] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.656+0000 F -        [conn14186] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.657+0000 F -        [conn14097] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.657+0000 F -        [conn14068] Invariant failure date.isFormattable() src/mongo/util/time_support.cpp 148
2018-09-25T23:08:09.657+0000 F -        [conn14097] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.657+0000 F -        [conn14068] 
 
***aborting after invariant() failure
 
 
2018-09-25T23:08:09.658+0000 I TXN      [conn14183] transaction parameters:{ lsid: { id: UUID("f648d6ea-4962-4f64-8b37-239ad3e33274"), uid: BinData(0, F61FC3336B290B6276B4475A10D1179C7858CC3544AE78465DB782A7F2913A2F) }, txnNumber: 3, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(1537916889, 611), keysExamined:59 docsExamined:30 nMatched:1 nModified:1 ninserted:16 keysInserted:48 keysDeleted:1 terminationCause:committed timeActiveMicros:121303 timeInactiveMicros:93804 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 9 } }, oplog: { acquireCount: { w: 1 } } } 215ms



 Comments   
Comment by Githook User [ 11/Oct/18 ]

Author:

{'name': 'Eric Milkie', 'email': 'milkie@10gen.com', 'username': 'milkie'}

Message: SERVER-37394 do not display deadline in timeout message

Because a lock acquisition can time out due to the minimum of the passed-in deadline or the MaxLockTimeout set on the Locker, we cannot show the exact deadline used for the timeout in the timeout message.

(cherry picked from commit 1e03955cdab995fed6672d75a6a4544a9771a279)
Branch: v4.0
https://github.com/mongodb/mongo/commit/9bf799a49ded7e9bd58183bdd636c8196988c22d

Comment by Githook User [ 09/Oct/18 ]

Author:

{'name': 'Eric Milkie', 'email': 'milkie@10gen.com', 'username': 'milkie'}

Message: SERVER-37394 do not display deadline in timeout message

Because a lock acquisition can time out due to the minimum of the passed-in deadline or the MaxLockTimeout set on the Locker, we cannot show the exact deadline used for the timeout in the timeout message.
Branch: master
https://github.com/mongodb/mongo/commit/1e03955cdab995fed6672d75a6a4544a9771a279

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