[SERVER-8242] assertion failures (btree) during repair Created: 18/Jan/13  Updated: 10/Dec/14  Resolved: 03/Jun/13

Status: Closed
Project: Core Server
Component/s: Admin
Affects Version/s: 2.2.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Zac Witte Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

ubuntu on EC2


Attachments: Text File mongo1_repair.log     Text File mongo2_repair.log     Text File mongo3_repair.log    
Issue Links:
Related
related to SERVER-8241 assertion failures (saveerrmsg) durin... Closed
related to SERVER-8917 buildBottomUpPhases2And3 should check... Closed
Operating System: ALL
Participants:

 Description   

Was running a repair with the following command and got this assertion error in the log of 1 out of 3 shards. The other shards had a different assertion error, which I filed a different bug for:

ubuntu@mongo3:~$ mongod --version
db version v2.2.0, pdfile version 4.5
Fri Jan 18 20:56:42 git version: f5e83eae9cfbec7fb7a071321928f00d1b0c5207

sudo -u mongodb mongod --dbpath=/db/mongodb --repair --repairpath=/export/mongodb --nojournal

Fri Jan 18 03:25:59 [initandlisten] 47127700/861940368 5%
Fri Jan 18 03:26:09 [initandlisten] 47232800/861940368 5%
Fri Jan 18 03:26:19 [initandlisten] 47342500/861940368 5%
Fri Jan 18 03:26:29 [initandlisten] 47451000/861940368 5%
Fri Jan 18 03:26:39 [initandlisten] 47560200/861940368 5%
Fri Jan 18 03:26:49 [initandlisten] 47665300/861940368 5%
Fri Jan 18 03:26:59 [initandlisten] 47774400/861940368 5%
Fri Jan 18 03:27:09 [initandlisten] 47881800/861940368 5%
Fri Jan 18 03:27:19 [initandlisten] 47988500/861940368 5%
Fri Jan 18 03:27:29 [initandlisten] 48097900/861940368 5%
Fri Jan 18 03:27:39 [initandlisten] 48207400/861940368 5%
Fri Jan 18 03:27:49 [initandlisten] 48313200/861940368 5%
Fri Jan 18 03:27:59 [initandlisten] 48422400/861940368 5%
Fri Jan 18 03:28:00 [initandlisten] pb3 Assertion failure la <= 0xffffff src/mongo/db/btree.h 243
0xade6e1 0x803dfd 0x683ebb 0xb1e868 0xae7d19 0xae15ed 0xae46e7 0x747ed3 0x7490bd 0xae2c0d 0x737f9c 0x8535bc 0x8560c9 0x856269 0x74037a 0x5596d8 0x55b78d 0x55c6f0 0x55d2dd 0x563dbe
mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xade6e1]
mongod(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0x803dfd]
mongod(ZN5mongo12BucketBasicsINS_12BtreeData_V1EE9_pushBackENS_7DiskLocERKNS_5KeyV1ERKNS_8OrderingES3+0x8ab) [0x683ebb]
mongod(_ZN5mongo12BtreeBuilderINS_12BtreeData_V1EE6addKeyERNS_7BSONObjENS_7DiskLocE+0x2a8) [0xb1e868]
mongod(_ZN5mongo24buildBottomUpPhases2And3INS_12BtreeData_V1EEEvbRNS_12IndexDetailsERNS_21BSONObjExternalSorterEbRSt3setINS_7DiskLocESt4lessIS7_ESaIS7_EEPNS_5CurOpEPNS_12SortPhaseOneERNS_19ProgressMeterHolderERNS_5TimerE+0x1f9) [0xae7d19]
mongod(_ZN5mongo14fastBuildIndexEPKcPNS_16NamespaceDetailsERNS_12IndexDetailsEi+0xc9d) [0xae15ed]
mongod(_ZN5mongo12buildAnIndexESsPNS_16NamespaceDetailsERNS_12IndexDetailsEib+0x217) [0xae46e7]
mongod(_ZN5mongo16insert_makeIndexEPNS_16NamespaceDetailsERKSsRKNS_7DiskLocE+0x1f3) [0x747ed3]
mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibbPb+0x93d) [0x7490bd]
mongod(_ZN5mongo17ensureHaveIdIndexEPKc+0x7ad) [0xae2c0d]
mongod(_ZN5mongo21ensureIdIndexForNewNsEPKc+0x9c) [0x737f9c]
mongod(_ZN5mongo6Cloner2goEPKcRKNS_12CloneOptionsERSt3setISsSt4lessISsESaISsEERSsPi+0xd1c) [0x8535bc]
mongod(_ZN5mongo6Cloner2goEPKcRSsRKSsbbbbbbPi+0x139) [0x8560c9]
mongod(_ZN5mongo9cloneFromEPKcRSsRKSsbbbbbbPi+0x59) [0x856269]
mongod(_ZN5mongo14repairDatabaseESsRSsbb+0x52a) [0x74037a]
mongod(_ZN5mongo11doDBUpgradeERKSsSsPNS_14DataFileHeaderE+0x68) [0x5596d8]
mongod() [0x55b78d]
mongod(_ZN5mongo14_initAndListenEi+0x480) [0x55c6f0]
mongod(_ZN5mongo13initAndListenEi+0x1d) [0x55d2dd]
mongod() [0x563dbe]
Fri Jan 18 03:28:00 [initandlisten] Assertion: 16394:reading doc for external sort failed:errno:2 No such file or directory
0xade6e1 0x8036eb 0x80386c 0x909535 0x909c10 0xae7bff 0xae15ed 0xae46e7 0x747ed3 0x7490bd 0xae2c0d 0x737f9c 0x8535bc 0x8560c9 0x856269 0x74037a 0x5596d8 0x55b78d 0x55c6f0 0x55d2dd
mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xade6e1]
mongod(_ZN5mongo11msgassertedEiPKc+0x9b) [0x8036eb]
mongod() [0x80386c]
mongod(_ZN5mongo21BSONObjExternalSorter12FileIterator4nextEv+0xc5) [0x909535]
mongod(_ZN5mongo21BSONObjExternalSorter8Iterator4nextEv+0x220) [0x909c10]
mongod(_ZN5mongo24buildBottomUpPhases2And3INS_12BtreeData_V1EEEvbRNS_12IndexDetailsERNS_21BSONObjExternalSorterEbRSt3setINS_7DiskLocESt4lessIS7_ESaIS7_EEPNS_5CurOpEPNS_12SortPhaseOneERNS_19ProgressMeterHolderERNS_5TimerE+0xdf) [0xae7bff]
mongod(_ZN5mongo14fastBuildIndexEPKcPNS_16NamespaceDetailsERNS_12IndexDetailsEi+0xc9d) [0xae15ed]
mongod(_ZN5mongo12buildAnIndexESsPNS_16NamespaceDetailsERNS_12IndexDetailsEib+0x217) [0xae46e7]
mongod(_ZN5mongo16insert_makeIndexEPNS_16NamespaceDetailsERKSsRKNS_7DiskLocE+0x1f3) [0x747ed3]
mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibbPb+0x93d) [0x7490bd]
mongod(_ZN5mongo17ensureHaveIdIndexEPKc+0x7ad) [0xae2c0d]
mongod(_ZN5mongo21ensureIdIndexForNewNsEPKc+0x9c) [0x737f9c]
mongod(_ZN5mongo6Cloner2goEPKcRKNS_12CloneOptionsERSt3setISsSt4lessISsESaISsEERSsPi+0xd1c) [0x8535bc]
mongod(_ZN5mongo6Cloner2goEPKcRSsRKSsbbbbbbPi+0x139) [0x8560c9]
mongod(_ZN5mongo9cloneFromEPKcRSsRKSsbbbbbbPi+0x59) [0x856269]
mongod(_ZN5mongo14repairDatabaseESsRSsbb+0x52a) [0x74037a]
mongod(_ZN5mongo11doDBUpgradeERKSsSsPNS_14DataFileHeaderE+0x68) [0x5596d8]
mongod() [0x55b78d]
mongod(_ZN5mongo14_initAndListenEi+0x480) [0x55c6f0]
mongod(_ZN5mongo13initAndListenEi+0x1d) [0x55d2dd]
Fri Jan 18 03:28:08 [initandlisten] exception in initAndListen: 16394 reading doc for external sort failed:errno:2 No such file or directory, terminating
Fri Jan 18 03:28:08 dbexit:
Fri Jan 18 03:28:08 [initandlisten] shutdown: going to close listening sockets...
Fri Jan 18 03:28:08 [initandlisten] shutdown: going to flush diaglog...
Fri Jan 18 03:28:08 [initandlisten] shutdown: going to close sockets...
Fri Jan 18 03:28:08 [initandlisten] shutdown: waiting for fs preallocator...
Fri Jan 18 03:28:08 [initandlisten] shutdown: closing all files...
Fri Jan 18 03:28:10 [initandlisten] 119/824 14%
Fri Jan 18 03:28:12 [initandlisten] 402/824 48%
Fri Jan 18 03:28:14 [initandlisten] 448/824 54%
Fri Jan 18 03:28:16 [initandlisten] 455/824 55%
Fri Jan 18 03:28:18 [initandlisten] 464/824 56%
Fri Jan 18 03:28:20 [initandlisten] 573/824 69%
Fri Jan 18 03:28:22 [initandlisten] 580/824 70%
Fri Jan 18 03:28:24 [initandlisten] 605/824 73%
Fri Jan 18 03:28:26 [initandlisten] 671/824 81%
Fri Jan 18 03:28:27 [initandlisten] closeAllFiles() finished
Fri Jan 18 03:28:27 [initandlisten] shutdown: removing fs lock...
Fri Jan 18 03:28:27 dbexit: really exiting now



 Comments   
Comment by Daniel Pasette (Inactive) [ 03/Jun/13 ]

Looks to be the same problem as SERVER-8241 in which the index build in the dbpath caused disk space issues. Can't say for sure without more data.

Comment by Aaron Staple [ 21/Mar/13 ]

Hi Zac,

One other thing to be aware of is that the temporary external sort files go inside _tmp within your dbpath not your repair path. So a disk error including out of disk space on the partition containing /db/mongodb could cause this issue.

We have
SERVER-8917
SERVER-8449

to improve reporting when there is an error during a repair operation.

For this ticket and SERVER-8241, if you know your index sizes and amount of free space on /db/mongodb at the time of the error we may be able to determine whether a repair run under these conditions could have exhausted disk space.

Comment by Zac Witte [ 24/Jan/13 ]

OK so it sounds like mongod needs to be more robust in how it reads in files and retries on failure. At the very least it needs more user-friendly error messages.

Comment by Aaron Staple [ 23/Jan/13 ]

Hi Zac,

Here's some analysis of the two assertions described in the log. But first some background info:

A foreground index build is implemented in three phases:

1) The whole collection is scanned, and for each document in the collection the set of keys that will appear in the index are extracted from the document. The keys for all documents, along with the locations of these documents, are saved into a set of temporary external sort files in a temporary directory ( named _tmp ) within your dbpath. (The keys within each external sort file are sorted, but there is no sorting relationship between the different files.)

