Verify-backtrace fails on BACKTRACE-INTERRUPTED-CONDITION-WAIT

[Chris Wagner]

Hi.

I compiled today Sbcl 1.1.9 on a Macbook (Mac OS/X 10.6.8). I selected the integration of the SB-Thread and SB-Core-Compression features beyond those selected by default. The local-target-features.lisp-expr contains:

((lambda (features) (set-difference features (list)))
 (union (list :sb-thread :sb-core-compression) (list :x86-64 :inode64 :darwin9-or-better :unix :mach-o :bsd :darwin :mach-exception-handler :ud2-breakpoints :gencgc :stack-grows-downward-not-upward :c-stack-is-control-stack :linkage-table :compare-and-swap-vops :unwind-to-frame-and-call-vop :raw-instance-init-vops :stack-allocatable-closures :stack-allocatable-vectors :stack-allocatable-lists :stack-allocatable-fixed-objects :alien-callbacks :cycle-counter :complex-float-vops :float-eql-vops :inline-constants :memory-barrier-vops :multiply-high-vops :sb-simd-pack :ash-right-vops :little-endian :os-provides-dlopen :os-provides-dladdr :os-provides-putwc :os-provides-blksize-t :os-provides-suseconds-t)))

Running the regression tests failed only on 2 test cases, one being the BACKTRACE-INTERRUPTED-CONDITION-WAIT case because:

$ (cd tests && sh ./run-tests.sh --break-on-failure debug.impure.lisp)

[...]
; caught 1 STYLE-WARNING condition
::: Running :BACKTRACE-INTERRUPTED-CONDITION-WAIT
//SB-THREAD:CONDITION-WAIT not in backtrace:
   (((FLET #:LAMBDA1 :IN VERIFY-BACKTRACE) #<SIMPLE-ERROR "foo" {1004FFDCC3}>)
    (SIGNAL #<SIMPLE-ERROR "foo" {1004FFDCC3}>) (ERROR "foo")
[...]
    due to #<SIMPLE-ERROR "~@<The assertion ~S failed~:[.~:; ~
                                    with ~:*~{~{~S = ~S~}~^, ~}.~]~:@>"
             {1005016343}>:
        "The assertion
         (VERIFY-BACKTRACE
          (LAMBDA ()
            (SB-THREAD:WITH-MUTEX (M)
              (HANDLER-BIND ((TIMEOUT (LAMBDA (C) (ERROR "foo"))))
                (WITH-TIMEOUT 0.1
                  (SB-THREAD:CONDITION-WAIT Q M)))))
          `((SB-THREAD:CONDITION-WAIT ,Q ,M :TIMEOUT NIL)))
         failed with
         (LAMBDA ()
           (SB-THREAD:WITH-MUTEX (M)
             (HANDLER-BIND ((TIMEOUT (LAMBDA (C) (ERROR "foo"))))
               (WITH-TIMEOUT 0.1
                 (SB-THREAD:CONDITION-WAIT Q M)))))
         = #<CLOSURE # {1004FFD86B}>,
         `((SB-THREAD:CONDITION-WAIT ,Q ,M :TIMEOUT NIL)) =
         ((SB-THREAD:CONDITION-WAIT #<SB-THREAD:WAITQUEUE {1004FFD833}>
                                    #<SB-THREAD:MUTEX (free) {1004FFD813}>
                                    :TIMEOUT NIL))."
[...]

Looking up on Launchpad for a condition similar to that referred to in debug.impure.lisp I found Bug #549673. I am however not sure whether this test case is a regression test for the fix to that bug.

In addition to the trace reported above I observed the following when I run this command:

 $ (cd tmp && sbcl --eval '(with-compilation-unit () (load "wait-cond"))' )

This is SBCL 1.1.9, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.

; file: /Users/christianwagner/src/Lisp/archs/sbcl-1.1.9/tmp/wait-cond.lisp
; in: LET ((M (SB-THREAD:MAKE-MUTEX)) (Q (SB-THREAD:MAKE-WAITQUEUE)))
; (HANDLER-BIND ((TIMEOUT (LAMBDA (C) (ERROR "foo"))))
; (WITH-TIMEOUT 0.1
; (SB-THREAD:CONDITION-WAIT Q M)))
; --> SB-IMPL::%HANDLER-BIND SB-INT:DX-FLET
; ==>
; (FLET ((#:LAMBDA0 (C)
; (ERROR "foo")))
; (DECLARE (SB-INT:TRULY-DYNAMIC-EXTENT (FUNCTION #:LAMBDA0)))
; (LET ((SB-KERNEL:*HANDLER-CLUSTERS* (CONS # SB-KERNEL:*HANDLER-CLUSTERS*)))
; (DECLARE (SB-INT:TRULY-DYNAMIC-EXTENT SB-KERNEL:*HANDLER-CLUSTERS*))
; (PROGN
; (PROGN
; (WITH-TIMEOUT 0.1
; #)))))
;
; caught STYLE-WARNING:
; The variable C is defined but never used.

debugger invoked on a SIMPLE-ERROR in thread
#<THREAD "main thread" RUNNING {1002B1B6C3}>:
  foo

Type HELP for debugger help, or (SB-EXT:EXIT) to exit from SBCL.

restarts (invokable by number or by possibly-abbreviated name):
  0: [RETRY ] Retry EVAL of current toplevel form.
  1: [CONTINUE] Ignore error and continue loading file "/Users/christianwagner/src/Lisp/archs/sbcl-1.1.9/tmp/wait-cond.lisp".
  2: [ABORT ] Abort loading file "/Users/christianwagner/src/Lisp/archs/sbcl-1.1.9/tmp/wait-cond.lisp".
  3: Ignore runtime option --eval "(with-compilation-unit () (load \"wait-cond\"))".
  4: Skip rest of --eval and --load options.
  5: Skip to toplevel READ/EVAL/PRINT loop.
  6: [EXIT ] Exit SBCL (calling #'EXIT, killing the process).

("bogus stack frame")
0]
WARNING: Starting a select(2) without a timeout while interrupts are disabled.
(list-backtrace)
; No debug variables for current frame: using EVAL instead of EVAL-IN-FRAME.
(("bogus stack frame")
 (SB-UNIX:NANOSLEEP #<unavailable argument> #<unavailable argument>)
 (SB-IMPL::%%WAIT-FOR
  #<dynamic-extent: #<CLOSURE (FLET SB-THREAD::WAKEUP :IN SB-THREAD:CONDITION-WAIT) {19FE8DB}>>
  NIL NIL)
 ((FLET #:WITHOUT-INTERRUPTS-BODY-549 :IN SB-THREAD:CONDITION-WAIT))
 (SB-THREAD:CONDITION-WAIT #<SB-THREAD:WAITQUEUE {1002C04F83}>
                           #<SB-THREAD:MUTEX (free) {1002C04F63}> :TIMEOUT NIL)
 ((FLET SB-THREAD::WITH-MUTEX-THUNK :IN "/Users/christianwagner/src/Lisp/archs/sbcl-1.1.9/tmp/wait-cond.lisp"))
 ((FLET #:WITHOUT-INTERRUPTS-BODY-535 :IN SB-THREAD::CALL-WITH-MUTEX))
 (SB-THREAD::CALL-WITH-MUTEX
  #<dynamic-extent: #<CLOSURE (FLET SB-THREAD::WITH-MUTEX-THUNK :IN "/Users/christianwagner/src/Lisp/archs/sbcl-1.1.9/tmp/wait-cond.lisp") {19FEF2B}>>
  #<SB-THREAD:MUTEX (free) {1002C04F63}> NIL T NIL)
 ((LAMBDA ()
    :IN
    "/Users/christianwagner/src/Lisp/archs/sbcl-1.1.9/tmp/wait-cond.lisp"))
 (SB-INT:SIMPLE-EVAL-IN-LEXENV
  (LET ((M (SB-THREAD:MAKE-MUTEX)) (Q (SB-THREAD:MAKE-WAITQUEUE)))
    (SB-THREAD:WITH-MUTEX (M)
      (HANDLER-BIND (#)
        (WITH-TIMEOUT 0.1
          #))))
  #<NULL-LEXENV>)
 (EVAL-TLF
  (LET ((M (SB-THREAD:MAKE-MUTEX)) (Q (SB-THREAD:MAKE-WAITQUEUE)))
    (SB-THREAD:WITH-MUTEX (M)
      (HANDLER-BIND (#)
        (WITH-TIMEOUT 0.1
          #))))
  0 #<NULL-LEXENV>)
 ((FLET SB-FASL::EVAL-FORM :IN SB-INT:LOAD-AS-SOURCE)
  (LET ((M (SB-THREAD:MAKE-MUTEX)) (Q (SB-THREAD:MAKE-WAITQUEUE)))
    (SB-THREAD:WITH-MUTEX (M)
      (HANDLER-BIND (#)
        (WITH-TIMEOUT 0.1
          #))))
  0)
 ...)
0]
WARNING: Starting a select(2) without a timeout while interrupts are disabled.

That is, I have to call (list-backtrace) to get the full trace which, incidentally, does contain a reference to the wait-condition. I'm not sure how this fits in with the comment left in debug.impure.lisp's verify-backtrace and the failing test case.

FYI, the code in cond-wait.lisp reads:

(let ((m (sb-thread:make-mutex))
      (q (sb-thread:make-waitqueue)))
  (sb-thread:with-mutex (m)
      (handler-bind ((timeout (lambda (c)
                                (error "foo"))))
      (with-timeout 0.1
         (sb-thread:condition-wait q m)))))

* Additional information *

uname -a:
Darwin christian-wagners-macbook-pro.local 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun 7 16:33:36 PDT 2011; root:xnu-1504.15.3~1/RELEASE_I386 i386

*features*:
(:ALIEN-CALLBACKS :ANSI-CL :ASH-RIGHT-VOPS :BSD :C-STACK-IS-CONTROL-STACK
 :COMMON-LISP :COMPARE-AND-SWAP-VOPS :COMPLEX-FLOAT-VOPS :CYCLE-COUNTER :DARWIN
 :DARWIN9-OR-BETTER :FLOAT-EQL-VOPS :GENCGC :IEEE-FLOATING-POINT
 :INLINE-CONSTANTS :INODE64 :LINKAGE-TABLE :LITTLE-ENDIAN
 :MACH-EXCEPTION-HANDLER :MACH-O :MEMORY-BARRIER-VOPS :MULTIPLY-HIGH-VOPS
 :OS-PROVIDES-BLKSIZE-T :OS-PROVIDES-DLADDR :OS-PROVIDES-DLOPEN
 :OS-PROVIDES-PUTWC :OS-PROVIDES-SUSECONDS-T :PACKAGE-LOCAL-NICKNAMES
 :RAW-INSTANCE-INIT-VOPS :SB-CORE-COMPRESSION :SB-DOC :SB-EVAL :SB-LDB
 :SB-PACKAGE-LOCKS :SB-SIMD-PACK :SB-SOURCE-LOCATIONS :SB-TEST :SB-THREAD
 :SB-UNICODE :SBCL :STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-FIXED-OBJECTS
 :STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-VECTORS
 :STACK-GROWS-DOWNWARD-NOT-UPWARD :UD2-BREAKPOINTS :UNIX
 :UNWIND-TO-FRAME-AND-CALL-VOP :X86-64)