valgrind scary report

[lightness1024]

in the middle of handling a GET

Invalid read of size 8
==4048== at 0x1BDF18: statusContentIter_zW9c7nGLSNoIH9cfofFXi4nA (jester.nim:90)
==4048== by 0x1BE5B6: statusContent_continue_WCCTXOA9c65GXBv9aCNAX1zA (asyncmacro.nim:34)
==4048== by 0x1BEC73: statusContent_HxrYd39cDwtMUIbqM5hufsw (asyncmacro.nim:401)
==4048== by 0x1C5BB2: handleRequestIter_zW9c7nGLSNoIH9cfofFXi4nA_5 (jester.nim:303)
==4048== by 0x1C6234: handleRequest_continue_WCCTXOA9c65GXBv9aCNAX1zA_5 (asyncmacro.nim:37)
==4048== by 0x1C6993: handleRequest_0y9awor09bpQXNdY54QcfG9bg (asyncmacro.nim:401)
==4048== by 0x1C6A83: handleHTTPRequest_wgoGIkIobaSioVhefHcx7A (jester.nim:321)
==4048== by 0x1C6CC9: colonanonymous__NR9bnPHLoHio4fLEwVHo3og (jester.nim:350)
==4048== by 0x1CFF35: processRequestIter_dwt11Jx9bQoVsTeVQbJ9bzQQ (asynchttpserver.nim:143)
==4048== by 0x1D0A26: processRequest_continue_8U9cIXoWfwogCKwJZ6S0SNA (asyncmacro.nim:37)
==4048== by 0x14B97A: processPendingCallbacks_SmnbicdBxLog3d0rzfeG3w (asyncdispatch.nim:183)
==4048== by 0x14F9E4: runOnce_mXlNJtuWiqnwbU9ceoRo80w (asyncdispatch.nim:1277)
==4048== Address 0x0 is not stack'd, malloc'd or (recently) free'd

I'm skipping the reports of all the Use of uninitialised value of size 8 since it was reported it is Nim's way of doing [sic] "conservative stack marking" nim-lang/Nim#3063

but then there are those

Conditional jump or move depends on uninitialised value(s)
==4048== at 0x128CA8: auxWriteStackTrace_WTLGTxWV8l6Fdgckdz3n2Q (excpt.nim:257)
==4048== by 0x128F5E: rawWriteStackTrace_imNuOIqoJ9csXlrh58OtfXg (excpt.nim:268)
==4048== by 0x132430: signalHandler (excpt.nim:460)
==4048== by 0x579805F: ??? (in /lib/x86_64-linux-gnu/libc-2.24.so)

and finally

Syscall param write(buf) contains uninitialised byte(s)
==4048== at 0x584074D: ??? (syscall-template.S:84)
==4048== by 0x57D7816: _IO_file_write@@GLIBC_2.2.5 (fileops.c:1271)
==4048== by 0x57D6B61: new_do_write (fileops.c:526)
==4048== by 0x57D7F6D: _IO_file_xsputn@@GLIBC_2.2.5 (fileops.c:1350)
==4048== by 0x57CC96E: fputs (iofputs.c:38)
==4048== by 0x128365: write_ADGLlEJAOtGNWWur8rrJfg (sysio.nim:96)
==4048== by 0x128399: writeToStdErr_7HRVfGfZT2rSmBdcLxl8TA (excpt.nim:21)
==4048== by 0x1283EB: showErrorMessage_rsUJ87b89bH0GlWKYL9c8wUQ (excpt.nim:34)
==4048== by 0x1325CE: signalHandler (excpt.nim:462)
==4048== by 0x579805F: ??? (in /lib/x86_64-linux-gnu/libc-2.24.so)
==4048== by 0x1BDF17: statusContentIter_zW9c7nGLSNoIH9cfofFXi4nA (jester.nim:90)
==4048== by 0x1BE5B6: statusContent_continue_WCCTXOA9c65GXBv9aCNAX1zA (asyncmacro.nim:34)

Which in the end results in:

Traceback (most recent call last)
prcServer.nim(184) prcServer
prcServer.nim(180) main
asyncdispatch.nim(1507) runForever
asyncdispatch.nim(1511) poll
asyncdispatch.nim(1277) runOnce
asyncdispatch.nim(183) processPendingCallbacks
asyncmacro.nim(37) processRequest_continue
asynchttpserver.nim(143) processRequestIter
jester.nim(350) :anonymous
jester.nim(321) handleHTTPRequest
asyncmacro.nim(401) handleRequest
asyncmacro.nim(37) handleRequest_continue
jester.nim(303) handleRequestIter
asyncmacro.nim(401) statusContent
asyncmacro.nim(34) statusContent_continue
jester.nim(90) statusContentIter
SIGSEGV: Illegal storage access. (Attempt to read from nil?)

Possibly, it's trying to handle an exception, caused by db_mysql module.
It's undebugable because we don't know where it is when it crashes.
So, I ran it under gdb and that's where it is:

Thread 1 "prcServer" received signal SIGSEGV, Segmentation fault.
0x0000555555609f18 in statusContentIter_zW9c7nGLSNoIH9cfofFXi4nA (ClE_0=0x7ffff7f72408) at /home/vivien/.nimble/pkgs/jester-0.2.0/jester.nim:90
90 await c.send(headerData & content)

PS: Thanks for the fun project, but it just doesn't cut it, so I'll be moving to Node.js

[lightness1024]

New info: Staring at this line 90 I figured, content must have been nil.
And just so it was.

I suspected db_mysql because It seemed to appear in one of the errors reported by valgrind, and I had exceptions caused by it before.
But that was not it, db.exec (on my client code side) was returning nil and that, while respecting the return type of the proc I made the jester route call (string), was still a possible value. So of course, jester (or asynchttpserver?) 's resp function was trying to work with a nil string, and ugly-ly failed in an obscure SIGSEV.

The fix (client side): just don't pass nil valued things to the responses.

Suggestion: make jester more defensive in case of nil replies instead of crashing, report some nice message, or a default empty reply, or maybe an exception ?

PS: but that's not enough to remove Node.js from the menu, lol. sorry tho

[dom96]

You broke out valgrind because you had a nil in your program? That's a bit of an overreaction :)

But thanks for the suggestion. The problem with doing this is that it makes performance worse, but in debug mode it should be good. Btw IIRC there is a flag you can pass to Nim to get a Nil exception instead of a SIGSEGV. Maybe somebody will eventually answer me on IRC with the actual flag :)

[lightness1024]

I took valgrind because I had a stacktrace that didn't mention any of my code. Therefore I was lead to suspect a bug in jester. Also curiosity about how Nim would score. But in the end it was gdb that gave me the answer.
Though I'm really puzzled about the nil check being slow ? How can a nil check be slow compared to sending packets on a network ?

[lightness1024]

I checked the IRC, the module segfaults reminds me of structured exceptions on windows. Indeed like you said, SIGSEV happen at any access to a page address that hasn't been mapped to this process virtual space. not just nil dereference.

[dom96]

There isn't a bug in Jester. Unfortunately async stack traces aren't all that great in Nim yet.

Any branching code in a hot path will lead to slow-downs. If you're checking whether the response is nil for every request you'll get a massive slow-down.

[lightness1024]

you can't be serious lol

[dom96]

I never tested this notion, so I might be completely wrong :)

[dom96]

This won't be a problem soon as nil will be the same as ""