fukamachi / caveman

Lightweight web application framework for Common Lisp.
http://8arrow.org/caveman/
782 stars 63 forks source link

unhandled memory fault in caveman app #96

Open slyrus opened 7 years ago

slyrus commented 7 years ago

I can fairly reliably trigger this:

Callback Error: the message-complete callback failed
  Unhandled memory fault at #x5.
   [Condition of type FAST-HTTP.ERROR:CB-MESSAGE-COMPLETE]

Restarts:
 0: [SKIP-PRINTING-FRAME] Skip printing frame 2
 1: [ABORT] abort thread (#<THREAD "clack-handler-woo" RUNNING {1002166EA3}>)

Backtrace:
  0: ((FLET #:H0 :IN FAST-HTTP.PARSER::PARSE-BODY) #<unavailable argument>)
  1: (SB-KERNEL::%SIGNAL #<SB-SYS:MEMORY-FAULT-ERROR {1003D49303}>)
  2: (ERROR SB-SYS:MEMORY-FAULT-ERROR :ADDRESS 5)
  3: (SB-SYS:MEMORY-FAULT-ERROR)
  4: ("foreign function: call_into_lisp")
  5: ("foreign function: post_signal_tramp")
  6: [error printing frame]
  7: ((LABELS SB-IMPL::HANDLE-IT :IN SB-KERNEL:OUTPUT-OBJECT) #<SB-PRETTY:PRETTY-STREAM {1003D491C3}>)
  8: [error printing frame]
  9: ((FLET #:PPRINT-BLOCK :IN SB-DEBUG::PRINT-FRAME-CALL) #<unused argument> #<SB-PRETTY:PRETTY-STREAM {1003D491C3}>)
 10: ((FLET #:WITH-PRETTY-STREAM2629 :IN SB-PRETTY::CALL-LOGICAL-BLOCK-PRINTER) #<SB-PRETTY:PRETTY-STREAM {1003D491C3}>)
 11: (SB-PRETTY::CALL-LOGICAL-BLOCK-PRINTER #<CLOSURE (FLET #:PPRINT-BLOCK :IN SB-DEBUG::PRINT-FRAME-CALL) {7F4933DAD08B}> #<SB-IMPL::STRING-OUTPUT-STREAM {1003D432C3}> "(" NIL ")" NIL)
 12: (SB-DEBUG::PRINT-FRAME-CALL #<SB-DI::COMPILED-FRAME DJULA:RENDER-TEMPLATE*> #<SB-IMPL::STRING-OUTPUT-STREAM {1003D432C3}> :PRINT-FRAME-SOURCE NIL :NUMBER 2 :METHOD-FRAME-STYLE :NORMAL :EMERGENCY-BEST-..
 13: ((LAMBDA (SB-DEBUG::FRAME) :IN PRINT-BACKTRACE) #<SB-DI::COMPILED-FRAME DJULA:RENDER-TEMPLATE*>)
 14: (SB-DEBUG::MAP-BACKTRACE #<CLOSURE (LAMBDA (SB-DEBUG::FRAME) :IN PRINT-BACKTRACE) {1003D45B0B}> :START 0 :FROM #<SB-DI::COMPILED-FRAME TRIVIAL-BACKTRACE:PRINT-BACKTRACE-TO-STREAM> :COUNT 4611686018427..
 15: ((FLET #:THUNK61 :IN PRINT-BACKTRACE))
 16: ((LAMBDA NIL :IN SB-DEBUG::FUNCALL-WITH-DEBUG-IO-SYNTAX))
 17: (SB-IMPL::CALL-WITH-SANE-IO-SYNTAX #<CLOSURE (LAMBDA NIL :IN SB-DEBUG::FUNCALL-WITH-DEBUG-IO-SYNTAX) {1003D454DB}>)
 18: (SB-IMPL::%WITH-STANDARD-IO-SYNTAX #<CLOSURE (FLET #:THUNK :IN SB-DEBUG::FUNCALL-WITH-DEBUG-IO-SYNTAX) {7F4933DAD5DB}>)
 19: (SB-DEBUG::FUNCALL-WITH-DEBUG-IO-SYNTAX #<CLOSURE (FLET #:THUNK61 :IN PRINT-BACKTRACE) {7F4933DAD68B}>)
 20: (PRINT-BACKTRACE :STREAM #<SB-IMPL::STRING-OUTPUT-STREAM {1003D432C3}> :START 0 :FROM :DEBUGGER-FRAME :COUNT 4611686018427387903 :PRINT-THREAD T :PRINT-FRAME-SOURCE NIL :METHOD-FRAME-STYLE NIL :EMERGE..
 21: (TRIVIAL-BACKTRACE:PRINT-BACKTRACE-TO-STREAM #<SB-IMPL::STRING-OUTPUT-STREAM {1003D432C3}>)
 22: (TRIVIAL-BACKTRACE:PRINT-BACKTRACE #<SB-SYS:MEMORY-FAULT-ERROR {1003D43153}> :OUTPUT NIL :IF-EXISTS :APPEND :VERBOSE NIL)
 23: [error printing frame]
 24: ((LABELS MYWAY.MAPPER::DISPATCH-WITH-RULES :IN MYWAY.MAPPER:DISPATCH) (#<NINGLE.ROUTE:NINGLE-ROUTE {100868A5E3}> #<NINGLE.ROUTE:NINGLE-ROUTE {100868A5F3}> #<NINGLE.ROUTE:NINGLE-ROUTE {100868A603}> #<N..
 25: ((:METHOD LACK.COMPONENT:CALL (NINGLE.APP:<APP> T)) #<ATOUK-TEST-APP.WEB::<WEB> {1006C7E963}> #<unused argument>) [fast-method]
 26: ((:METHOD LACK.COMPONENT:CALL (CAVEMAN2.APP:<APP> T)) #<ATOUK-TEST-APP.WEB::<WEB> {1006C7E963}> (:LACK.SESSION.OPTIONS (:ID "8eca7737a96508fe4314ab4a8a7a27feea265202" :NEW-SESSION NIL :CHANGE-ID NIL ...
 27: ((:METHOD LACK.COMPONENT:CALL :AROUND (NINGLE.APP:<APP> T)) #<ATOUK-TEST-APP.WEB::<WEB> {1006C7E963}> (:LACK.SESSION.OPTIONS (:ID "8eca7737a96508fe4314ab4a8a7a27feea265202" :NEW-SESSION NIL :CHANGE-ID..
 28: ((LAMBDA (ATOUK-TEST-APP.APP::ENV) :IN "/src/lisp/atouk-test-app/app.lisp") (:LACK.SESSION.OPTIONS (:ID "8eca7737a96508fe4314ab4a8a7a27feea265202" :NEW-SESSION NIL :CHANGE-ID NIL ...) :LACK.SESSION #<..
 29: ((LAMBDA (LACK.MIDDLEWARE.SESSION::ENV) :IN "/root/quicklisp/dists/quicklisp/software/lack-20161204-git/src/middleware/session.lisp") (:LACK.SESSION.OPTIONS (:ID "8eca7737a96508fe4314ab4a8a7a27feea265..
 30: (LACK.UTIL:FUNCALL-WITH-CB #<CLOSURE (LAMBDA (LACK.MIDDLEWARE.SESSION::ENV) :IN "/root/quicklisp/dists/quicklisp/software/lack-20161204-git/src/middleware/session.lisp") {1003AB70EB}> (:RAW-BODY #<FLE..
 31: ((LAMBDA (LACK.MIDDLEWARE.BACKTRACE::ENV) :IN "/root/quicklisp/dists/quicklisp/software/lack-20161204-git/src/middleware/backtrace.lisp") (:RAW-BODY #<FLEXI-STREAMS::VECTOR-INPUT-STREAM {1003D40F83}> ..
 32: ((LAMBDA NIL :IN WOO::SETUP-PARSER))
 33: ((LAMBDA (FAST-HTTP.HTTP:HTTP) :IN FAST-HTTP:MAKE-PARSER) #<unused argument>)
 34: (FAST-HTTP.PARSER::PARSE-BODY #S(FAST-HTTP.HTTP:HTTP-REQUEST :METHOD :GET :MAJOR-VERSION 1 :MINOR-VERSION 1 :STATUS 0 :CONTENT-LENGTH NIL :CHUNKED-P NIL ...) #<unavailable argument> #<unavailable argu..
 35: (FAST-HTTP.PARSER:PARSE-REQUEST #S(FAST-HTTP.HTTP:HTTP-REQUEST :METHOD :GET :MAJOR-VERSION 1 :MINOR-VERSION 1 :STATUS 0 :CONTENT-LENGTH NIL :CHUNKED-P NIL ...) #S(FAST-HTTP.PARSER:CALLBACKS :MESSAGE-B..
 36: ((LAMBDA (FAST-HTTP::DATA &KEY :START :END) :IN FAST-HTTP:MAKE-PARSER) #(71 69 84 32 47 108 ...) :START #<unavailable argument> :END #<unavailable argument>)
 37: (WOO::READ-CB #S(WOO.EV.SOCKET:SOCKET :WATCHERS #(#.(SB-SYS:INT-SAP #X7F492C011190) #.(SB-SYS:INT-SAP #X7F492C0111D0) #.(SB-SYS:INT-SAP #X7F492C011510)) :LAST-ACTIVITY 1.496376079342627d9 :FD 12 :REMO..
 38: ((LAMBDA (WOO.EV.TCP::EVLOOP WOO.EV.TCP::WATCHER WOO.EV.TCP::EVENTS) :IN "/root/quicklisp/dists/quicklisp/software/woo-20170227-git/src/ev/tcp.lisp") #<unused argument> #.(SB-SYS:INT-SAP #X7F492C01119..
 39: ((LAMBDA (SB-ALIEN::ARGS-POINTER SB-ALIEN::RESULT-POINTER FUNCTION) :IN "/root/.cache/common-lisp/sbcl-1.3.18.23-dbb8186-linux-x64/root/quicklisp/dists/quicklisp/software/woo-20170227-git/src/ev/socke..
 40: ("foreign function: call_into_lisp")
 41: ("foreign function: funcall3")
 42: ("foreign function: callback_wrapper_trampoline")
 43: ("foreign function: #x20100D1C")
 44: (WOO:RUN #<CLOSURE (LAMBDA (LACK.MIDDLEWARE.BACKTRACE::ENV) :IN "/root/quicklisp/dists/quicklisp/software/lack-20161204-git/src/middleware/backtrace.lisp") {1001F3FF9B}> :DEBUG T :PORT 8080 :ADDRESS N..
 45: ((LAMBDA NIL :IN BORDEAUX-THREADS::BINDING-DEFAULT-SPECIALS))
 46: ((FLET #:WITHOUT-INTERRUPTS-BODY-1127 :IN SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE))
 47: ((FLET SB-THREAD::WITH-MUTEX-THUNK :IN SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE))
 48: ((FLET #:WITHOUT-INTERRUPTS-BODY-358 :IN SB-THREAD::CALL-WITH-MUTEX))
 49: (SB-THREAD::CALL-WITH-MUTEX #<CLOSURE (FLET SB-THREAD::WITH-MUTEX-THUNK :IN SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE) {7F4933DAED6B}> #<SB-THREAD:MUTEX "thread result lock" owner: #<SB-THREAD:THR..
 50: (SB-THREAD::INITIAL-THREAD-FUNCTION-TRAMPOLINE #<SB-THREAD:THREAD "clack-handler-woo" RUNNING {1002166EA3}> NIL #<CLOSURE (LAMBDA NIL :IN BORDEAUX-THREADS::BINDING-DEFAULT-SPECIALS) {1002166E4B}> (#<S..
 51: ("foreign function: call_into_lisp")
 52: ("foreign function: new_thread_trampoline")

If I use ab to load a page 10,000 times and then load another page, I can trigger this fairly reliably.

Not sure if the problem lies in caveman2/clack/lack/fast-http/etc... or in SBCL itself. Happy to provide more details.

slyrus commented 7 years ago

And digging more deeply down the rabbit hole, I can see the following when I turn off various optimizations and (the ...) forms. We shouldn't be lying to the compiler and should be striving for correctness over speed here.

The value
  263
is not of type
  (UNSIGNED-BYTE 8)
   [Condition of type TYPE-ERROR]

Restarts:
 0: [ABORT] abort thread (#<THREAD "clack-handler-woo" RUNNING {1002339743}>)

Backtrace:
  0: (FAST-HTTP.PARSER::PARSE-HEADERS #S(FAST-HTTP.HTTP:HTTP-REQUEST :METHOD :GET :MAJOR-VERSION 1 :MINOR-VERSION 1 :STATUS 0 :CONTENT-LENGTH NIL :CHUNKED-P NIL ...) #S(FAST-HTTP.PARSER:CALLBACKS :MESSAGE-..
      Locals:
        FAST-HTTP.PARSER:CALLBACKS = #S(FAST-HTTP.PARSER:CALLBACKS ..)
        FAST-HTTP.PARSER::DATA = #(71 69 84 32 47 108 ...)
        #:DATA2862 = #<invalid object #x7F56EC01166F>
        #:ELEM2859 = 65
        FAST-HTTP.PARSER::END = 408
        #:G-END2858 = 408
        #:G2932 = 263
        #:G2932#1 = 263
        #:G2933 = NIL
        #:G2933#1 = NIL
        FAST-HTTP.HTTP:HTTP = #S(FAST-HTTP.HTTP:HTTP-REQUEST :METHOD :GET :MAJOR-VERSION 1 :MINOR-VERSION 1 :STATUS 0 :CONTENT-LENGTH NIL :CHUNKED-P NIL ...)
        #:P2860 = 231
        FAST-HTTP.PARSER::START = 21
  1: (FAST-HTTP.PARSER:PARSE-REQUEST #S(FAST-HTTP.HTTP:HTTP-REQUEST :METHOD :GET :MAJOR-VERSION 1 :MINOR-VERSION 1 :STATUS 0 :CONTENT-LENGTH NIL :CHUNKED-P NIL ...) #S(FAST-HTTP.PARSER:CALLBACKS :MESSAGE-B..
  2: ((LAMBDA (FAST-HTTP::DATA &KEY :START :END) :IN FAST-HTTP:MAKE-PARSER) #(71 69 84 32 47 108 ...) :START #<unavailable argument> :END #<unavailable argument>)
  3: (WOO::READ-CB #S(WOO.EV.SOCKET:SOCKET :WATCHERS #(#.(SB-SYS:INT-SAP #X7F56EC002740) #.(SB-SYS:INT-SAP #X7F56EC002780) #.(SB-SYS:INT-SAP #X7F56EC0027C0)) :LAST-ACTIVITY 1.4963796056381776d9 :FD 20 :REM..
  4: ((LAMBDA (WOO.EV.TCP::EVLOOP WOO.EV.TCP::WATCHER WOO.EV.TCP::EVENTS) :IN "/root/quicklisp/dists/quicklisp/software/woo-20170227-git/src/ev/tcp.lisp") #<unused argument> #.(SB-SYS:INT-SAP #X7F56EC00274..
  5: ((LAMBDA (SB-ALIEN::ARGS-POINTER SB-ALIEN::RESULT-POINTER FUNCTION) :IN "/root/.cache/common-lisp/sbcl-1.3.18.23-dbb8186-linux-x64/root/quicklisp/dists/quicklisp/software/woo-20170227-git/src/ev/socke..
  6: ("foreign function: call_into_lisp")
  7: ("foreign function: funcall3")
  8: ("foreign function: callback_wrapper_trampoline")
  9: ("foreign function: #x20100D1C")
 10: (WOO:RUN #<CLOSURE (LAMBDA (LACK.MIDDLEWARE.BACKTRACE::ENV) :IN "/root/quicklisp/dists/quicklisp/software/lack-20161204-git/src/middleware/backtrace.lisp") {10023391CB}> :DEBUG T :PORT 8080 :ADDRESS N..