Segmentation fault: runtime crash in xeno

swamp-agr commented 4 years ago

We have an application that make a lot of asynchronous HTTP requests to external system with a custom response timeout and strict non-functional requirements.
External system respond with XML bytestrings and we used xeno as a parser for them.
Under const 500 rps application started to crash unexpectedly after 1-5 minutes uptime with a segmentation fault.
While bisecting we identified that root cause located somewhere under the hood of xeno SAX parser.
After switching to tagsoup the problem has gone, application stopped to crash.
I do realise that xeno parser should be used with care, different trade-offs should be considered.

Here are some details:

GHC: 8.4.3, 8.4.4.
xeno: 0.4.2.

lldb output (looks like GC is going wild):

(lldb) thread backtrace 22
* thread #22, stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
* frame #0: 0x000000010cc2cd91 some-application`LOOKS_LIKE_INFO_PTR_NOT_NULL(p=12297829382473034410) at ClosureMacros.h:260:23
  frame #1: 0x000000010cc2baa6 some-application`LOOKS_LIKE_INFO_PTR(p=12297829382473034410) at ClosureMacros.h:265:42
  frame #2: 0x000000010cc2aa7d some-application`LOOKS_LIKE_CLOSURE_PTR(p=0x00000042095c41e0) at ClosureMacros.h:270:12
  frame #3: 0x000000010cc2b05a some-application`checkClosure(p=0x0000004200209000) at Sanity.c:344:9
  frame #4: 0x000000010cc2b9b7 some-application`checkHeapChain(bd=0x0000004200200240) at Sanity.c:473:33
  frame #5: 0x000000010cc2ce40 some-application`checkGeneration(gen=0x00007fee41704250, after_major_gc=true) at Sanity.c:769:5
  frame #6: 0x000000010cc2c0b3 some-application`checkFullHeap(after_major_gc=true) at Sanity.c:788:9
  frame #7: 0x000000010cc2c03d some-application`checkSanity(after_gc=true, major_gc=true) at Sanity.c:797:5
  frame #8: 0x000000010cc256e4 some-application`GarbageCollect(collect_gen=1, do_heap_census=false, gc_type=2, cap=0x00007fee4180a600, idle_cap=0x00007fee4140bf80) at GC.c:769:3
  frame #9: 0x000000010cc0c77f some-application`scheduleDoGC(pcap=0x00007000053c6f48, task=0x00007fee41712000, force_major=true) at Schedule.c:1804:5
  frame #10: 0x000000010cc0dd59 some-application`scheduleDetectDeadlock(pcap=0x00007000053c6f48, task=0x00007fee41712000) at Schedule.c:924:9
  frame #11: 0x000000010cc0b1d2 some-application`schedule(initialCapability=0x00007fee4180a600, task=0x00007fee41712000) at Schedule.c:281:5
  frame #12: 0x000000010cc0bbdd some-application`scheduleWorker(cap=0x00007fee4180a600, task=0x00007fee41712000) at Schedule.c:2564:11
  frame #13: 0x000000010cc1487a some-application`workerStart(task=0x00007fee41712000) at Task.c:445:5
  frame #14: 0x00007fff70081109 libsystem_pthread.dylib`_pthread_start + 148
  frame #15: 0x00007fff7007cb8b libsystem_pthread.dylib`thread_start + 15
