Re: release only runtime crash

2018-09-18 Thread yglukhov
This may happen if nim GC loses track of your json objects, "deallocates" them, 
and later reuses their memory for something else. As a test, patch `json.nim` 
by adding a finalizer to all allocated JsonNodes, and see if it is getting 
called when it's not supposed to. Revealing your source code for our review 
could also help :)


release only runtime crash

2018-09-17 Thread sflennik
My nim program crashes in release but not in debug mode. Some system code is 
overwriting my json structures causing the crash. The problem is hard to narrow 
down, it moves around as I add debugging code. I haven't been able to simplify 
the error case to something that is easy to share.

The release and optimizer options must be on to reproduce the problem. 
Compiling with debug and --opt:size or with --opt:speed works without error and 
-d:release with --opt:none works.

I been using the lldb debugger and isolated the problem. I found the address of 
the json structure being overwritten and set a hardware watchpoint there. At 
this point, my code adds to a sequence filling it to capacity then the system 
expands the sequence and moves memory around. This process overwrites the 
unrelated json object.

I am working on a Mac with the latest release version of nim and am debugging a 
python shared library.

Anyone have ideas where the bug is and how to fix it? Or have ideas I can try?

Here is part of my debugger session:


# dump a pointer to a json jArray object then set a watch point on it.
(lldb) x 4302866232
0x100788738: 18 ac 7d 00 01 00 00 00 58 aa 7d 00 01 00 00 00  
.?}.X?}.
0x100788748: f0 a0 7d 00 01 00 00 00 58 a3 7d 00 01 00 00 00  
?}.X?}.
(lldb) watchpoint set expression 4302866232
Watchpoint created: Watchpoint 1: addr = 0x100788738 size = 8 state = 
enabled type = w
new value: 4303203352

# run the program
(lldb) c
Process 69738 resuming

# the watchpoint is hit by memmove.
Watchpoint 1 hit:
old value: 4303203352
new value: 4337886456
Process 69738 stopped
* thread #2, queue = 'com.apple.main-thread', stop reason = watchpoint 1
frame #0: 0x7fff7b79052b 
libsystem_platform.dylib`_platform_memmove$VARIANT$Nehalem + 299
libsystem_platform.dylib`_platform_memmove$VARIANT$Nehalem:
->  0x7fff7b79052b <+299>: movaps xmmword ptr [rdi + 0x20], xmm3
0x7fff7b79052f <+303>: movaps xmmword ptr [rdi + 0x30], xmm4
0x7fff7b790533 <+307>: movups xmmword ptr [rdi + rdx + 0x40], xmm5
0x7fff7b790538 <+312>: movups xmmword ptr [rdi + rdx + 0x50], xmm6
Target 0: (Python) stopped.
(lldb) x 4302866232
0x100788738: f8 e4 8e 02 01 00 00 00 58 aa 7d 00 01 00 00 00  
??..X?}.
0x100788748: f0 a0 7d 00 01 00 00 00 58 a3 7d 00 01 00 00 00  
?}.X?}.

# memove is called by copyMem.
(lldb) fr select 1
frame #1: 0x000102808726 metar.so`growObj_FZeyQYjWPcE9c06y1gNqZxw 
[inlined] copyMem_E1xtACub5WcDa3vbrIXbwgsystem(dest=, 
source=0x0001028d9038, size=) at system.nim:3242 [opt]
   3239 when declared(memTrackerOp):
   3240   memTrackerOp("zeroMem", p, size)
   3241   proc copyMem(dest, source: pointer, size: Natural) =
-> 3242 c_memcpy(dest, source, size)
   3243 when declared(memTrackerOp):
   3244   memTrackerOp("copyMem", dest, size)
   3245   proc moveMem(dest, source: pointer, size: Natural) =

# here is the stack
(lldb) bt
* thread #2, queue = 'com.apple.main-thread', stop reason = watchpoint 1
frame #0: 0x7fff7b79052b 
libsystem_platform.dylib`_platform_memmove$VARIANT$Nehalem + 299
  * frame #1: 0x000102808726 metar.so`growObj_FZeyQYjWPcE9c06y1gNqZxw 
[inlined] copyMem_E1xtACub5WcDa3vbrIXbwgsystem(dest=, 
source=0x0001028d9038, size=) at system.nim:3242 [opt]
frame #2: 0x000102808717 
metar.so`growObj_FZeyQYjWPcE9c06y1gNqZxw(old=, 
newsize=, gch=0x000101809000) at gc.nim:537 [opt]
frame #3: 0x000102808999 metar.so`incrSeqV2 [inlined] 
growObj_AVYny8c0GTk28gxjmat1MA(old=, newsize=) at 
gc.nim:586 [opt]
frame #4: 0x000102808985 metar.so`incrSeqV2(seq=, 
elemSize=) at sysstr.nim:260 [opt]
frame #5: 0x000102844316 
metar.so`getLeafString_Zo50qhbAAbCqf7Q3nRkzYA(node=0x0001007f0240, 
maxLen=72) at readable.nim:109 [opt]
frame #6: 0x000102844fe7 
metar.so`readable_v9cZ2WN4Rpw3hZ8FsvwdS4A(metadata=, 
readerName=) at readable.nim:183 [opt]
frame #7: 0x000102801998 
metar.so`readMetadata_2nQm9bwutYGCHUjTrSrQ5Aw_2(filename="testfiles/image.jpg") 
at metar.nim:44 [opt]
frame #8: 0x000102801a18 
metar.so`readMetadataPy_wrapper_ANfPuNIhXMYZOCUppM6Wug_4(self=, 
args=) at metar.nim:38 [opt]
frame #9: 0x7fff5f89 Python`PyEval_EvalFrameEx + 2917
frame #10: 0x7fff5232 Python`PyEval_EvalCodeEx + 1551
frame #11: 0x7fff5dddcc1d Python`PyEval_EvalCode + 32
frame #12: 0x7fff5ddfbad1 Python`___lldb_unnamed_symbol1600$$Python 
+ 49
frame #13: 0x7fff5ddfbb78 Python`PyRun_FileExFlags + 130
frame #14: 0x7fff5ddfb6fa Python`PyRun_SimpleFileExFlags + 706
frame #15: 0x7fff5de0c96c Python`Py_Main + 3064
frame #16: