[SERVER-2670] Assertion failure _a != -1 db/pdfile.h 425 Created: 03/Mar/11  Updated: 30/Mar/12  Resolved: 17/Mar/11

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 1.8.0-rc0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: David Mytton Assignee: Eliot Horowitz (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongod.tar.gz    
Operating System: ALL
Participants:

 Description   

Running a count on a newly created index caused an assertion. mongod then complained the db was corrupt and to run a repair, which I did, which resolved the issue.

pb1:PRIMARY> use postbacks
switched to db postbacks
db.createCollection("postbacks",

{capped:true, size:2147483648}

) // 2GB

{ "ok" : 1 }

pb1:PRIMARY> db.postbacks.ensureIndex(

{ '_id' : 1}

,

{background: true}

)
pb1:PRIMARY> db.postbacks.ensureIndex(

{ 'p' : 1}

,

{background: true}

)
pb1:PRIMARY> db.postbacks.stats()
{
"ns" : "postbacks.postbacks",
"count" : 0,
"size" : 0,
"storageSize" : 2147483904,
"numExtents" : 2,
"nindexes" : 2,
"lastExtentSize" : 1057040,
"paddingFactor" : 1,
"flags" : 1,
"totalIndexSize" : 16384,
"indexSizes" :

{ "_id_" : 8192, "p_1" : 8192 }

,
"capped" : 1,
"max" : 2147483647,
"ok" : 1
}
pb1:PRIMARY> db.postbacks.count(

{p: false}

)
0
pb1:PRIMARY> db.postbacks.count(

{p: false}

)
0
pb1:PRIMARY> db.postbacks.count(

{p: false}

)
0
pb1:PRIMARY> db.postbacks.count()
3944
pb1:PRIMARY> db.postbacks.stats()
{
"ns" : "postbacks.postbacks",
"count" : 4522,
"size" : 186458896,
"avgObjSize" : 41233.72313135781,
"storageSize" : 2147483904,
"numExtents" : 2,
"nindexes" : 2,
"lastExtentSize" : 1057040,
"paddingFactor" : 1,
"flags" : 1,
"totalIndexSize" : 278528,
"indexSizes" :

{ "_id_" : 270336, "p_1" : 8192 }

,
"capped" : 1,
"max" : 2147483647,
"ok" : 1
}
pb1:PRIMARY> db.postbacks.dropIndexes()
{
"nIndexesWas" : 2,
"msg" : "non-_id indexes dropped for collection",
"ok" : 1
}
pb1:PRIMARY> db.postbacks.ensureIndex(

{ 'p' : 1}

,

{background: true}

)
interrupted at shutdown
pb1:PRIMARY> use sd
switched to db sd
Thu Mar 3 00:32:42 DBClientCursor::init call() failed
> use postbacks
switched to db postbacks
Thu Mar 3 00:32:45 trying reconnect to 127.0.0.1
Thu Mar 3 00:32:45 reconnect 127.0.0.1 ok
pb1:PRIMARY> db.repairDatabase()

{ "ok" : 1 }

pb1:PRIMARY> db.postbacks.stats()
{
"ns" : "postbacks.postbacks",
"count" : 12955,
"size" : 548969696,
"avgObjSize" : 42375.1212659205,
"storageSize" : 2147483904,
"numExtents" : 2,
"nindexes" : 0,
"lastExtentSize" : 1057040,
"paddingFactor" : 1,
"flags" : 0,
"totalIndexSize" : 0,
"indexSizes" : {

},
"capped" : 1,
"max" : 2147483647,
"ok" : 1
}
pb1:PRIMARY> db.postbacks.ensureIndex(

{ '_id' : 1}

,

{background: true}

)
pb1:PRIMARY> db.postbacks.ensureIndex(

{ 'p' : 1}

,

{background: true}

)
pb1:PRIMARY> db.postbacks.stats()
{
"ns" : "postbacks.postbacks",
"count" : 12955,
"size" : 548969696,
"avgObjSize" : 42375.1212659205,
"storageSize" : 2147483904,
"numExtents" : 2,
"nindexes" : 2,
"lastExtentSize" : 1057040,
"paddingFactor" : 1,
"flags" : 1,
"totalIndexSize" : 876544,
"indexSizes" :

{ "_id_" : 491520, "p_1" : 385024 }

,
"capped" : 1,
"max" : 2147483647,
"ok" : 1
}
pb1:PRIMARY> db.postbacks.count(

{p: false}

)
12955



 Comments   
Comment by Eliot Horowitz (Inactive) [ 04/Mar/11 ]

There were a number of fixes that might be related in 1.8.0-rc1 going out shortly.
I can't reproduce at all, so would be great if you could try with that in a few hours

Comment by David Mytton [ 04/Mar/11 ]

This was a new database on a new mongo instance. Dropping/re-indexing works fine without --dur enabled but with --dur it asserts.

Comment by Eliot Horowitz (Inactive) [ 04/Mar/11 ]

Is there any chance this db was corrupt before creating the index?
Can you try again? i.e. drop index, re-add, and see if it works

Comment by David Mytton [ 03/Mar/11 ]

Done.

david@pb1b /mongodbdata/dump/dump/postbacks: scp -P 722 postbacks.bson david@www.10gen.com:
Enter passphrase for key '/home/david/.ssh/id_rsa':
david@www.10gen.com's password:
postbacks.bson 100% 2127MB 2.8MB/s 12:54

Comment by Eliot Horowitz (Inactive) [ 03/Mar/11 ]

Sorry, should be

scp -P 722 yourfile david@www.10gen.com:

don't put anything after the colon

Comment by David Mytton [ 03/Mar/11 ]

david@pb1b /mongodbdata/dump/dump/postbacks: scp -v -P 722 david@www.10gen.com: postbacks.bson
Executing: program /usr/bin/ssh host www.10gen.com, user david, command scp -v -f .
OpenSSH_4.3p2, OpenSSL 0.9.8e-fips-rhel5 01 Jul 2008
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Applying options for *
debug1: Connecting to www.10gen.com [75.101.156.249] port 722.
debug1: Connection established.
debug1: identity file /home/david/.ssh/identity type -1
debug1: identity file /home/david/.ssh/id_rsa type -1
debug1: identity file /home/david/.ssh/id_dsa type -1
debug1: loaded 3 keys
debug1: Remote protocol version 2.0, remote software version SSHD-CORE-0.3.0
debug1: no match: SSHD-CORE-0.3.0
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_4.3
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-cbc hmac-md5 none
debug1: kex: client->server aes128-cbc hmac-md5 none
debug1: sending SSH2_MSG_KEXDH_INIT
debug1: expecting SSH2_MSG_KEXDH_REPLY
debug1: Host 'www.10gen.com' is known and matches the DSA host key.
debug1: Found key in /home/david/.ssh/known_hosts:14
debug1: ssh_dss_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: password,publickey
debug1: Next authentication method: publickey
debug1: Trying private key: /home/david/.ssh/identity
debug1: Trying private key: /home/david/.ssh/id_rsa
debug1: PEM_read_PrivateKey failed
debug1: read PEM private key done: type <unknown>
Enter passphrase for key '/home/david/.ssh/id_rsa':
debug1: read PEM private key done: type RSA
debug1: Authentications that can continue: password,publickey
debug1: Trying private key: /home/david/.ssh/id_dsa
debug1: Next authentication method: password
david@www.10gen.com's password:
debug1: Authentication succeeded (password).
debug1: channel 0: new [client-session]
debug1: Entering interactive session.
debug1: Sending environment.
debug1: Sending env LANG = en_US.UTF-8
debug1: Sending command: scp -v -f .
dispatch_protocol_error: type 100 seq 8
debug1: channel 0: free: client-session, nchannels 1
debug1: fd 0 clearing O_NONBLOCK
debug1: fd 1 clearing O_NONBLOCK
Connection to www.10gen.com closed by remote host.
debug1: Transferred: stdin 0, stdout 0, stderr 52 bytes in 0.1 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 557.4
debug1: Exit status -1

Comment by Eliot Horowitz (Inactive) [ 03/Mar/11 ]

Correct, for the public its write only.

Comment by David Mytton [ 03/Mar/11 ]

Will do. This isn't publicly accessible?

Comment by Eliot Horowitz (Inactive) [ 03/Mar/11 ]

Can you scp to us?

scp -P 722 david@www.10gen.com:
<any password>

Comment by David Mytton [ 03/Mar/11 ]

It's a couple of GB:

david@pb1b /mongodbdata/dump: ls -alh dump/postbacks/
total 2.1G
drwxrwxr-x 2 david david 53 Mar 3 17:51 .
drwxrwxr-x 3 david david 22 Mar 3 17:49 ..
rw-rw-r- 1 david david 2.1G Mar 3 17:51 postbacks.bson
rw-rw-r- 1 david david 166 Mar 3 17:51 system.indexes.bson

Comment by Eliot Horowitz (Inactive) [ 03/Mar/11 ]

Is this is a small collection?
If so, can we get a bsondump?

Comment by David Mytton [ 03/Mar/11 ]

Actually scrap that, I can reproduce with both background and not. It's durability that makes the difference - enabled = crash. not enabled = no crash.

Comment by David Mytton [ 03/Mar/11 ]

Seems to be related to using a background index - I can reproduce if I use background, but not if it's a regular blocking index creation.

Comment by David Mytton [ 03/Mar/11 ]

It's either true or false. The whole doc itself is quite big though.

Comment by Eliot Horowitz (Inactive) [ 03/Mar/11 ]

What kind of field is "p"?
Is it possible its long?

Comment by David Mytton [ 03/Mar/11 ]

Thu Mar 3 00:28:17 [conn214320] query postbacks.$cmd ntoreturn:1 command:

{ create: "postbacks", capped: true, size: 2147483648.0, max: undefined }

reslen:53 14390ms
Thu Mar 3 00:28:21 [conn5237] getmore local.oplog.rs cid:6564990938122368607 getMore: { ts:

{ $gte: new Date(5579234990782153672) }

} bytes:139 nreturned:1 19197ms
Thu Mar 3 00:28:28 [conn214320] building new index on

{ _id: 1 }

for postbacks.postbacks
Thu Mar 3 00:28:28 [conn214320] done for 0 records 0.05secs
Thu Mar 3 00:28:29 [conn214320] building new index on

{ p: 1.0 }

for postbacks.postbacks background
Thu Mar 3 00:28:29 [conn214320] done for 0 records 0.014secs
Thu Mar 3 00:28:35 [conn214320] query postbacks.$cmd ntoreturn:1 command:

{ collstats: "postbacks", scale: undefined }

reslen:284 433ms
Thu Mar 3 00:28:35 [conn214372] query metrics.$cmd ntoreturn:1 command:

{ dbstats: 1 }

reslen:224 1283ms
Thu Mar 3 00:28:54 [conn214320] postbacks.postbacks Assertion failure _a != -1 db/pdfile.h 425
0x55125e 0x562c61 0x71f157 0x78f4df 0x652eef 0x790c4a 0x796463 0x79a115 0x79c644 0x79d1e7 0x64c89b 0x7df348 0x7dbc52 0x7dcb95 0x644c55 0x649191 0x757995 0x759ec0 0x8a65ee 0x8b6a30
/home/david/mongodb/latest/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x55125e]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo8assertedEPKcS1_j+0x111) [0x562c61]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo11BtreeCursorC1EPNS_16NamespaceDetailsEiRKNS_12IndexDetailsERKN5boost10shared_ptrINS_16FieldRangeVectorEEEi+0xae7) [0x71f157]
/home/david/mongodb/latest/bin/mongod(_ZNK5mongo9QueryPlan9newCursorERKNS_7DiskLocEi+0x9df) [0x78f4df]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo7CountOp5_initEv+0x4f) [0x652eef]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo12QueryPlanSet6Runner6initOpERNS_7QueryOpE+0x11a) [0x790c4a]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo12QueryPlanSet6Runner3runEv+0x333) [0x796463]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo12QueryPlanSet5runOpERNS_7QueryOpE+0x255) [0x79a115]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo16MultiPlanScanner9runOpOnceERNS_7QueryOpE+0x64) [0x79c644]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo16MultiPlanScanner5runOpERNS_7QueryOpE+0x17) [0x79d1e7]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo8runCountEPKcRKNS_7BSONObjERSs+0x3cb) [0x64c89b]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo8CmdCount3runERKSsRNS_7BSONObjERSsRNS_14BSONObjBuilderEb+0xa8) [0x7df348]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo11execCommandEPNS_7CommandERNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0x9e2) [0x7dbc52]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_10BufBuilderERNS_14BSONObjBuilderEbi+0x895) [0x7dcb95]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo11runCommandsEPKcRNS_7BSONObjERNS_5CurOpERNS_10BufBuilderERNS_14BSONObjBuilderEbi+0x35) [0x644c55]
/home/david/mongodb/latest/bin/mongod(ZN5mongo8runQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1+0x32e1) [0x649191]
/home/david/mongodb/latest/bin/mongod [0x757995]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x5b0) [0x759ec0]
/home/david/mongodb/latest/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a65ee]
/home/david/mongodb/latest/bin/mongod(thread_proxy+0x80) [0x8b6a30]
Thu Mar 3 00:28:55 [conn214320] Count with ns: postbacks.postbacks and query:

{ p: false }

failed with exception: exception: 0 assertion db/pdfile.h:425

Generated at Thu Feb 08 03:00:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.