(lldb) disassemble
some-application`LOOKS_LIKE_INFO_PTR_NOT_NULL:
  0x10cc2cd70 <+0>:  pushq  %rbp
  0x10cc2cd71 <+1>:  movq   %rsp, %rbp
  0x10cc2cd74 <+4>:  subq   $0x20, %rsp
  0x10cc2cd78 <+8>:  movq   %rdi, -0x8(%rbp)
  0x10cc2cd7c <+12>: movq   -0x8(%rbp), %rdi
  0x10cc2cd80 <+16>: callq  0x10cbf7760               ; INFO_PTR_TO_STRUCT at ClosureMacros.h:59
  0x10cc2cd85 <+21>: xorl   %ecx, %ecx
  0x10cc2cd87 <+23>: movb   %cl, %dl
  0x10cc2cd89 <+25>: movq   %rax, -0x10(%rbp)
  0x10cc2cd8d <+29>: movq   -0x10(%rbp), %rax
->  0x10cc2cd91 <+33>: cmpl   $0x0, 0x8(%rax)
  0x10cc2cd95 <+37>: movb   %dl, -0x11(%rbp)
  0x10cc2cd98 <+40>: je     0x10cc2cda8               ; <+56> at ClosureMacros.h
  0x10cc2cd9a <+42>: movq   -0x10(%rbp), %rax
  0x10cc2cd9e <+46>: cmpl   $0x40, 0x8(%rax)
  0x10cc2cda2 <+50>: setb   %cl
  0x10cc2cda5 <+53>: movb   %cl, -0x11(%rbp)
  0x10cc2cda8 <+56>: movb   -0x11(%rbp), %al
  0x10cc2cdab <+59>: andb   $0x1, %al
  0x10cc2cdad <+61>: movzbl %al, %eax
  0x10cc2cdb0 <+64>: addq   $0x20, %rsp
  0x10cc2cdb4 <+68>: popq   %rbp
  0x10cc2cdb5 <+69>: retq
  0x10cc2cdb6 <+70>: nopw   %cs:(%rax,%rax)

I guess, some unsafe functions are producing this unexpected effect, e.g.

qrilka commented 4 years ago

@swamp-agr any example of an XML giving this? It doesn't look to me that high rps could have anything to do with out of bounds access at the linked sites.

swamp-agr commented 4 years ago

@qrilka, let me reproduce the case with enabled dump of entire bytestring. I will come back once will be able to obtain such example.

swamp-agr commented 4 years ago

App crashed on 4s since start.
I was able to gather 278 responses before crash on local machine.
However, in single-threaded mode all of them are parseable.

They contain some sensitive data I cannot share.

swamp-agr commented 4 years ago

I will try to reproduce the issue on some sample/open datasets.

ocramz commented 3 years ago

Hi @swamp-agr , any updates on this?

mgajda commented 3 years ago

@swamp-agr Can I please have an XML document to reproduce the issue?

swamp-agr commented 3 years ago

@ocramz @mgajda thank you for reaching me out.

There are two components required in order to reproduce the case:

Concurrency;
IO.

While previously I was receiving different XMLs via http-client concurrently with explicit ResponseTimeout, currently I am able to emulate the case and reproduce segmentation fault via reading and parsing the parts of the same file in async mode.

I set up the repository which you could clone and try to reproduce by yourselves: https://github.com/swamp-agr/xeno-issue-43

Issue reproduced with both stack (GHC 8.8) and cabal (GHC 8.10).

Stack:

stack build
stack exec -- xeno-runner
[1]    29950 segmentation fault  stack exec -- xeno-runner

Cabal:

cabal v2-build
cabal v2-exec -- xeno-runner
[1]    30266 segmentation fault  cabal v2-exec -- xeno-runner

swamp-agr commented 3 years ago

I also noticed that minor tweaks in example2.xml (i.e. removing some nodes from it) without any changes in code could make segfault gone.

qrilka commented 3 years ago

@swamp-agr what are those tweaks?

swamp-agr commented 3 years ago

Remove first occurence of //Tracking@event="firstQuartile" (whole line).
Remove first occurence of //Tracking@event="thirdQuartile" (whole line).

Output will become:

stack exec -- xeno-runner
errors: 10970
good: 422

swamp-agr commented 3 years ago

@ocramz @mgajda Did you have a time to confirm the case with information provided in this comment above? Could you please share techniques on how to debug segmentation faults in order to help with resolving this issue?

ocramz commented 3 years ago

Hi, currently I have no bandwidth to investigate this issue. sorry!

On Wed, 3 Mar 2021 at 23:02, Andrey Prokopenko notifications@github.com wrote:

@ocramz https://github.com/ocramz @mgajda https://github.com/mgajda Did you have a time to confirm the case with information provided in this comment above https://github.com/ocramz/xeno/issues/43#issuecomment-784567243?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/ocramz/xeno/issues/43#issuecomment-790094332, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABNBDKHCL3LUZL2FIJT6A33TB2WVVANCNFSM4S7VWUEA .

ingarsjekabsons commented 3 years ago

Hi there!

By accident I've stumbled upon strange xeno's segfaulting issue and I seem to have stable static XML payload with which parse is segfaulting - https://gist.github.com/ingarsjekabsons/5061bd84e0abc30aa78de5b59ecf9259

Seems that any tiny change to this xml makes segfault gone. Add some random characters in the comment section at the end - gone, remove some random element from the document - gone, etc.

Not sure I'm hitting exactly the same issue as reported here initially, though, since I'm using DOM parser, not SAX.

Will try to spend some time digging into more details.

adamse commented 3 years ago

I changed all the unsafe* functions to their safe variants and found that we we're calling unsafeGrow with a negative length, this caused the problem. https://github.com/ocramz/xeno/pull/48 should fix this, please give it a spin @ingarsjekabsons, @swamp-agr.

swamp-agr commented 3 years ago

@adamse With following cabal.project

packages: .

source-repository-package
    type: git
    location: https://github.com/adamse/xeno.git
    tag: f4a6f9f23415ed24aae8dd2529ea3788234044e1

I cannot reproduce the issue (segmentation fault):

cabal v2-exec -- xeno-runner
errors: 11514
good: 432

ingarsjekabsons commented 3 years ago

Can confirm, no more segfaults with known payload.

xeno@master:

*Xeno.SAX IO BS Xeno.DOM> d <- IO.openFile "bad.xml" ReadMode >>= BS.hGetContents
*Xeno.SAX IO BS Xeno.DOM> parse d
cabal: repl failed for xeno-0.4.2. The build process segfaulted (i.e.
SIGSEGV).

xeno@pull/43:

*Xeno.SAX IO BS Xeno.DOM> d <- IO.openFile "bad.xml" ReadMode >>= BS.hGetContents
*Xeno.SAX IO BS Xeno.DOM> 
*Xeno.SAX IO BS Xeno.DOM> parse d
Right (Node "Package" [("name","cs.bc.ebpp"),("version","")] [Text "\n    ",Element (Node "Dependency" [("name","cs.bc.ebpp_db"),("version","1.3.2")] []),Text "\n    ",Element (Node "Dependency" [("name","cs.bc.libutils"),("version","")] []),Text "\n    ",Element (Node "Dependency" [("name","cs.bc.libutilstux"),("version","")] []),Text "\n    ",Element (Node "Dependency" [("name","cs.bc.liborasql"),("version","")] []),Text "\n    ",Element (Node "Dependency" [("name","cs.ext.libxercesc"),("version","")] []),Text "\n    ",Eleme
...
...
...

ocramz commented 3 years ago

Thank you everyone, xeno-0.4.3 with the fix is on Hackage ^^

ocramz / xeno

Segmentation fault: runtime crash in xeno #43