[hunchentoot-devel] Strange condition during error handling (possible double error?)

Sat May 10 20:53:34 UTC 2008

Hi.

For my development I've tried to setup hunchentoot error
logging/condition handling that better suits taste. Here's my setup
(code snippets to reduce word clutter):

(setf hunchentoot:*catch-errors-p* nil
          hunchentoot::*log-lisp-backtraces-p* t
          hunchentoot::*log-lisp-errors-p* t
          hunchentoot::*log-lisp-warnings-p* t
          hunchentoot::*show-lisp-errors-p* t
          hunchentoot::*show-lisp-backtraces-p* t)

(defgeneric maybe-log-condition (condition)
  (:documentation
   "This generic function is called whenever a
condition CONDITION is about to be logged in an application. You might want to
specialize it on specific condition classes to fine-tune error and
warning logging
in addition to Hunchentoot's *log-lisp-errors-p* and *log-lisp-warnings-p*.")
  (:method (condition) t))

(defmethod log-message :around (log-level fmt &rest args)
  (let ((*log-level* log-level)
        (*fmt* fmt)
        (condition (and args (car args))))
    (declare (special *log-level* *fmt*))
    (cond ((and condition (typep condition 'condition))
           (when (maybe-log-condition condition)
             (call-next-method)))
          (t (call-next-method)))))

(defmethod maybe-invoke-debugger ((condition
sb-int:simple-stream-error)) ; muffle useless condition reporting
  (cond ((eql (search "/img/" (script-name *request*)) 0)
         (log-message :warn "ignored condition for ~a: ~a"
(script-name *request*) condition))
        (t (call-next-method))))

(defmethod maybe-log-condition ((condition sb-int:simple-stream-error)) nil)

It's rather crude workaround for something that should probably be
more tightly integrated into hunchentoot (customizable error/warning
logging similar to maybe-invoke-debugger). Notice
maybe-invoke-debugger specialized for sb-int:simple-stream-error. I've
put that in my development setup because I've tried to silence Firefox
related errors, which has nasty habit of dropping connection on
favicon.ico retrieval (well, that's what I suspect; haven't check that
theory with packet sniffer) that results in "Broken pipe" condition.

So far all fine and dandy. But, for every such condition handled by my
code hunchentoot logs following line:

[2008-05-10 11:41:42 [ERROR]] Error while processing connection: The
variable *REQUEST* is unbound.

No more information available. So I've modified hunchentoot a little bit:

diff -x '*.fasl' -r -u -w -B hunchentoot-0.15.6.orig/server.lisp
hunchentoot-0.15.6/server.lisp

--- hunchentoot-0.15.6.orig/server.lisp 2008-04-09 10:17:48.000000000 +0200
+++ hunchentoot-0.15.6/server.lisp      2008-04-21 22:25:33.000000000 +0200
@@ -282,6 +282,7 @@
                   (lambda (cond)
                     (log-message *lisp-errors-log-level*
                                  "Error while processing connection: ~A" cond)
+                    (log-message *lisp-errors-log-level* "~a"
(get-backtrace cond))
                     (return-from process-connection)))
                  (warning
                   ;; log all warnings which aren't caught inside

and got following:

[2008-05-10 11:41:42 [ERROR]] Error while processing connection: The
variable *REQUEST* is unbound.
[2008-05-10 11:41:43 [ERROR]] 0: (SB-DEBUG::MAP-BACKTRACE #<CLOSURE
(LAMBDA #) {AF6C86D}>)[:EXTERNAL]
1: (SB-DEBUG:BACKTRACE 536870911 #<SB-IMPL::STRING-OUTPUT-STREAM {AF6C809}>)
2: (GET-BACKTRACE #<unused argument>)
3: ((LAMBDA (COND)) #<UNBOUND-VARIABLE *REQUEST* {A793961}>)
4: ((LAMBDA (COND)) #<UNBOUND-VARIABLE *REQUEST* {A793961}>)[:EXTERNAL]
5: (SIGNAL #<UNBOUND-VARIABLE *REQUEST* {A793961}>)[:EXTERNAL]
6: (ERROR UNBOUND-VARIABLE)[:EXTERNAL]
7: (SB-KERNEL::UNBOUND-SYMBOL-ERROR-HANDLER
    #<unavailable argument>
    #.(SB-SYS:INT-SAP #XB51C1DF0)
    #<SB-ALIEN-INTERNALS:ALIEN-VALUE :SAP #XB51C1A7C :TYPE (*
                                                            (SB-ALIEN:STRUCT

SB-VM::OS-CONTEXT-T-STRUCT))>
    (14))
8: (SB-KERNEL::UNBOUND-SYMBOL-ERROR-HANDLER
    #<unavailable argument>
    #.(SB-SYS:INT-SAP #XB51C1DF0)
    #<SB-ALIEN-INTERNALS:ALIEN-VALUE :SAP #XB51C1A7C :TYPE (*
                                                            (SB-ALIEN:STRUCT

SB-VM::OS-CONTEXT-T-STRUCT))>
    (14))[:EXTERNAL]
9: (SB-KERNEL:INTERNAL-ERROR
    #.(SB-SYS:INT-SAP #XB51C1A7C)
    #<unavailable argument>)
10: ("foreign function: call_into_lisp")
11: ("foreign function: funcall2")
12: ("foreign function: interrupt_internal_error")
13: ("foreign function: handle_trap")
14: ((SB-PCL::FAST-METHOD MAYBE-INVOKE-DEBUGGER (SB-INT:SIMPLE-STREAM-ERROR))
     #<unused argument>
     #S(SB-PCL::FAST-METHOD-CALL
        :FUNCTION #<FUNCTION #>
        :PV NIL
        :NEXT-METHOD-CALL NIL
        :ARG-INFO (1))
     #<SB-INT:SIMPLE-STREAM-ERROR {A78E219}>)
15: (SIGNAL #<SB-INT:SIMPLE-STREAM-ERROR {A78E219}>)[:EXTERNAL]
16: (ERROR SB-INT:SIMPLE-STREAM-ERROR)[:EXTERNAL]
17: (SB-IMPL::SIMPLE-STREAM-PERROR
     "Couldn't write to ~s"
     #<SB-SYS:FD-STREAM for "a socket" {B123609}>
     32)
18: (SB-IMPL::SIMPLE-STREAM-PERROR
     "Couldn't write to ~s"
     #<SB-SYS:FD-STREAM for "a socket" {B123609}>
     32)[:EXTERNAL]
19: (FORCE-OUTPUT #<SB-SYS:FD-STREAM for "a socket" {B123609}>)
20: ((SB-PCL::FAST-METHOD SB-GRAY:STREAM-FORCE-OUTPUT
      (CHUNGA:CHUNKED-OUTPUT-STREAM))
     #<unused argument>
     #<unused argument>
     #<CHUNGA:CHUNKED-IO-STREAM {B127C49}>)
21: (FORCE-OUTPUT #<CHUNGA:CHUNKED-IO-STREAM {B127C49}>)
22: (FORCE-OUTPUT #<FLEXI-STREAMS::FLEXI-UTF-8-IO-STREAM {B12A4E9}>)
23: (HUNCHENTOOT::PROCESS-CONNECTION
     #<HUNCHENTOOT::SERVER {B3C6FB1}>
     #<SB-BSD-SOCKETS:INET-SOCKET descriptor 11 {B121819}>)
24: ((LAMBDA ()))
25: ((FLET SB-THREAD::WITH-MUTEX-THUNK))
26: ((FLET #:WITHOUT-INTERRUPTS-BODY-[CALL-WITH-MUTEX]438))
27: (SB-THREAD::CALL-WITH-MUTEX
     #<CLOSURE (FLET SB-THREAD::WITH-MUTEX-THUNK) {B51C2295}>
     #S(SB-THREAD:MUTEX
        :NAME "thread result lock"
        :%OWNER #<SB-THREAD:THREAD "hunchentoot-worker-2" {B1225D9}>
        :STATE 1)
     #<SB-THREAD:THREAD "hunchentoot-worker-2" {B1225D9}>
     T)
28: ((LAMBDA ()))
29: ("foreign function: call_into_lisp")
30: ("foreign function: funcall0")
31: ("foreign function: new_thread_trampoline")
32: ("foreign function: #xB7FD2240")

Looking at the above backtrace and process-connection source code I
wasn't able to figure out anything constructive. I'm stuck. It looks
for me like double error (error during error handling), but what do I
know? Can someone tell me what am I doing wrong? Can I avoid this "The
variable *REQUEST* is unbound." error? Is this hunchentoot error or my
silly mistake? Take into account that these are my first 40 or so
hours with CL (not even mentioning Hunchentoot).

I'm using SBCL 1.0.15 and Hunchentoot 0.15.6.

Thanks

Tomasz

