[MONGOCRYPT-30] linkbench can crash libmongocrypt Created: 12/Jul/19  Updated: 28/Oct/23  Resolved: 15/Jul/19

Status: Closed
Project: Libmongocrypt
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Jeffrey Yemin
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File hs_err_pid50289.log     Text File hs_err_pid57718.log    
Issue Links:
Depends
Epic Link: Build libmongocrypt library

 Description   

To reproduce:

Repo: https://github.com/markbenvenuto/linkbench
Branch: fle

Steps

mvn clean package -DskipTests

mongo --eval "db.getSiblingDB('linkdb0').dropDatabase(); db.getSiblingDB('linkdb0').createCollection('linktable');  db.getSiblingDB('linkdb0').createCollection('nodetable');  db.getSiblingDB('linkdb0').createCollection('counttable'); ";

./bin/linkbench -c config/LinkConfigMongoDb.properties -l

It will take a few minutes to actually segfault.

Running on OS X I see this in the JVM logfile:

Current thread (0x00007f9f9ebf8000):  JavaThread "Thread-16" [_thread_in_native, id=34563, stack(0x000070000b9c9000,0x000070000bac9000)]
 
Stack: [0x000070000b9c9000,0x000070000bac9000],  sp=0x000070000bac5ec0,  free space=1011k
Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  [jna16384194371315847686.tmp+0x1fec2]  _bson_iter_next_internal+0xc2
C  [jna16384194371315847686.tmp+0x1f9fb]  bson_iter_next+0x1b
C  [jna16384194371315847686.tmp+0x116d6]  _recurse+0x56
C  [jna16384194371315847686.tmp+0x11c45]  _recurse+0x5c5
C  [jna16384194371315847686.tmp+0x11a82]  _recurse+0x402
C  [jna16384194371315847686.tmp+0x11ea0]  _mongocrypt_traverse_binary_in_bson+0x110
C  [jna16384194371315847686.tmp+0x7ed5]  _mongo_feed_markings+0x225
C  [jna16384194371315847686.tmp+0x9f54]  mongocrypt_ctx_mongo_feed+0x184
C  [jna12906277947524783135.tmp+0xdef4]  ffi_call_unix64+0x4c
C  0x000070000bac7e90
 
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
J 4130  com.mongodb.crypt.capi.CAPI.mongocrypt_ctx_mongo_feed(Lcom/mongodb/crypt/capi/CAPI$mongocrypt_ctx_t;Lcom/mongodb/crypt/capi/CAPI$mongocrypt_binary_t;)Z (0 bytes) @ 0x000000011b36fea3 [0x000000011b36fe40+0x0000000000000063]
J 6276 c1 com.mongodb.crypt.capi.MongoCryptContextImpl.addMongoOperationResult(Lorg/bson/BsonDocument;)V (56 bytes) @ 0x0000000113e13c3c [0x0000000113e13ac0+0x000000000000017c]
J 6266 c2 com.mongodb.client.internal.Crypt.executeStateMachine(Lcom/mongodb/crypt/capi/MongoCryptContext;Ljava/lang/String;)Lorg/bson/RawBsonDocument; (175 bytes) @ 0x000000011b5eea80 [0x000000011b5ebea0+0x0000000000002be0]
J 4924 c1 com.mongodb.client.internal.Crypt.encrypt(Ljava/lang/String;Lorg/bson/RawBsonDocument;)Lorg/bson/RawBsonDocument; (70 bytes) @ 0x00000001144faf9c [0x00000001144fad80+0x000000000000021c]
J 4140 c1 com.mongodb.client.internal.CryptConnection.command(Ljava/lang/String;Lorg/bson/BsonDocument;Lorg/bson/FieldNameValidator;Lcom/mongodb/ReadPreference;Lorg/bson/codecs/Decoder;Lcom/mongodb/session/SessionContext;ZLcom/mongodb/connection/SplittablePayload;Lorg/bson/FieldNameValidator;)Ljava/lang/Object; (217 bytes) @ 0x00000001143470ec [0x0000000114345da0+0x000000000000134c]



 Comments   
Comment by Githook User [ 15/Jul/19 ]

Author:

{'name': 'Jeff Yemin', 'username': 'jyemin', 'email': 'jeff.yemin@10gen.com'}

Message: Ensure that JNA-managed memory is not GC'd before we're done with it

Since mongocrypt_binary_t is non-owning, the binding must ensure that
the data it creates one with is not freed before the mongocrypt_binary_t
is destroyed. We accomplish this by creating a BinaryHolder class to
wrap the JNA memory and the mongocrypt_binary_t and make it
AutoCloseable.

CDRIVER-3233
Branch: master
https://github.com/mongodb/libmongocrypt/commit/f5bf05f5f63730706c919ef6a8fac91ce526682e

Comment by Jeffrey Yemin [ 15/Jul/19 ]

https://github.com/mongodb/libmongocrypt/pull/27

Comment by Kevin Albertson [ 12/Jul/19 ]

I'm having trouble reproducing this, but it might be worth noting the logged message you saw:

1452070008686173456E6372797074696F6E506C616365686F6C64657273000108736368656D615265717569726573456E6372797074696F6E000103726573756C7400C451070002757064617465000A0000006C696E6B7461626C6500086F7264657265...

The first four bytes 14520700, the document length, is the decimal value 479764, which is larger than I expected (mongocrypt_ctx_mongo_feed is called with either the marked document, key document, or collection info). Though, perhaps that's actually reasonable if we're doing a large bulk write or something.

To help debug this, I'm going to update the logging per CDRIVER-3235 to log the full document.

Comment by Jeffrey Yemin [ 12/Jul/19 ]

Crash at a different stack trace on the next run. Here's the linkbench log file from right before the crash:

