--rwEMma7ioTxnRzrJ Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Hi Howard, Thanks for the quick reply. On Sat, Mar 26, 2016 at 06:44:29PM +0000, Howard Chu wrote: This entire process is read only, and indeed the transactions that contain cursors are marked RDONLY. No other process is running that accesses any of these databases. Ok, I've done all that and got debug output going. I can still provoke the same problem easily. A log is attached. Ultimately, both cursors should start on a key 0000000000000000000000000000000000000000, but the second cursor/db discovers it actually starts on 0000000000000000000000000000000141d8872b. One problem is that the debug output gives no indication of which thread is which so it seems pretty tricky to separate out the different calls. Do you have any hints or tricks for doing this? Matthew --rwEMma7ioTxnRzrJ Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename=log GoshawkDBConsistencyChecker 2016/03/26 20:58:25.362121 [./consistencychecker /tmp/data1 /tmp/data2] GoshawkDBConsistencyChecker 2016/03/26 20:58:25.362201 ...loading from /tmp/data1 GoshawkDBConsistencyChecker 2016/03/26 20:58:25.362223 Starting disk server on /tmp/data1 mdb_env_open2:4175 opened database version 1, pagesize 4096 mdb_env_open2:4176 using meta page 0 mdb_env_open2:4177 depth: 1 mdb_env_open2:4178 entries: 5 mdb_env_open2:4179 branch pages: 0 mdb_env_open2:4180 leaf pages: 1 mdb_env_open2:4181 overflow pages: 0 mdb_env_open2:4182 root: 1192 mdb_env_open:4803 opened dbenv 0xd363c0 mdb_txn_begin:2850 begin txn 1785w 0xd37660 on mdbenv 0xd363c0, root page 1192 mdb_page_search:5426 db 1 root page 1192 has flags 0x2 mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e52656673] mdb_node_search:5072 searching 5 keys in leaf page 1192 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e52656673] mdb_page_search:5426 db 1 root page 1192 has flags 0x2 mdb_page_search_root:5323 found leaf page 1192 for key [56617273] mdb_node_search:5072 searching 5 keys in leaf page 1192 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2 mdb_node_search:5116 found leaf index 4 [56617273], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [56617273] mdb_page_search:5426 db 1 root page 1192 has flags 0x2 mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e73] mdb_node_search:5072 searching 5 keys in leaf page 1192 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e73] mdb_txn_end:2918 empty-commit txn 1785w 0xd37660 on mdbenv 0xd363c0, root page 1192 mdb_txn_begin:2850 begin txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192 mdb_txn_end:2918 abort txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192 mdb_txn_begin:2850 begin txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192 mdb_get:5556 ===> get db 3 key [0000000000000000000000000000000000000000] mdb_page_search:5426 db 1 root page 1192 has flags 0x2 mdb_page_search_root:5323 found leaf page 1192 for key [56617273] mdb_node_search:5072 searching 5 keys in leaf page 1192 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2 mdb_node_search:5116 found leaf index 4 [56617273], rc = 0 mdb_page_search:5426 db 3 root page 854 has flags 0x1 mdb_page_search:5426 db 3 root page 854 has flags 0x1 mdb_page_search_root:5271 branch page 854 has 2 keys mdb_page_search_root:5277 found index 0 to page 868 mdb_node_search:5072 searching 2 keys in branch page 854 mdb_node_search:5119 found branch index 1 [00000000000001f500000006000000016634c9ee -> 734], rc = -1 mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000] mdb_cursor_push:5183 pushing page 868 on db 3 cursor 0x7f36f0d5e6c0 mdb_page_search_root:5271 branch page 868 has 135 keys mdb_page_search_root:5277 found index 0 to page 96 mdb_node_search:5072 searching 135 keys in branch page 868 mdb_node_search:5119 found branch index 67 [00000000000000c600000006000000016634c9ee -> 65], rc = -50688 mdb_node_search:5119 found branch index 33 [000000000000005a00000006000000016634c9ee -> 61], rc = -23040 mdb_node_search:5119 found branch index 16 [000000000000001900000006000000016634c9ee -> 964], rc = -6400 mdb_node_search:5119 found branch index 8 [000000000000000f00000006000000016634c9ee -> 72], rc = -3840 mdb_node_search:5119 found branch index 4 [000000000000000500000006000000016634c9ee -> 124], rc = -1280 mdb_node_search:5119 found branch index 2 [000000000000000100000004000000016634c9ee -> 1021], rc = -256 mdb_node_search:5119 found branch index 1 [000000000000000000000006000000016634c9ee -> 869], rc = -1536 mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000] mdb_cursor_push:5183 pushing page 96 on db 3 cursor 0x7f36f0d5e6c0 mdb_page_search_root:5323 found leaf page 96 for key [0000000000000000000000000000000000000000] mdb_node_search:5072 searching 7 keys in leaf page 96 mdb_node_search:5116 found leaf index 3 [000000000000000000000000000000019f23085d], rc = -256 mdb_node_search:5116 found leaf index 1 [0000000000000000000000000000000141d8872b], rc = -256 mdb_node_search:5116 found leaf index 0 [0000000000000000000000000000000000000000], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [0000000000000000000000000000000000000000] mdb_get:5556 ===> get db 4 key [000000000000000100000000000000019f23085d] mdb_page_search:5426 db 1 root page 1192 has flags 0x2 mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e73] mdb_node_search:5072 searching 5 keys in leaf page 1192 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0 mdb_page_search:5426 db 4 root page 592 has flags 0x1 mdb_page_search:5426 db 4 root page 592 has flags 0x1 mdb_page_search_root:5271 branch page 592 has 128 keys mdb_page_search_root:5277 found index 0 to page 37 mdb_node_search:5072 searching 128 keys in branch page 592 mdb_node_search:5119 found branch index 64 [00000000000001fe000000000000000141d8872b -> 565], rc = -1 mdb_node_search:5119 found branch index 32 [00000000000000fe00000000000000019f23085d -> 461], rc = -64768 mdb_node_search:5119 found branch index 16 [000000000000007300000000000000016634c9ee -> 323], rc = -29184 mdb_node_search:5119 found branch index 8 [000000000000003f000000000000000141d8872b -> 20], rc = -15872 mdb_node_search:5119 found branch index 4 [000000000000001200000000000000019f23085d -> 448], rc = -4352 mdb_node_search:5119 found branch index 2 [000000000000000200000000000000019f23085d -> 141], rc = -256 mdb_node_search:5119 found branch index 1 [000000000000000100000000000000019f23085d -> 142], rc = 0 mdb_page_search_root:5295 following index 1 for key [000000000000000100000000000000019f23085d] mdb_cursor_push:5183 pushing page 142 on db 4 cursor 0x7f36f0d5e6c0 mdb_page_search_root:5323 found leaf page 142 for key [000000000000000100000000000000019f23085d] mdb_node_search:5072 searching 3 keys in leaf page 142 mdb_node_search:5116 found leaf index 1 [0000000000000002000000000000000141d8872b], rc = -256 mdb_node_search:5116 found leaf index 0 [000000000000000100000000000000019f23085d], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [000000000000000100000000000000019f23085d] mdb_txn_end:2918 reset txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192 GoshawkDBConsistencyChecker 2016/03/26 20:58:25.364770 ...loading from /tmp/data2 GoshawkDBConsistencyChecker 2016/03/26 20:58:25.364807 Starting disk server on /tmp/data2 mdb_env_open2:4175 opened database version 1, pagesize 4096 mdb_env_open2:4176 using meta page 1 mdb_env_open2:4177 depth: 1 mdb_env_open2:4178 entries: 5 mdb_env_open2:4179 branch pages: 0 mdb_env_open2:4180 leaf pages: 1 mdb_env_open2:4181 overflow pages: 0 mdb_env_open2:4182 root: 1239 mdb_env_open:4803 opened dbenv 0x7f36e00008c0 mdb_txn_begin:2850 begin txn 1858w 0x7f36e0001b80 on mdbenv 0x7f36e00008c0, root page 1239 mdb_page_search:5426 db 1 root page 1239 has flags 0x2 mdb_page_search_root:5323 found leaf page 1239 for key [5472616e73616374696f6e73] mdb_node_search:5072 searching 5 keys in leaf page 1239 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e73] mdb_page_search:5426 db 1 root page 1239 has flags 0x2 mdb_page_search_root:5323 found leaf page 1239 for key [5472616e73616374696f6e52656673] mdb_node_search:5072 searching 5 keys in leaf page 1239 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e52656673] mdb_page_search:5426 db 1 root page 1239 has flags 0x2 mdb_page_search_root:5323 found leaf page 1239 for key [56617273] mdb_node_search:5072 searching 5 keys in leaf page 1239 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2 mdb_node_search:5116 found leaf index 4 [56617273], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [56617273] mdb_txn_end:2918 empty-commit txn 1858w 0x7f36e0001b80 on mdbenv 0x7f36e00008c0, root page 1239 mdb_txn_begin:2850 begin txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239 mdb_txn_end:2918 abort txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239 mdb_txn_begin:2850 begin txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239 mdb_get:5556 ===> get db 4 key [0000000000000000000000000000000000000000] mdb_page_search:5426 db 1 root page 1239 has flags 0x2 mdb_page_search_root:5323 found leaf page 1239 for key [56617273] mdb_node_search:5072 searching 5 keys in leaf page 1239 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2 mdb_node_search:5116 found leaf index 4 [56617273], rc = 0 mdb_page_search:5426 db 4 root page 633 has flags 0x1 mdb_page_search:5426 db 4 root page 633 has flags 0x1 mdb_page_search_root:5271 branch page 633 has 2 keys mdb_page_search_root:5277 found index 0 to page 634 mdb_node_search:5072 searching 2 keys in branch page 633 mdb_node_search:5119 found branch index 1 [00000000000000f900000006000000016634c9ee -> 115], rc = -63744 mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000] mdb_cursor_push:5183 pushing page 634 on db 4 cursor 0x7f36f055d6c0 mdb_page_search_root:5271 branch page 634 has 68 keys mdb_page_search_root:5277 found index 0 to page 56 mdb_node_search:5072 searching 68 keys in branch page 634 mdb_node_search:5119 found branch index 34 [000000000000006100000006000000016634c9ee -> 562], rc = -24832 mdb_node_search:5119 found branch index 17 [000000000000001c00000006000000016634c9ee -> 18], rc = -7168 mdb_node_search:5119 found branch index 8 [000000000000000e00000006000000016634c9ee -> 160], rc = -3584 mdb_node_search:5119 found branch index 4 [000000000000000400000006000000016634c9ee -> 405], rc = -1024 mdb_node_search:5119 found branch index 2 [000000000000000100000004000000016634c9ee -> 489], rc = -256 mdb_node_search:5119 found branch index 1 [000000000000000000000006000000016634c9ee -> 636], rc = -1536 mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000] mdb_cursor_push:5183 pushing page 56 on db 4 cursor 0x7f36f055d6c0 mdb_page_search_root:5323 found leaf page 56 for key [0000000000000000000000000000000000000000] mdb_node_search:5072 searching 7 keys in leaf page 56 mdb_node_search:5116 found leaf index 3 [000000000000000000000000000000019f23085d], rc = -256 mdb_node_search:5116 found leaf index 1 [0000000000000000000000000000000141d8872b], rc = -256 mdb_node_search:5116 found leaf index 0 [0000000000000000000000000000000000000000], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [0000000000000000000000000000000000000000] mdb_get:5556 ===> get db 2 key [000000000000000100000000000000019f23085d] mdb_page_search:5426 db 1 root page 1239 has flags 0x2 mdb_page_search_root:5323 found leaf page 1239 for key [5472616e73616374696f6e73] mdb_node_search:5072 searching 5 keys in leaf page 1239 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0 mdb_page_search:5426 db 2 root page 606 has flags 0x1 mdb_page_search:5426 db 2 root page 606 has flags 0x1 mdb_page_search_root:5271 branch page 606 has 128 keys mdb_page_search_root:5277 found index 0 to page 8 mdb_node_search:5072 searching 128 keys in branch page 606 mdb_node_search:5119 found branch index 64 [0000000000000219000000000000000141d8872b -> 414], rc = -2 mdb_node_search:5119 found branch index 32 [00000000000000fe00000000000000019f23085d -> 832], rc = -64768 mdb_node_search:5119 found branch index 16 [000000000000007400000000000000016634c9ee -> 85], rc = -29440 mdb_node_search:5119 found branch index 8 [000000000000003f000000000000000141d8872b -> 108], rc = -15872 mdb_node_search:5119 found branch index 4 [000000000000001200000000000000019f23085d -> 10], rc = -4352 mdb_node_search:5119 found branch index 2 [000000000000000200000000000000019f23085d -> 19], rc = -256 mdb_node_search:5119 found branch index 1 [000000000000000100000000000000019f23085d -> 33], rc = 0 mdb_page_search_root:5295 following index 1 for key [000000000000000100000000000000019f23085d] mdb_cursor_push:5183 pushing page 33 on db 2 cursor 0x7f36f055d6c0 mdb_page_search_root:5323 found leaf page 33 for key [000000000000000100000000000000019f23085d] mdb_node_search:5072 searching 3 keys in leaf page 33 mdb_node_search:5116 found leaf index 1 [0000000000000002000000000000000141d8872b], rc = -256 mdb_node_search:5116 found leaf index 0 [000000000000000100000000000000019f23085d], rc = 0 mdb_cursor_set:5980 ==> cursor placed on key [000000000000000100000000000000019f23085d] mdb_txn_end:2918 reset txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239 mdb_txn_renew:2750 renew txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239 mdb_page_search:5426 db 1 root page 1239 has flags 0x2 mdb_page_search_root:5323 found leaf page 1239 for key [56617273] mdb_node_search:5072 searching 5 keys in leaf page 1239 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2 mdb_node_search:5116 found leaf index 4 [56617273], rc = 0 mdb_page_search:5426 db 4 root page 633 has flags 0x1 mdb_page_search:5426 db 4 root page 633 has flags 0x1 mdb_page_search_root:5271 branch page 633 has 2 keys mdb_page_search_root:5277 found index 0 to page 634 mdb_cursor_push:5183 pushing page 634 on db 4 cursor 0x7f36e4000bd0 mdb_page_search_root:5271 branch page 634 has 68 keys mdb_page_search_root:5277 found index 0 to page 56 mdb_cursor_push:5183 pushing page 56 on db 4 cursor 0x7f36e4000bd0 mdb_page_search_root:5323 found leaf page 56 for key [null] RM:9f23085d(/tmp/data2) VarUUId:0000000000000000000000000000000000000000 [0 0 0 0 26 0 0 0 0 0 0 0 0 0 5 0 17 0 0 0 162 0 0 0 25 0 0 0 2 0 0 0 21 0 0 0 162 0 0 0 28 0 0 0 0 0 2 0 52 0 0 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 1 159 35 8 93 0 0 0 0 5 0 0 0 14 0 0 0 17 0 0 0 13 0 0 0 1 0 0 0 162 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0 5 0 0 0 14 0 0 0 5 0 0 0 13 0 0 0 5 0 0 0 162 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] mdb_txn_renew:2750 renew txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192 mdb_page_search:5426 db 1 root page 1192 has flags 0x2 mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e73] mdb_node_search:5072 searching 5 keys in leaf page 1192 mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448 mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0 mdb_page_search:5426 db 4 root page 592 has flags 0x1 mdb_page_search:5426 db 4 root page 592 has flags 0x1 mdb_page_search_root:5271 branch page 592 has 128 keys mdb_page_search_root:5277 found index 0 to page 37 mdb_cursor_push:5183 pushing page 37 on db 4 cursor 0x7f36e8000bd0 mdb_page_search_root:5323 found leaf page 37 for key [null] mdb_txn_end:2918 reset txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192 GoshawkDBConsistencyChecker 2016/03/26 20:58:25.367498 Shutting down iterator GoshawkDBConsistencyChecker 2016/03/26 20:58:25.367507 Err on finding first var in RM:6634c9ee(/tmp/data1): expected to find topology var, but found VarUUId:0000000000000000000000000000000141d8872b instead! ([0 0 0 0 30 0 0 0 0 0 0 0 2 0 3 0 43 135 216 65 1 0 0 0 0 2 0 0 2 0 0 0 9 0 0 0 162 0 0 0 17 0 0 0 47 0 0 0 57 0 0 0 55 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 65 216 135 43 0 0 0 0 4 0 0 0 1 0 4 0 3 0 0 0 0 0 0 0 13 0 0 0 162 0 0 0 21 0 0 0 42 0 0 0 21 0 0 0 2 0 0 0 17 0 0 0 7 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 65 216 135 43 0 0 0 0 0 1 2 3 4 0 0 0 0 0 0 0 0 0 2 0 12 0 0 0 1 0 1 0 238 201 52 102 1 0 0 0 17 0 0 0 11 0 0 0 93 8 35 159 1 0 0 0 13 0 0 0 11 0 0 0 43 135 216 65 0 0 0 0 9 0 0 0 11 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]) --rwEMma7ioTxnRzrJ--