Fix debugger re-entry while detaching

[svaarala]

Fixes #597. Possibly related to debugger read callback re-entry issue described in #591.

Tasks:

• Fix debugger re-entry when dbg_processing was set to zero during detach1()
• Fix Duktape never doing detach2() if detach1() occurred outside of debugger message loop
• Fix write_cb NULLing for duk_debug_write_byte()
• Any way to repeat @harold-b's issue with repeated read calls not resetting callbacks to NULL? => Could not reproduce.
• Add fix backport notes for earlier releases where appropriate
• Releases

[fatcerberus]

Alright, I'll test this out in a bit and let you know if it fixes the issue.

[svaarala]

Ok, I'm still testing manually as we speak, but if you also test no harm :)

[svaarala]

Ok, testing in master by adding DUK_ASSERT(heap->dbg_processing == 1) into the message loop (not just outside of it) triggers the assert on reattach. So definitely master handles dbg_processing wrong. The branch fixes this assert failure.

Can you confirm the branch fixes your issue too?

[fatcerberus]

Sure, let me pull the branch on my local Duktape repo and I'll test it.

[fatcerberus]

Detaching and reattaching at the debugger statement seems to work now. However now there's a different issue: I can't detach+reattach while the the target is running (it causes a detach like the original bug).

[svaarala]

Hmm, I wonder why. Could you post a debug log about that?

The reattach should automatically make the client paused but maybe something goes wrong with that. It should be unrelated to dbg_processing flag though.

[fatcerberus]

Okay, something weird is going on here, minisphere is resuming execution instead of waiting for the debugger to reattach even though I ran it with the --debug switch. Not sure if that's a bug in minisphere or Duktape communicating the detach incorrectly (i.e. not calling the detach callback). At one point I even got Duktape to segfault during mark-and-sweep (not running in Linux right now so no valgrind log):

[D] duk_debugger.c:572 (duk_debug_write_byte): connection error during write
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_debugger.c:572 (duk_debug_write_byte): connection error during write
[D] duk_debugger.c:548 (duk_debug_write_bytes): connection error during write
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:565 (duk_debug_write_byte): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 3 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 32 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 0 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:565 (duk_debug_write_byte): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:164 (duk_debug_write_flush): attempt to write flush in detached state, ignore
[D] duk_debugger.c:1936 (duk_debug_process_messages): debug connection broken, stop processing messages
[D] duk_debugger.c:145 (duk_debug_read_flush): attempt to read flush in detached state, ignore
[D] duk_js_executor.c:1663 (duk__interrupt_handle_debugger): debugger became detached, resume normal execution
[D] duk_heap_memory.c:30 (duk__run_voluntary_gc): triggering voluntary mark-and-sweep
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
*SEGFAULT*

[fatcerberus]

The segfault points to a larger issue (I couldn't get it to happen again), but here's the log from the point I forcibly terminated SSJ and then reattached:

[D] duk_debugger.c:572 (duk_debug_write_byte): connection error during write
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_debugger.c:572 (duk_debug_write_byte): connection error during write
[D] duk_debugger.c:548 (duk_debug_write_bytes): connection error during write
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:565 (duk_debug_write_byte): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 3 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 39 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 6 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:565 (duk_debug_write_byte): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:164 (duk_debug_write_flush): attempt to write flush in detached state, ignore
[D] duk_debugger.c:1936 (duk_debug_process_messages): debug connection broken, stop processing messages
[D] duk_debugger.c:145 (duk_debug_read_flush): attempt to read flush in detached state, ignore
[D] duk_js_executor.c:1663 (duk__interrupt_handle_debugger): debugger became detached, resume normal execution
[D] duk_heap_memory.c:30 (duk__run_voluntary_gc): triggering voluntary mark-and-sweep
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 15600 freed, 10893 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4615 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10893 objects kept, 4615 strings kept, trigger reset to 769024
[D] duk_debugger.c:102 (duk__debug_do_detach2): detached during message loop, delayed call to detached_cb
[D] duk_heap_alloc.c:272 (duk_heap_free): free heap: 0000020E0E279CF0
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_heap_alloc.c:297 (duk_heap_free): execute finalizers before freeing heap
[D] duk_heap_alloc.c:307 (duk_heap_free): forced gc #1 in heap destruction
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 145 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 29 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:309 (duk_heap_free): forced gc #2 in heap destruction
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 0 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:311 (duk_heap_free): forced gc #3 in heap destruction (don't run finalizers)
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000010, effective flags: 0x00000010
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 0 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:255 (duk__free_run_finalizers): finalizer round 0 complete, 10736 objects, tried to execute 7 finalizers, current limit is 21472
[D] duk_heap_alloc.c:255 (duk__free_run_finalizers): finalizer round 1 complete, 10736 objects, tried to execute 0 finalizers, current limit is 16104
[D] duk_heap_alloc.c:258 (duk__free_run_finalizers): no more finalizable objects, forced finalization finished
[D] duk_heap_alloc.c:322 (duk_heap_free): freeing heap objects of heap: 0000020E0E279CF0
[D] duk_heap_alloc.c:326 (duk_heap_free): freeing refzero list of heap: 0000020E0E279CF0
[D] duk_heap_alloc.c:331 (duk_heap_free): freeing mark-and-sweep finalize list of heap: 0000020E0E279CF0
[D] duk_heap_alloc.c:335 (duk_heap_free): freeing string table of heap: 0000020E0E279CF0
[D] duk_heap_alloc.c:338 (duk_heap_free): freeing heap structure: 0000020E0E279CF0

[svaarala]

Hmm, it'd be nice if you could add a debug log to the duk_debugger_attach() call so one could see where it takes place here.

[fatcerberus]

New log, from first attach to minisphere termination:

# First attach

Buu says: ME BUU, KILL YOU!
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
>>> Engine started!
[D] duk_heap_memory.c:30 (duk__run_voluntary_gc): triggering voluntary mark-and-sweep
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x0000000c
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 945 freed, 4410 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 59 freed, 2396 kept
[D] duk_heap_markandsweep.c:1344 (duk_heap_mark_and_sweep): finalizer run skipped because DUK_MS_FLAG_NO_FINALIZERS is set
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 4410 objects kept, 2396 strings kept, trigger reset to 333824
[D] duk_debugger.c:1945 (duk_debug_process_messages): paused, process debug message, blocking if necessary
[D] duk_debugger.c:1369 (duk__debug_handle_eval): debug command Eval
[D] duk_debugger.c:1945 (duk_debug_process_messages): paused, process debug message, blocking if necessary
[D] duk_debugger.c:1084 (duk__debug_handle_resume): debug command Resume
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_js_executor.c:1659 (duk__interrupt_handle_debugger): processed debug messages, restart execution to recheck possibly changed breakpoints
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x01\x02\x0b\x00\x07N\x07$\x02'\x09\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x04\x03\x01\x02'\x06 \x02\"\x09\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x04\x03\x01\x02\"\x06\xc2\x8c\x0a\x01\xfe\x83\xbf\xbf\xbf\xbf\xbf\x01v\x05\x0b\x09\x0d  \xc2\xa0\xc2\xa0\xe1\x9a\x80\xe1\x9a\x80\xe1\xa0\x8e\xe1\xa0\x8e\xe2\x80\x80\xe2\x80\x8a\xe2\x80\xa8\xe2\x80\xa9\xe2\x80\xaf\xe2\x80\xaf\xe2\x81\x9f\xe2\x81\x9f\xe3\x80\x80\xe3\x80\x80\xef\xbb\xbf\xef\xbb\xbf\x01\x0b\x01\x01"/1, escaped source: "'.*?'|\".*?\"|\\S+"/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x00\x04\x0b\x00\x02'\x0b\x02\x0a\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x01\x04\x03\x01\x0b\x03\x02'\x0b\x01\x01"/1, escaped source: "'(.*)'"/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x00\x04\x0b\x00\x02\"\x0b\x02\x0a\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x01\x04\x03\x01\x0b\x03\x02\"\x0b\x01\x01"/1, escaped source: "\"(.*)\""/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x01\x02\x0b\x00\x07N\x07$\x02'\x09\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x04\x03\x01\x02'\x06 \x02\"\x09\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x04\x03\x01\x02\"\x06\xc2\x8c\x0a\x01\xfe\x83\xbf\xbf\xbf\xbf\xbf\x01v\x05\x0b\x09\x0d  \xc2\xa0\xc2\xa0\xe1\x9a\x80\xe1\x9a\x80\xe1\xa0\x8e\xe1\xa0\x8e\xe2\x80\x80\xe2\x80\x8a\xe2\x80\xa8\xe2\x80\xa9\xe2\x80\xaf\xe2\x80\xaf\xe2\x81\x9f\xe2\x81\x9f\xe3\x80\x80\xe3\x80\x80\xef\xbb\xbf\xef\xbb\xbf\x01\x0b\x01\x01"/1, escaped source: "'.*?'|\".*?\"|\\S+"/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x00\x04\x0b\x00\x02'\x0b\x02\x0a\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x01\x04\x03\x01\x0b\x03\x02'\x0b\x01\x01"/1, escaped source: "'(.*)'"/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x00\x04\x0b\x00\x02\"\x0b\x02\x0a\x00\xfe\x83\xbf\xbf\xbf\xbf\xbf\x01\x04\x03\x01\x0b\x03\x02\"\x0b\x01\x01"/1, escaped source: "\"(.*)\""/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x01\x02\x0b\x00\x02\\\x0b\x01\x01"/1, escaped source: "\\\\"/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x00\x02\x0b\x00\x02.\x02.\x0b\x01\x01"/1, escaped source: "\\.\\."/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x01\x02\x0b\x00\x02\\\x0b\x01\x01"/1, escaped source: "\\\\"/3
[D] duk_regexp_compiler.c:965 (duk_regexp_compile): starting regexp compilation
[D] duk_regexp_compiler.c:1010 (duk_regexp_compile): regexp compilation successful, bytecode: "\x00\x02\x0b\x00\x02.\x02.\x0b\x01\x01"/1, escaped source: "\\.\\."/3
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_heap_memory.c:30 (duk__run_voluntary_gc): triggering voluntary mark-and-sweep
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x0000000c
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 3349 freed, 10804 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 61 freed, 4615 kept
[D] duk_heap_markandsweep.c:1344 (duk_heap_mark_and_sweep): finalizer run skipped because DUK_MS_FLAG_NO_FINALIZERS is set
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10804 objects kept, 4615 strings kept, trigger reset to 769024
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:1940 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing
[D] duk_debugger.c:572 (duk_debug_write_byte): connection error during write
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_debugger.c:572 (duk_debug_write_byte): connection error during write
[D] duk_debugger.c:548 (duk_debug_write_bytes): connection error during write
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:565 (duk_debug_write_byte): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 25 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 0 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 2 bytes in detached state, ignore
[D] duk_debugger.c:523 (duk_debug_write_bytes): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:565 (duk_debug_write_byte): attempt to write 1 bytes in detached state, ignore
[D] duk_debugger.c:164 (duk_debug_write_flush): attempt to write flush in detached state, ignore
[D] duk_debugger.c:1936 (duk_debug_process_messages): debug connection broken, stop processing messages
[D] duk_debugger.c:145 (duk_debug_read_flush): attempt to read flush in detached state, ignore
[D] duk_js_executor.c:1663 (duk__interrupt_handle_debugger): debugger became detached, resume normal execution

# Reattach

Buu says: ME BUU, KILL YOU!
[D] duk_debugger.c:102 (duk__debug_do_detach2): detached during message loop, delayed call to detached_cb
[D] duk_heap_alloc.c:272 (duk_heap_free): free heap: 0000025223D58B30
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_heap_alloc.c:297 (duk_heap_free): execute finalizers before freeing heap
[D] duk_heap_alloc.c:307 (duk_heap_free): forced gc #1 in heap destruction
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 4391 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 29 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:309 (duk_heap_free): forced gc #2 in heap destruction
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 0 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:311 (duk_heap_free): forced gc #3 in heap destruction (don't run finalizers)
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000010, effective flags: 0x00000010
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 0 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:255 (duk__free_run_finalizers): finalizer round 0 complete, 10736 objects, tried to execute 7 finalizers, current limit is 21472
[D] duk_heap_alloc.c:255 (duk__free_run_finalizers): finalizer round 1 complete, 10736 objects, tried to execute 0 finalizers, current limit is 16104
[D] duk_heap_alloc.c:258 (duk__free_run_finalizers): no more finalizable objects, forced finalization finished
[D] duk_heap_alloc.c:322 (duk_heap_free): freeing heap objects of heap: 0000025223D58B30
[D] duk_heap_alloc.c:326 (duk_heap_free): freeing refzero list of heap: 0000025223D58B30
[D] duk_heap_alloc.c:331 (duk_heap_free): freeing mark-and-sweep finalize list of heap: 0000025223D58B30
[D] duk_heap_alloc.c:335 (duk_heap_free): freeing string table of heap: 0000025223D58B30
[D] duk_heap_alloc.c:338 (duk_heap_free): freeing heap structure: 0000025223D58B30

[fatcerberus]

It looks like it immediately detached after duk_debugger_attach() was called, without calling the detach callback.

[fatcerberus]

In case it's relevant, here's my reattach code:
https://github.com/fatcerberus/minisphere/blob/master/src/minisphere/debugger.c#L96-L108

[svaarala]

Pushed one more assert to test with - it might be that we're in "detaching" state because an error which happens here:

• https://github.com/svaarala/duktape/blob/master/src/duk_debugger.c#L1918-L1924

we'd then exit the message loop without reattaching here:

• https://github.com/svaarala/duktape/blob/master/src/duk_debugger.c#L1893-L1895

which would be incorrect. I added an assert there to see if this is indeed what's happening in your case. If so, it's much clearer what to fix.

[fatcerberus]

Okay, I'll try it out with assertions enabled and see what happens.

[fatcerberus]

minisphere 3.0a2 JS game engine (x64)
A lightweight Sphere-compatible game engine
(c) 2016 Fat Cerberus

Waiting for debug connection from SSJ...
Buu says: ME BUU, KILL YOU!
>>> Engine started!
PANIC 54: assertion failed: DUK_HEAP_IS_DEBUGGER_ATTACHED(thr->heap) (duk_debugger.c:1880) (calling abort)

[svaarala]

That's actually a different assert that you hit this time. But it's a similar case: an earlier duk_debug_send_status() may have caused a detach (it would require the write callback returning zero I guess) after which we go to process messages but are not actually attached anymore.

Added one more assert (and a potential fix). I'd first like to see where the root cause is. It'd then probably be best to allow duk_debug_process_messages() to allow entry when detached and then just exit quietly. This would reduce the need to have the exactly correct condition in three different call sites.

[fatcerberus]

Well, no assertions were triggered this time, but it still detaches upon the second reattach.

[fatcerberus]

[D] duk_js_executor.c:1663 (duk__interrupt_handle_debugger): debugger became detached, resume normal execution
>>> Buu says: ME BUU, KILL YOU!
[D] duk_debugger.c:41 (duk__debug_do_detach1): debugger already detaching, ignore detach1
[D] duk_debugger.c:103 (duk__debug_do_detach2): detached during message loop, delayed call to detached_cb
[D] duk_debugger.c:41 (duk__debug_do_detach1): debugger already detaching, ignore detach1
[D] duk_heap_alloc.c:272 (duk_heap_free): free heap: 000002407E700DC0
[D] duk_debugger.c:45 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_heap_alloc.c:297 (duk_heap_free): execute finalizers before freeing heap
[D] duk_heap_alloc.c:307 (duk_heap_free): forced gc #1 in heap destruction
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 4422 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 29 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:309 (duk_heap_free): forced gc #2 in heap destruction
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000000, effective flags: 0x00000000
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 0 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:311 (duk_heap_free): forced gc #3 in heap destruction (don't run finalizers)
[D] duk_heap_markandsweep.c:1173 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) starting, requested flags: 0x00000010, effective flags: 0x00000010
[D] duk_heap_markandsweep.c:861 (duk__sweep_heap): mark-and-sweep sweep objects (non-string): 0 freed, 10736 kept, 0 rescued, 0 queued for finalization
[D] duk_heap_markandsweep.c:702 (duk__sweep_stringtable_probe): mark-and-sweep sweep stringtable: 0 freed, 4586 kept
[D] duk_heap_markandsweep.c:925 (duk__run_object_finalizers): mark-and-sweep finalize objects: 0 finalizers called
[D] duk_heap_markandsweep.c:1382 (duk_heap_mark_and_sweep): garbage collect (mark-and-sweep) finished: 10736 objects kept, 4586 strings kept, trigger reset to 756224
[D] duk_heap_alloc.c:255 (duk__free_run_finalizers): finalizer round 0 complete, 10736 objects, tried to execute 7 finalizers, current limit is 21472
[D] duk_heap_alloc.c:255 (duk__free_run_finalizers): finalizer round 1 complete, 10736 objects, tried to execute 0 finalizers, current limit is 16104
[D] duk_heap_alloc.c:258 (duk__free_run_finalizers): no more finalizable objects, forced finalization finished
[D] duk_heap_alloc.c:322 (duk_heap_free): freeing heap objects of heap: 000002407E700DC0
[D] duk_heap_alloc.c:326 (duk_heap_free): freeing refzero list of heap: 000002407E700DC0
[D] duk_heap_alloc.c:331 (duk_heap_free): freeing mark-and-sweep finalize list of heap: 000002407E700DC0
[D] duk_heap_alloc.c:335 (duk_heap_free): freeing string table of heap: 000002407E700DC0
[D] duk_heap_alloc.c:338 (duk_heap_free): freeing heap structure: 000002407E700DC0

