orthecreedence / wookie

Asynchronous HTTP server in common lisp
http://wookie.lyonbros.com/
MIT License
189 stars 19 forks source link

Possible bug in SETUP-PARSER #79

Closed mtstickney closed 7 years ago

mtstickney commented 7 years ago

I saw this in my server logs the other day, and I'm having some trouble determining whether this is actually a bug or not. The error seems to be same thing as #68, but in a different place (somewhere in setup-parser) -- I believe the "response already sent" error is erroneous, and only happens because I'm trying to send a status page out in response to an error that's occurred after the original response has been processed.

There's a (rather large) backtrace pasted below that I'm trying to analyze to see where this could have originated from. To complicate matters, this is a clackup app, and I'm using an older version of wookie (dated 2015-09-23). I'm still working through the problem, but I figured I'd report it early in case you knew what it was. I'll update with any further progress.

 <ERROR> [04:50:15] laundrybin.middleware - Error re-ensuring backend connection: attempt to RETURN-FROM a block or GO to a tag that no longer exists
Unhandled WOOKIE:RESPONSE-ALREADY-SENT in thread #<SB-THREAD:THREAD "main thread" RUNNING
                                                    {267AB0E9}>:
  Response already sent: #<RESPONSE {26C56411}>

Backtrace for: #<SB-THREAD:THREAD "main thread" RUNNING {267AB0E9}>
0: (SB-DEBUG::DEBUGGER-DISABLED-HOOK #<WOOKIE:RESPONSE-ALREADY-SENT {26C77B89}> #<unavailable argument>)
1: (SB-DEBUG::RUN-HOOK *INVOKE-DEBUGGER-HOOK* #<WOOKIE:RESPONSE-ALREADY-SENT {26C77B89}>)
2: (INVOKE-DEBUGGER #<WOOKIE:RESPONSE-ALREADY-SENT {26C77B89}>)
3: (ERROR #<WOOKIE:RESPONSE-ALREADY-SENT {26C77B89}>)
4: (WOOKIE:SEND-RESPONSE #<WOOKIE:RESPONSE {26C56411}> :STATUS 500 :HEADERS (:CONTENT-TYPE "text/plain") :BODY "Error connecting to backend." :CLOSE NIL)
5: ((LAMBDA (CLACK.HANDLER.WOOKIE::CLACK-RES) :IN CLACK.HANDLER.WOOKIE::HANDLE-RESPONSE) (500 (:CONTENT-TYPE "text/plain") ("Error connecting to backend.")))
6: ((LAMBDA (BLACKBIRD-BASE::E) :IN BLACKBIRD-BASE:DO-CATCH) #<SB-INT:SIMPLE-CONTROL-ERROR "attempt to RETURN-FROM a block or GO to a tag that no longer exists" {26C66091}>)
7: (BLACKBIRD-BASE::RUN-PROMISE #<BLACKBIRD-BASE:PROMISE name: "attach: (BLACKBIRD-BASE:PROMISIFY (ENSURE-CONNECTION CON))" finished: NIL errored: T forward: NIL {26C617F1}>)
8: (BLACKBIRD-BASE::DO-ATTACH-ERRBACK #<BLACKBIRD-BASE:PROMISE name: "attach: (BLACKBIRD-BASE:PROMISIFY (ENSURE-CONNECTION CON))" finished: NIL errored: T forward: NIL {26C617F1}> #<CLOSURE (LAMBDA (BLACKBIRD-BASE::E) :IN BLACKBIRD-BASE:DO-CATCH) {26C6619D}>)
9: ((LAMBDA (BLACKBIRD-BASE::RESOLVE-FN #:|reject-fn827|) :IN BLACKBIRD-BASE:DO-CATCH) #<CLOSURE (LAMBDA (&REST BLACKBIRD-BASE::VALS) :IN BLACKBIRD-BASE:CREATE-PROMISE) {26C6613D}> #<CLOSURE (LAMBDA (CONDITION) :IN BLACKBIRD-BASE:CREATE-PROMISE) {26C6614D}>)
10: (BLACKBIRD-BASE:CREATE-PROMISE #<CLOSURE (LAMBDA (BLACKBIRD-BASE::RESOLVE-FN #:|reject-fn827|) :IN BLACKBIRD-BASE:DO-CATCH) {26C660F5}> :NAME NIL)
11: ((LAMBDA (&REST #:|async-ignore28|) :IN WOOKIE::SETUP-PARSER))
12: ((LAMBDA (&REST BLACKBIRD-BASE::ARGS) :IN BLACKBIRD-BASE:DO-ATTACH) NIL)
13: (BLACKBIRD-BASE::RUN-PROMISE #<BLACKBIRD-BASE:PROMISE name: "amap" finished: T errored: NIL forward: NIL {26C5F3D9}>)
14: (BLACKBIRD-BASE:DO-ATTACH #<BLACKBIRD-BASE:PROMISE finished: NIL errored: NIL forward: T {26C5F289}> #<CLOSURE (LAMBDA (&REST #:|async-ignore28|) :IN WOOKIE::SETUP-PARSER) {26C601DD}> :NAME "attach: (RUN-HOOKS :PRE-ROUTE REQUEST RESPONSE)")
15: (BLACKBIRD-BASE::DO-PROMISIFY #<CLOSURE (LAMBDA NIL :IN WOOKIE::SETUP-PARSER) {26C5F125}> :NAME "promisify: (WAIT (RUN-HOOKS :PRE-ROUTE REQUEST RESPONSE)
             (BLOCK SKIP-ROUTE
               (FLET ((RUN-ROUTE (ROUTE)
                        (IF ROUTE
                            (LET ((ROUTE-FN (GETF ROUTE :CURRIED-ROUTE)))
                              (VOM:DEBUG1 \"(route) Dispatch ~a: ~s\" SOCK ROUTE)
                              (FUNCALL ROUTE-FN REQUEST RESPONSE)
                              (LET ((REQUEST-BODY-CB
                                     (REQUEST-BODY-CALLBACK REQUEST)))
                                (WHEN
                                    (AND (GETF ROUTE :ALLOW-CHUNKING)
                                         (GETF ROUTE :BUFFER-BODY))
                                  (IF (AND BODY-BUFFER BODY-FINISHED-P)
                                      (LET ((BODY
                                             (FAST-IO:FINISH-OUTPUT-BUFFER
                                              BODY-BUFFER)))
                                        (IF REQUEST-BODY-CB
                                            (PROGN
                                             (FUNCALL REQUEST-BODY-CB BODY T)
                                             (SETF BODY-BUFFER NIL))
                                            (SETF (REQUEST-BODY-CALLBACK-SETCB
                                                   REQUEST)
                                                    (LAMBDA (BODY-CB)
                                                      (FUNCALL BODY-CB BODY
                                                               T)))))
                                      (SETF (REQUEST-BODY-CALLBACK-SETCB
                                             REQUEST)
                                              (LAMBDA (BODY-CB)
                                                (WHEN BODY-BUFFER
                                                  (LET ((BODY
                                                         (FAST-IO:FINISH-OUTPUT-BUFFER
                                                          BODY-BUFFER)))
                                                    (FUNCALL BODY-CB BODY
                                                             BODY-FINISHED-P)
                                                    (SETF BODY-BUFFER
                                                            NIL)))))))))
                            (PROGN
                             (VOM:WARN \"(route) Missing route: ~a ~s\"
                                       (REQUEST-METHOD REQUEST) ROUTE-PATH)
                             (FUNCALL 'MAIN-EVENT-HANDLER
                                      (MAKE-INSTANCE 'ROUTE-NOT-FOUND :RESOURCE
                                                     ROUTE-PATH :SOCKET SOCK)
                                      SOCK)
                             (RETURN-FROM SKIP-ROUTE)))))
                 (LET ((ROUTE-EXCLUDE NIL))
                   (BLOCK RUN-ROUTE
                     (LOOP
                      (BLOCK NEXT
                        (HANDLER-BIND ((USE-NEXT-ROUTE
                                        (LAMBDA (E)
                                          (DECLARE (IGNORE E))
                                          (VOM:DEBUG1 \"(route) Next route\")
                                          (PUSH ROUTE ROUTE-EXCLUDE)
                                          (SETF ROUTE
                                                  (FIND-ROUTE
                                                   (FAST-HTTP.HTTP:HTTP-METHOD
                                                    HTTP)
                                                   ROUTE-PATH :EXCLUDE
                                                   ROUTE-EXCLUDE))
                                          (RETURN-FROM NEXT))))
                          (PROGN
                           (RUN-ROUTE ROUTE)
                           (RETURN-FROM RUN-ROUTE))))))))
               (DO-RUN-HOOKS (SOCK)
                   (RUN-HOOKS :POST-ROUTE REQUEST RESPONSE)
                 NIL)))")
16: ((LABELS WOOKIE::DISPATCH-ROUTE :IN WOOKIE::SETUP-PARSER))
17: ((LAMBDA (&REST BLACKBIRD-BASE::ARGS) :IN BLACKBIRD-BASE:DO-ATTACH) NIL)
18: (BLACKBIRD-BASE::RUN-PROMISE #<BLACKBIRD-BASE:PROMISE name: "amap" finished: T errored: NIL forward: NIL {26C5E1A9}>)
19: (BLACKBIRD-BASE:DO-ATTACH #<BLACKBIRD-BASE:PROMISE finished: NIL errored: NIL forward: T {26C5E059}> #<CLOSURE (LAMBDA (&REST #:|async-ignore73|) :IN WOOKIE::SETUP-PARSER) {26C5EFAD}> :NAME "attach: (RUN-HOOKS :BODY-COMPLETE REQUEST)")
20: (BLACKBIRD-BASE::DO-PROMISIFY #<CLOSURE (LAMBDA NIL :IN WOOKIE::SETUP-PARSER) {26C5DEED}> :NAME "promisify: (WAIT (RUN-HOOKS :BODY-COMPLETE REQUEST)
             (DISPATCH-ROUTE))")
21: ((LABELS WOOKIE::FINISH-CALLBACK :IN WOOKIE::SETUP-PARSER))
22: ((LAMBDA (FAST-HTTP.HTTP:HTTP) :IN FAST-HTTP:MAKE-PARSER) #<unavailable argument>)
23: (FAST-HTTP.PARSER::PARSE-BODY #<unavailable argument> #<unavailable argument> #<unavailable argument> #<unavailable argument> #<unavailable argument> #<unavailable argument>)
24: (FAST-HTTP.PARSER:PARSE-REQUEST #<unavailable argument> #<unavailable argument> #<unavailable argument> :START #<unavailable argument> :END #<unavailable argument>)
25: ((LAMBDA (FAST-HTTP::DATA &KEY :START :END) :IN FAST-HTTP:MAKE-PARSER) #<unavailable argument> :START #<unavailable argument> :END #<unavailable argument>)
26: (WOOKIE::READ-DATA #<CL-ASYNC:TCP-SOCKET {26C55071}> #(80 79 83 84 32 47 65 112 112 47 80 114 ...))
27: (CL-ASYNC-UTIL:CALL-WITH-CALLBACK-RESTARTS #<CLOSURE (LAMBDA NIL :IN CL-ASYNC::STREAMISH-READ-CB) {26C56D25}> :CONTINUE-FN #<CLOSURE (LAMBDA NIL :IN CL-ASYNC::STREAMISH-READ-CB) {26C56D55}> :ABORT-RESTART-DESCRIPTION "Abort cl-async callback.")
28: (CL-ASYNC::STREAMISH-READ-CB #.(SB-SYS:INT-SAP #X0085C218) 749 #<unavailable argument>)
29: ((LAMBDA (SB-ALIEN::ARGS-POINTER SB-ALIEN::RESULT-POINTER FUNCTION) :IN "C:/Users/mts/AppData/Local/cache/common-lisp/sbcl-1.3.9-win-x86/C/Users/mts/Desktop/laundrybin/quicklisp/dists/cl-async/software/cl-async-dd9bbfa09883ce7d379fc6ee3c85adf3799434ea/src/dns.fasl") 671215 671211 #<FUNCTION (LAMBDA (CL-ASYNC::UVSTREAM CL-ASYNC::NREAD CL-ASYNC::BUF) :IN "C:/Users/mts/Desktop/laundrybin/quicklisp/dists/cl-async/software/cl-async-dd9bbfa09883ce7d379fc6ee3c85adf3799434ea/src/streamish.lisp") {22ADB9DD}>)
30: ("foreign function: #x42C060")
31: ("foreign function: #x4033A2")
32: ("foreign function: #x416E51")
33: ("foreign function: #x22100C1E")
34: (CL-ASYNC:START-EVENT-LOOP #<CLOSURE (LAMBDA NIL :IN CLACK.HANDLER.WOOKIE:RUN) {27B8A07D}> :CATCH-APP-ERRORS NIL :SEND-ERRORS-TO-EVENTCB T)
35: (CLACK.HANDLER.WOOKIE:RUN #<CLOSURE (LAMBDA (LACK.MIDDLEWARE.BACKTRACE::ENV) :IN "C:/Users/mts/Desktop/laundrybin/quicklisp/dists/lack/software/lack-627ae9d2c32f07d0504173ef225a7f8a091ab605/src/middleware/backtrace.lisp") {27B408E5}> :ALLOW-OTHER-KEYS T :PORT 5000 :DEBUG NIL :USE-THREAD NIL)
36: (CLACK.HANDLER:RUN #<CLOSURE (LAMBDA (LACK.MIDDLEWARE.BACKTRACE::ENV) :IN "C:/Users/mts/Desktop/laundrybin/quicklisp/dists/lack/software/lack-627ae9d2c32f07d0504173ef225a7f8a091ab605/src/middleware/backtrace.lisp") {27B408E5}> :WOOKIE :PORT 5000 :DEBUG NIL :USE-THREAD NIL)
37: (CLACK:CLACKUP #<CLOSURE (LAMBDA (LAUNDRYBIN.MIDDLEWARE::ENV) :IN LAUNDRYBIN.MIDDLEWARE:EMPTY-BODY-FIXER-MIDDLEWARE) {27B3F975}> :PORT 5000 :SERVER :WOOKIE :DEBUG NIL :USE-THREAD NIL)
mtstickney commented 7 years ago

Looks like this was an issue with our application after all, and not part of wookie. After wading through the promise-related calls, I found one of our controllers was using return-from in a lambda improperly, which caused the error.

Apologies for the noise.

orthecreedence commented 7 years ago

No problem, glad you found it!