2) A merge sort over the external sort files is used to iterate over all the keys in the external sort files, in order. The keys are used to build the leaves of a new btree.

3) The internal nodes of the btree are built up based on the leaves of the btree.

The first error in the log, about "la <= 0xffffff" is occurring because an invalid document location is being passed from an external sort file to a new btree leaf as part of step 2.

The second error in the log, about "reading doc for external sort failed" describes an error reading an external sort file. It looks like it's occurring while reading an index key from the external sort file. It looks like part of the key is read but there is an error while reading the rest of the key.

I believe what's happening is that the implementation assumes the first error is a dup key error, even though it seems to result from a bad read of the external sort file. Then it continues trying to read from the external sort file until it sees the second error and at that point fails.

Comment by Zac Witte [ 22/Jan/13 ]

I no longer have the full logs, but I have the excerpts where the exceptions occurred. I'll attach them here. I think everything looked normal until this exception. The /export partition did not run out of disk space, but it is possible that the EBS volumes or the network connection had a hiccup. That kind of thing is always possible with EC2. It is strange that all 3 servers had these assertion errors at different times, though.

I noticed this in my syslog but I can't be sure if it's related since there's no way to match timestamps:

[11797218.035099] md/raid0:md100: md_size is 10737408000 sectors.
[11797218.035101] ******* md100 configuration *********
[11797218.035103] zone0=[xvdi1/xvdi2/xvdi3/xvdi4/xvdi5/]
[11797218.035109] zone offset=0kb device offset=0kb size=5368704000kb
[11797218.035111] **********************************
[11797218.035112]
[11797218.035126] md100: detected capacity change from 0 to 5497552896000
[11797218.040469] md100: unknown partition table
[11797321.696348] XFS (md100): Mounting Filesystem
[11797321.871849] XFS (md100): Ending clean mount
[11945966.207563] INFO: task kworker/0:1:23258 blocked for more than 120 seconds.
[11945966.207579] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[11945966.207589] kworker/0:1 D ffff881116ee2940 0 23258 2 0x00000000
[11945966.207596] ffff88001c45bcc0 0000000000000246 ffff88001c45ba44 0000000000000000
[11945966.207603] ffff88001c45bfd8 ffff88001c45bfd8 ffff88001c45bfd8 0000000000012940
[11945966.207610] ffff8810a3b00000 ffff8810a0d2dc00 ffffffff8160380e ffff8810a1337c18
[11945966.207615] Call Trace:
[11945966.207627] [<ffffffff8160380e>] ? _raw_spin_unlock_irqrestore+0x1e/0x30
[11945966.207661] [<ffffffffa00df811>] _xfs_log_force_lsn+0x171/0x2e0 [xfs]
[11945966.207668] [<ffffffff810570e0>] ? try_to_wake_up+0x200/0x200
[11945966.207685] [<ffffffffa00ececd>] _xfs_trans_commit+0x29d/0x2b0 [xfs]
[11945966.207702] [<ffffffffa0100c30>] ? xfs_sync_inode_attr+0xf0/0xf0 [xfs]
[11945966.207720] [<ffffffffa00d00c4>] xfs_fs_log_dummy+0x64/0x90 [xfs]
[11945966.207740] [<ffffffffa0100cb4>] xfs_sync_worker+0x84/0x90 [xfs]
[11945966.207749] [<ffffffff8107af3a>] process_one_work+0x11a/0x480
[11945966.207755] [<ffffffff8110af47>] ? mempool_free_slab+0x17/0x20
[11945966.207758] [<ffffffff8107bcdf>] worker_thread+0x15f/0x360
[11945966.207761] [<ffffffff8107bb80>] ? manage_workers.isra.30+0x130/0x130
[11945966.207766] [<ffffffff810807bc>] kthread+0x8c/0xa0
[11945966.207770] [<ffffffff8160cae4>] kernel_thread_helper+0x4/0x10
[11945966.207774] [<ffffffff8160bbe3>] ? int_ret_from_sys_call+0x7/0x1b
[11945966.207778] [<ffffffff81603b61>] ? retint_restore_args+0x5/0x6
[11945966.207781] [<ffffffff8160cae0>] ? gs_change+0x13/0x13

Comment by Aaron Staple [ 22/Jan/13 ]

Hi Zac - Can you send the full log? Also, is it possible there was a disk error or you ran out of disk space while the repair was running?

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