[svaarala]

@fatcerberus I'm having a hard time reproducing the same behavior - could you add debug prints to your read, write, and detached callbacks so it'd be easier to see when those calls happen in relation to Duktape logging (ideally it'd be the same stream i.e. stderr so they interleave correctly).

I'll read a bit more code soonish and try to figure out what's going on.

[svaarala]

Hmm, if I read the Minisphere code correctly, you're calling also duk_debugger_detach() from the detached callback (attach_debugger() calls update_debugger() which always detaches and attaches). Is this correct?

[svaarala]

Even with a duk_debugger_detach() before a duk_debugger_attach() I can't seem to reproduce the problem.

[fatcerberus]

I don't know the exact reason for that detach-reattach cycle - I think I did it to ensure that I was always starting from a clean slate.

I'll run minisphere under the MSVC debugger and see if I can trace the code path later.

[svaarala]

That detach+attach is not explicitly supported and I was assuming you'd only call attach in the initial attach or detached callback which is why the log looked weird at first:

# First attach

Buu says: ME BUU, KILL YOU!
[D] duk_debugger.c:44 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
>>> Engine started!

There's a "detach1" even in the initial attach because it is preceded by a detach. And because dbg_detaching == 0 it actually goes through "detach1" processing. This shouldn't cause any side effects though (and detaching just in case outside of a detached callback is explicitly allowed) as such but makes the log entries a bit confusing.

Anyway, this log entry looks weird to me too (it's in the "reattach" position of the commented log):

[D] duk_heap_alloc.c:272 (duk_heap_free): free heap: 000002407E700DC0

The only relevant call site for that is duk_destroy_heap() which can only be called by the application. Is this intentional at that point in the log sequence? For example here:

[D] duk_js_executor.c:1663 (duk__interrupt_handle_debugger): debugger became detached, resume normal execution
>>> Buu says: ME BUU, KILL YOU!
[D] duk_debugger.c:41 (duk__debug_do_detach1): debugger already detaching, ignore detach1
[D] duk_debugger.c:103 (duk__debug_do_detach2): detached during message loop, delayed call to detached_cb
[D] duk_debugger.c:41 (duk__debug_do_detach1): debugger already detaching, ignore detach1
[D] duk_heap_alloc.c:272 (duk_heap_free): free heap: 000002407E700DC0
[D] duk_debugger.c:45 (duk__debug_do_detach1): debugger transport detaching, marking transport broken
[D] duk_heap_alloc.c:297 (duk_heap_free): execute finalizers before freeing heap
[...]

Commenting a bit on that snippet:

[D] duk_js_executor.c:1663 (duk__interrupt_handle_debugger): debugger became detached, resume normal execution
>>> Buu says: ME BUU, KILL YOU!
(I'm not sure who logs the above? It shouldn't be the detached callback yet.)
[D] duk_debugger.c:41 (duk__debug_do_detach1): debugger already detaching, ignore detach1
[D] duk_debugger.c:103 (duk__debug_do_detach2): detached during message loop, delayed call to detached_cb
(This is where the detached callback should be called.)
[D] duk_debugger.c:41 (duk__debug_do_detach1): debugger already detaching, ignore detach1
(Not sure where the above comes from: it could be from a `duk_debugger_detach()` which precedes
the call to `duk_debugger_attach()` in the client.)
[D] duk_heap_alloc.c:272 (duk_heap_free): free heap: 000002407E700DC0
(The above should only be possible if something called `duk_destroy_heap()`.)

I might be able to understand better if you re-ran this test with the few added debug commits I pushed, and if you could debug print from the read, write, and detached callbacks :)

[fatcerberus]

The heap is freed because, when run with the --debug option minisphere wants a debugger attached at all times, and if that can't be satisfied it will shut down rather than allowing game execution to continue.

However that shouldn't happen either--it should be waiting up to 30 seconds for a new connection before terminating. I'm not sure why but it's terminating immediately rather than waiting.

[svaarala]

@harold-b A longjmp could most likely cause that. It would've had to happen between setting dbg_detaching to 1 and before NULLing the callbacks. In other words, it would have had to happened trying to write the Detaching notify? Or maybe I didn't understand correctly.

In any case, with the fix to NULL all the I/O callbacks the first read error would have NULLed all callbacks other than the detached callback. This would be better behavior but still not correct because the latter half of detach1() would still have been skipped due to dbg_detaching == 1 and it also does important things.

However, I'm not sure why a longjmp() would happen between that short span of code, other than e.g. out-of-memory. But that's hard to imagine because the Detaching notify consists of just three integers, i.e. no strings or other dynamic data.

So unless there's a way to reproduce it's quite difficult to do anything about it - I can't explain that behavior by simply reading the code. At least right now, I can retry tomorrow :-)

[harold-b]

However, I'm not sure why a longjmp() would happen between that short span of code, other than e.g. out-of-memory. But that's hard to imagine because the Detaching notify consists of just three integers, i.e. no strings or other dynamic data.

So unless there's a way to reproduce it's quite difficult to do anything about it - I can't explain that behavior by simply reading the code. At least right now, I can retry tomorrow :-)

Oh no worries, I'm not asking for a fix, since I could hardly even reproduce it. I was just trying to point out that I couldn't understand the state of that bug give how the function was set up to protect itself!

[fatcerberus]

@harold-b
It sounds like you actually triggered the root cause of this bug - the debugger, under certain circumstances, could get itself into message processing recursively which causes all sorts of misbehavior. If that's the case, that will be fixed by this pull.

@svaarala
Those fixes look good to me, the fix turned out to be much less invasive than I was imagining.

[svaarala]

@fatcerberus I can't imagine why NULLing the other callbacks would cause any (at least harmful) side effects, but I won't merge this branch until there's been some more testing on the changes. I'll do my best with what I can test with once I've had a chance to finalize cleaning up the original fix.

[harold-b]

@fatcerberus Yeah, everything is working perfectly now though. Thanks again to both of you.

[fatcerberus]

I'm assuming the minimal fix (NULL'ing only write_cb) is what will be merged to master for 1.4.1?

