Block cache: PANIC: hash_remove_current(): invalid iteration state

[bonefish]

hrev35472 with my changes up to hrev35485; gcc4 hybrid

Encountered after clean Haiku build and "rm -rf haiku.image objects". Haven't tried to reproduce it yet.

kdebug> message
hash_remove_current(): invalid iteration state
kdebug> bt
stack trace for thread 35690 "rm"
    kernel stack: 0x8088c000 to 0x80890000
      user stack: 0x7efef000 to 0x7ffef000
frame               caller     <image>:function + offset
 0 8088f7d8 (+  32) 8006e165   <kernel_x86> invoke_command_trampoline(void*: 0x8088f858) + 0x0015
 1 8088f7f8 (+  12) 800e170c   <kernel_x86>:arch_debug_call_with_fault_handler + 0x001b
 2 8088f804 (+  48) 8006c05a   <kernel_x86>:debug_call_with_fault_handler + 0x0051
 3 8088f834 (+  64) 8006e4e2   <kernel_x86>:invoke_debugger_command + 0x00bb
 4 8088f874 (+  48) 8006e5ff   <kernel_x86> invoke_pipe_segment(debugger_command_pipe*: 0x80134e22, int32: 0, char*: NULL) + 0x0083
 5 8088f8a4 (+  32) 8006e6c7   <kernel_x86>:invoke_debugger_command_pipe + 0x008b
 6 8088f8c4 (+ 128) 80072452   <kernel_x86> ExpressionParser<0x8088f994>::_ParseCommandPipe(int&: 0x8088f990) + 0x0aae
 7 8088f944 (+  48) 80074c1b   <kernel_x86> ExpressionParser<0x8088f994>::EvaluateCommand(char const*: 0x80134e20 "bt", int&: 0x8088f990) + 0x06df
 8 8088f974 (+ 192) 80074d94   <kernel_x86>:evaluate_debug_command + 0x0084
 9 8088fa34 (+  96) 8006ce2d   <kernel_x86> kernel_debugger_internal(char const*: 0x82016ab8 "��..", int32: -2138506560) + 0x039a
10 8088fa94 (+  16) 8006cf83   <kernel_x86>:kernel_debugger + 0x0019
11 8088faa4 (+ 160) 8006d045   <kernel_x86>:panic + 0x002a
12 8088fb44 (+  48) 800c0bd8   <kernel_x86>:hash_remove_current + 0x003d
13 8088fb74 (+ 144) 8003e527   <kernel_x86>:cache_sync_transaction + 0x0148
14 8088fc04 (+  48) 809c5157   <bfs> Journal<0x8203e690>::_TransactionDone(true) + 0x00c5
15 8088fc34 (+  48) 809c5e98   <bfs> Journal<0x8203e690>::Unlock(Transaction*: 0x8088fc88, true) + 0x0054
16 8088fc64 (+  64) 809ce8c1   <bfs> bfs_remove_vnode(fs_volume*: 0xcfd167f8, fs_vnode*: 0xd171abf4, true) + 0x0119
17 8088fca4 (+  32) 800a6221   <kernel_x86> free_vnode(vnode*: 0x10001, true) + 0x0093
18 8088fcc4 (+  32) 800a9632   <kernel_x86> dec_vnode_ref_count(vnode*: 0x809d3b44, true, true) + 0x0232
19 8088fce4 (+  16) 800a9d96   <kernel_x86>:put_vnode + 0x007f
20 8088fcf4 (+  64) 809c5e33   <bfs> Transaction<0x8088fdcc>::UnlockInodes(true) + 0x01d9
21 8088fd34 (+  48) 809c5eb7   <bfs> Journal<0x8203e690>::Unlock(Transaction*: 0x8088fdcc, true) + 0x0073
22 8088fd64 (+  32) 809b3555   <bfs> Transaction<0x8088fdcc>::Done() + 0x002b
23 8088fd84 (+ 112) 809cd765   <bfs> bfs_unlink(fs_volume*: 0xcfd167f8, fs_vnode*: 0xcf223d48, char const*: 0x8088fe1c "ConfigView.o") + 0x00d5
24 8088fdf4 (+ 304) 800aeb70   <kernel_x86> common_unlink(int32: 1025, char*: 0x828c1420, true) + 0x0050
25 8088ff24 (+  32) 800aec0d   <kernel_x86>:_user_unlink + 0x007f
26 8088ff44 (+ 100) 800e1ce2   <kernel_x86>:handle_syscall + 0x00af
user iframe at 0x8088ffa8 (end = 0x80890000)
 eax 0x6e           ebx 0x2d4d28        ecx 0x7ffee93c   edx 0xffff0114
 esi 0x0            edi 0x0             ebp 0x7ffee958   esp 0x8088ffdc
 eip 0xffff0114  eflags 0x216      user esp 0x7ffee93c
 vector: 0x63, error code: 0x0
27 8088ffa8 (+   0) ffff0114   <commpage>:commpage_syscall + 0x0004
28 7ffee958 (+ 576) 00207661   <_APP_>:unlinkat + 0x01c1
29 7ffeeb98 (+  64) 00203cc0   <_APP_>:main (nearest) + 0x1048
30 7ffeebd8 (+ 448) 002049b4   <_APP_>:main (nearest) + 0x1d3c
31 7ffeed98 (+ 288) 00205825   <_APP_>:rm + 0x0191
32 7ffeeeb8 (+ 176) 002030f0   <_APP_>:main + 0x0478
33 7ffeef68 (+  52) 002029ad   <_APP_>:_start + 0x0051
34 7ffeef9c (+  64) 00105367   </boot/system/runtime_loader@0x00100000>:unknown + 0x5367
35 7ffeefdc (+   0) 7ffeefec   1306621:rm_main_stack@0x7efef000 + 0xffffec