711021 [Thread-11] INFO org.mongodb.driver.crypt - mongocrypt_ctx_mongo_feed (in="1452070008686173456E6372797074696F6E506C616365686F6C64657273000108736368656D615265717569726573456E6372797074696F6E000103726573756C7400C451070002757064617465000A0000006C696E6B7461626C6500086F7264657265...")
710994 [Thread-16] INFO org.mongodb.driver.crypt - mongocrypt_ctx_mongo_feed (in="AC40090008686173456E6372797074696F6E506C616365686F6C64657273000108736368656D615265717569726573456E6372797074696F6E000103726573756C74005C40090002696E73657274000A0000006E6F64657461626C6500086F7264657265...")
710977 [Thread-2] INFO org.mongodb.driver.crypt - mongocrypt_ctx_decrypt_init (doc="{ "cursor" : { "firstBatch" : [ { "_id" : { "$binary" : "ipsVv7FRTlO4envCBL4JKA==", "$type" : "04" }, "keyMaterial" : { "$binary" : "u0z86LGbVv46dwA3ozc5vpK0MoChop/GqX1uVbIHQoAsY0r4HUfr1HhYksHDG76mGOqlTSYjF4duHgpEs7f1ZdGheYKQete1o94yxc2zNlommN66LN+cO6G4sU6mFMgA44nG1UgwDs0+1NFpiCm+a/igJblheV7A+c0G47bN87n5Td9vdi4f+bJk2mCjIOQiIpImuW1gmDl1QxWiJJhEKg==", "$type" : "00" }, "creationDate" : { "$date" : 1169372621727000 }, "updateDate" : { "$date" : 1169372621727000 }, "status" : 0, "masterKey" : { "provider" : "local" } } ], "id" : 0, "ns" : "linkdb0.datakeys" }, "ok" : 1.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1562902484, "i" : 2048 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : 0 } }, "operationTime" : { "$timestamp" : { "t" : 1562902484, "i" : 2048 } } }")
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x0000000121f9e8ae, pid=57718, tid=29187
#
710977 [Thread-6] INFO org.mongodb.driver.crypt - mongocrypt_ctx_decrypt_init (doc="{ "cursor" : { "firstBatch" : [ { "_id" : { "$binary" : "JvpBHZOlSfuMEIY5pUR/Hg==", "$type" : "04" }, "keyMaterial" : { "$binary" : "olzsitjY2AgoFhxrsqJj9txTv0vvqqLvhUREVWRx+vxDf+wbK5W2zXJiP1repbkPi9LRcRozT3ni03uSePBKs2w7fST0TtmbwSE15qmPMDhMHD80R1QT30i9rQHsAbamm7NSkWCCZRQSxJZjTwsGjwM36ZPrGRMvwf115UcwtOjn5x+or3OAAEmfXraCP/PqMbR2/Fmi1mKHdu2BWo/kkA==", "$type" : "00" }, "creationDate" : { "$date" : 1169372066309000 }, "updateDate" : { "$date" : 1169372066309000 }, "status" : 0, "masterKey" : { "provider" : "local" } } ], "id" : 0, "ns" : "linkdb0.datakeys" }, "ok" : 1.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1562902484, "i" : 2048 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : 0 } }, "operationTime" : { "$timestamp" : { "t" : 1562902484, "i" : 2048 } } }")
# JRE version: Java(TM) SE Runtime Environment (9.0+181) (build 9+181)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (9+181, mixed mode, tiered, compressed oops, g1 gc, bsd-amd64)
# Problematic frame:
# 710976 [Thread-1] WARN org.mongodb.driver.crypt - local schema used but does not have encryption specifiers
ERROR 2019-07-11 23:34:45,585 [Thread-12]: Error: Exception in encryption library: malformed bson
com.mongodb.MongoClientException: Exception in encryption library: malformed bson
	at com.mongodb.client.internal.Crypt.wrapInClientException(Crypt.java:294)
	at com.mongodb.client.internal.Crypt.encrypt(Crypt.java:110)
	at com.mongodb.client.internal.CryptConnection.command(CryptConnection.java:111)
	at com.mongodb.operation.MixedBulkWriteOperation.executeCommand(MixedBulkWriteOperation.java:434)
	at com.mongodb.operation.MixedBulkWriteOperation.executeBulkWriteBatch(MixedBulkWriteOperation.java:260)
	at com.mongodb.operation.MixedBulkWriteOperation.access$700(MixedBulkWriteOperation.java:71)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:204)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:195)
	at com.mongodb.operation.OperationHelper.withReleasableConnection(OperationHelper.java:501)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:195)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:70)
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:206)
	at com.mongodb.client.internal.MongoCollectionImpl.executeBulkWrite(MongoCollectionImpl.java:471)
	at com.mongodb.client.internal.MongoCollectionImpl.bulkWrite(MongoCollectionImpl.java:463)
	at com.facebook.LinkBench.LinkStoreMongoDb$4.call(LinkStoreMongoDb.java:812)
	at com.facebook.LinkBench.LinkStoreMongoDb$4.call(LinkStoreMongoDb.java:787)
	at com.facebook.LinkBench.LinkStoreMongoDb$6.call(LinkStoreMongoDb.java:1113)
	at com.facebook.LinkBench.LinkStoreMongoDb$7.call(LinkStoreMongoDb.java:1156)
	at com.facebook.LinkBench.LinkStoreMongoDb.executeCommandBlock(LinkStoreMongoDb.java:1186)
	at com.facebook.LinkBench.LinkStoreMongoDb.addBulkLinks(LinkStoreMongoDb.java:828)
	at com.facebook.LinkBench.LinkBenchLoad.loadLinks(LinkBenchLoad.java:488)
	at com.facebook.LinkBench.LinkBenchLoad.createOutLinks(LinkBenchLoad.java:359)
	at com.facebook.LinkBench.LinkBenchLoad.processChunk(LinkBenchLoad.java:286)
	at com.facebook.LinkBench.LinkBenchLoad.run(LinkBenchLoad.java:232)
	at com.facebook.LinkBench.LinkBenchDriver$1.run(LinkBenchDriver.java:429)
	at java.base/java.lang.Thread.run(Thread.java:844)
Caused by: com.mongodb.crypt.capi.MongoCryptException: malformed bson
	at com.mongodb.crypt.capi.MongoCryptContextImpl.throwExceptionFromStatus(MongoCryptContextImpl.java:150)
	at com.mongodb.crypt.capi.MongoCryptContextImpl.throwExceptionFromStatus(MongoCryptContextImpl.java:156)