[fatcerberus]

Not master, I meant the 1.4.x maintenance branch.

[svaarala]

Stepping back a bit, there have been several small bugs related to the debugger state handling. That indicates pretty clearly that the state handling is not very well structured. I'll try to keep an eye on that as the code is worked on. The next bigger thing would be to add setjmp() protection to guard against unlikely causes such as out of memory (which are not handled now), and maybe I can try to restructure some of the code a bit in the process.

Anyway, if any new issues arise (especially something reproducible), I'll be eager to investigate and fix :-)

@fatcerberus Pros and cons to each approach, but I'd favor the minimal fix for 1.4.1 and the cleaner fix for master. No fix is needed prior to 1.4 because there's no Detaching callback there (nor detach1/detach2 split for that matter; and of course no support for debugger reattach in detached callback :).

[fatcerberus]

I always found the concept of bugs in a debugger amusing. It's half the fun of developing SSJ, I always get such a kick out of telling people my debugger is buggy. :)

[svaarala]

I've cleaned up the fixes, improved commit messages, squashed and rebased now and I'd be ready to merge this from my point of view. I can't reproduce any issues with the updates - but it'd be great if you could double check that from the tip.

@fatcerberus One issue in particular: while the debugger is running Duktape will log these two log lines around 5 times a second (total 10 log lines per second or so):