[axeld]

Fixed in hrev35489.

[stippi]

Just ran into this. Are you sure it's supposed to be fixed?

[axeld]

The bug in cache_sync_transaction() should indeed be fixed. And until now I was pretty sure about it :-)

[stippi]

Darn, I should have written down the stack trace. When I ran into it, I wasn't sure if it was supposed to be fixed, I just remembered there was a ticket. So only after I looked up the ticket, I saw it's actually supposed to be fixed. Really sorry about that, but now I've downgraded that system to 35294 again.

The way I got the panic was checking out the WebKit SVN (mmlr), leaving it idling for a short while after that and then trying svn up. I got the panic almost immediately. And after downgrading and rebooting, the repo was pretty much toast, so I rm -rf'd it all and checked it out again with the good kernel.

[anevilyak]

I hit this one while doing an svn up, backtrace as follows:

stack trace for thread 415 "svn"
    kernel stack: 0x817cf000 to 0x817d3000
      user stack: 0x7efef000 to 0x7ffef000
frame               caller     <image>:function + offset
 0 817d2718 (+  32) 80069a31   <kernel_x86> invoke_command_trampoline(void*: 0x817d2798) + 0x0015
 1 817d2738 (+  12) 800d82a8   <kernel_x86>:arch_debug_call_with_fault_handler + 0x001b
 2 817d2744 (+  48) 800678f6   <kernel_x86>:debug_call_with_fault_handler + 0x0051
 3 817d2774 (+  64) 80069d24   <kernel_x86>:invoke_debugger_command + 0x00bb
 4 817d27b4 (+  48) 80069e41   <kernel_x86> invoke_pipe_segment(debugger_command_pipe*: 0x80126da2, int32: 0, char*: NULL) + 0x0083
 5 817d27e4 (+  32) 80069f09   <kernel_x86>:invoke_debugger_command_pipe + 0x008b
 6 817d2804 (+ 128) 8006dd5a   <kernel_x86> ExpressionParser<0x817d28d4>::_ParseCommandPipe(int&: 0x817d28d0) + 0x0aae
 7 817d2884 (+  48) 80070523   <kernel_x86> ExpressionParser<0x817d28d4>::EvaluateCommand(char const*: 0x80126da0 "bt", int&: 0x817d28d0) + 0x06df
 8 817d28b4 (+ 192) 8007069c   <kernel_x86>:evaluate_debug_command + 0x0084
 9 817d2974 (+  96) 800686c9   <kernel_x86> kernel_debugger_internal(char const*: 0x83b55fc0 "²´", int32: -2122503680) + 0x039a
10 817d29d4 (+  16) 8006881f   <kernel_x86>:kernel_debugger + 0x0019
11 817d29e4 (+ 160) 800688e1   <kernel_x86>:panic + 0x002a
12 817d2a84 (+  48) 800ba508   <kernel_x86>:hash_remove_current + 0x003d
13 817d2ab4 (+ 144) 8003dd70   <kernel_x86>:cache_sync_transaction + 0x0147
14 817d2b44 (+  48) 8080b7ed   <bfs> Journal<0x83b56ea0>::_TransactionDone(true) + 0x00c5
15 817d2b74 (+  48) 8080b862   <bfs> Journal<0x83b56ea0>::Unlock(Transaction*: 0x817d2c70, true) + 0x0054
16 817d2ba4 (+  32) 807f99fb   <bfs> Transaction<0x817d2c70>::Done() + 0x002b
17 817d2bc4 (+ 240) 808155ea   <bfs> bfs_rename(fs_volume*: 0x81b7f060, fs_vnode*: 0x87656be0, char const*: 0x817d2df0 "entries", fs_vnode*: 0x87656d70, char const*: 0x817d2cf0 "entries") + 0x077c
18 817d2cb4 (+ 592) 800a81dc   <kernel_x86> common_rename(int32: -2083836672, char*: NULL, int32: 1024, char*: 0x800948f0, false) + 0x0134
19 817d2f04 (+  64) 800a830a   <kernel_x86>:_user_rename + 0x00e7
20 817d2f44 (+ 100) 800d8882   <kernel_x86>:handle_syscall + 0x00af
user iframe at 0x817d2fa8 (end = 0x817d3000)
 eax 0x6f           ebx 0x92d4ac        ecx 0x7ffee5e0   edx 0xffff0114
 esi 0x185fca78     edi 0x185fe168      ebp 0x7ffee60c   esp 0x817d2fdc
 eip 0xffff0114  eflags 0x200206   user esp 0x7ffee5e0
 vector: 0x63, error code: 0x0
21 817d2fa8 (+   0) ffff0114   <commpage>:commpage_syscall + 0x0004
22 7ffee60c (+  48) 004579cf   <libapr-1.so.0>:apr_file_rename + 0x0023
23 7ffee63c (+  64) 0036fb69   <libsvn_subr-1.so.0>:svn_io_file_rename + 0x0059
24 7ffee67c (+  48) 002717c2
[*** READ FAULT at 0xffffffff, pc: 0x800e588d ***]

Not sure what other KDL info would be helpful right now though.

[anevilyak]

hrev35502 by the way.

[axeld]

The problem is understood; the block notifier/writer may close/delete the transaction once BlockWriter::Write() unlocks the cache.

[axeld]

Fixed in hrev35510.