C  [jna9519466000210424614.tmp+0x188ae]  bson_init_static+0x1e
#
# No core dump will be written. Core dumps have been disabled. To enable core dumping,711569 [Thread-1] INFO org.mongodb.driver.crypt - mongocrypt_ctx_decrypt_init (doc="{ "cursor" : { "firstBatch" : [ { "_id" : { "$binary" : "cE/hDLSpSmOr0mb6SIA2pg==", "$type" : "04" }, "keyMaterial" : { "$binary" : "THiXR83CcGHy8Mad1vsZOAe3210gvySODrEqw5nYSGyEDry8t8IGyAH06WbQnXRt9URIDZk7cLAkkHeipVI02/wK2ptNJdVoNToj+b5Y8Onimw2yfyq7R5THU8gROZviEgDHxy8w7by27xynd0UxECdjZa15FI+SD/coiTuFaop6rL1dPUXaByEERz6ZVbpRPwE1d9BILP965U6U1u57/w==", "$type" : "00" }, "creationDate" : { "$date" : 1169372068594000 }, "updateDate" : { "$date" : 1169372068594000 }, "status" : 0, "masterKey" : { "provider" : "local" } } ], "id" : 0, "ns" : "linkdb0.datakeys" }, "ok" : 1.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1562902484, "i" : 2048 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : 0 } }, "operationTime" : { "$timestamp" : { "t" : 1562902484, "i" : 2048 } } }")
 try "ulimit -c unlimited" before starting Java again
#
[thread 30723 also had an error]
ERROR 2019-07-11 23:34:45,772 [Thread-6]: Error: Exception in encryption library: malformed bson
com.mongodb.MongoClientException: Exception in encryption library: malformed bson
	at com.mongodb.client.internal.Crypt.wrapInClientException(Crypt.java:294)
	at com.mongodb.client.internal.Crypt.decrypt(Crypt.java:132)
	at com.mongodb.client.internal.CryptConnection.command(CryptConnection.java:117)
	at com.mongodb.client.internal.CryptConnection.command(CryptConnection.java:127)
	at com.mongodb.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:341)
	at com.mongodb.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:332)
	at com.mongodb.operation.CommandOperationHelper.executeCommandWithConnection(CommandOperationHelper.java:218)
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:730)
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:724)
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:463)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:724)
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:88)
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:189)
	at com.mongodb.client.internal.MongoIterableImpl.execute(MongoIterableImpl.java:138)
	at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:92)
	at com.mongodb.client.internal.MongoIterableImpl.forEach(MongoIterableImpl.java:116)
	at com.mongodb.client.internal.MongoIterableImpl.into(MongoIterableImpl.java:128)
	at com.mongodb.client.internal.KeyRetriever.find(KeyRetriever.java:41)
	at com.mongodb.client.internal.Crypt.fetchKeys(Crypt.java:252)
	at com.mongodb.client.internal.Crypt.executeStateMachine(Crypt.java:238)
	at com.mongodb.client.internal.Crypt.encrypt(Crypt.java:105)
	at com.mongodb.client.internal.CryptConnection.command(CryptConnection.java:111)
	at com.mongodb.operation.MixedBulkWriteOperation.executeCommand(MixedBulkWriteOperation.java:434)
	at com.mongodb.operation.MixedBulkWriteOperation.executeBulkWriteBatch(MixedBulkWriteOperation.java:260)
	at com.mongodb.operation.MixedBulkWriteOperation.access$700(MixedBulkWriteOperation.java:71)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:204)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:195)
	at com.mongodb.operation.OperationHelper.withReleasableConnection(OperationHelper.java:501)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:195)

Since the crash was from Thread-11, possible that the last trace log from that thread is an interesting one:

711021 [Thread-11] INFO org.mongodb.driver.crypt - mongocrypt_ctx_mongo_feed (in="1452070008686173456E6372797074696F6E506C616365686F6C64657273000108736368656D615265717569726573456E6372797074696F6E000103726573756C7400C451070002757064617465000A0000006C696E6B7461626C6500086F7264657265...")

I see it's truncated so we may need to untruncate that to debug further

Generated at Thu Feb 08 09:07:47 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.