[D] duk_debugger.c:1957 (duk_debug_process_messages): processing debug message, peek indicated no data, stop processing messages
[D] duk_debugger.c:1891 (duk_debug_process_messages): process debug messages: read_cb=not NULL, no_block=0, detaching=0, processing=0

Do you still get way more than that?

There's a change in this behavior because I tried to simplify the executor handling of Status notify sending. It's now folded into the debugger message loop which now sends a Status if the state is marked dirty, even when no messages end up being processed.

This may technically increase the peek() callback rate slightly - but there should be very little practical difference: the earlier code would send a status when dirty without entering the debugger loop, but that dirty state could only really be set by (a) becoming paused (in which case we enter the message loop anyway) or (2) the timer based periodic debugger poll check (in which case we enter the message loop too).

For me the debug logging rate is reasonable, and I've double checked that the Unix example debug transport peek() rate is also reasonable for me.

[fatcerberus]

Let me try it out at I'll let you know. The thing is, the Windows terminal emulator is very slow, and gets progressively worse as the number of visible lines increases. This makes Duktape literally unusable for me with DUK_OPT_DDPRINT and above (unless I redirect stderr): minisphere never gets off the ground because it's bogged down in Duktape logging.

[svaarala]

Yes, DUK_OPT_DDPRINT is not really intended for anything other than capturing dumps for later analysis.

But is DUK_OPT_DPRINT level reasonable for you?

[fatcerberus]

Just tested it. Yes, that's reasonable. At one point when we were testing fixes it was literally printing those two lines nonstop, it's much better now.

[svaarala]

Yeah, that was the intermediate version where status sending was moved to the message loop, but the message loop wouldn't actually send a Status unless a message was processed. As a result, the state dirty -flag would remain set and we'd re-enter the message loop over and over again.

Anyway, that's fixed and if the branch is still working correctly I'll re-read the final diff and merge.

[fatcerberus]

I tested various scenarios: Stopped at breakpoint, single-step, debugger statement, disconnect-while-running... and detached and reattached several times, everything looks to be working correctly.