Subject: "make check-system" fails to report record-abi-mismatch-error

From: Chris Marusich <[email-masked]>
Date: Sat, 06 Oct 2018 00:19:12 -0700

Hi Guix,

On commit d71078bc75d149c70dc573a259986f1731145693, "make check-system"
failed for me with the following error message:

--8<---------------cut here---------------start------------->8---
[2] [env] [email-masked]:~/guix
$ make check-system
Compiling Scheme modules...
warning: failed to load '(gnu tests install)':
Backtrace:
           9 (apply-smob/1 #<catch-closure d998a0>)
In ice-9/boot-9.scm:
    705:2  8 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
In ice-9/eval.scm:
    619:8  7 (_ #(#(#<directory (guile-user) e24140>)))
    619:8  6 (_ #(#(#(#<directory (run-system-tests) e47aa0>) (#)) #))
   626:19  5 (_ #(#(#(#<directory (run-system-tests) e47aa0>) (#)) #))
In gnu/tests.scm:
   277:11  4 (all-system-tests)
   273:32  3 (fold-system-tests _ _)
In srfi/srfi-1.scm:
   697:23  2 (filter-map #<procedure 2e9da80 at guix/discovery.sc…> . #)
In guix/discovery.scm:
   113:22  1 (_ . _)
In unknown file:
           0 (display-error #f #<output: file /dev/pts/0> #<record-t…>)

ERROR: In procedure display-error:
Wrong number of arguments to #<procedure display-error (_ _ _ _ _ _)>
make: *** [Makefile:5454: check-system] Error 1
[2] [env] [email-masked]:~/guix
$ 
--8<---------------cut here---------------end--------------->8---

Although it wasn't obvious, this problem was actually caused by a
record-abi-mismatch-error.  When I deleted my $HOME/.cache/guile/ccache
directory, this error went away, and I was able to run the system tests.
However, it took some work to figure this out, since the error reporting
mechanism itself suffered an error.

To figure this out, I added some debug statements (see attached patch).
After I did that, "make check-system" failed with some more information:

--8<---------------cut here---------------start------------->8---
[2] [env] [email-masked]:~/guix
$ make check-system
Compiling Scheme modules...
XXX before

;;; (#<procedure warn-about-load-error (file args)>)

;;; ((gnu tests install))

;;; ((record-abi-mismatch-error #<record-type <openssh-configuration>>))

;;; ((record-abi-mismatch-error #<record-type <openssh-configuration>>))
warning: failed to load '(gnu tests install)':

;;; (#<output: file /dev/pts/0>)

;;; ((#<record-type <openssh-configuration>>))
Backtrace:
           9 (apply-smob/1 #<catch-closure cdc8a0>)
In ice-9/boot-9.scm:
    705:2  8 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
In ice-9/eval.scm:
    619:8  7 (_ #(#(#<directory (guile-user) d67140>)))
    619:8  6 (_ #(#(#(#<directory (run-system-tests) d8aaa0>) (#)) #))
   626:19  5 (_ #(#(#(#<directory (run-system-tests) d8aaa0>) (#)) #))
In gnu/tests.scm:
   277:11  4 (all-system-tests)
   273:32  3 (fold-system-tests _ _)
In srfi/srfi-1.scm:
   697:23  2 (filter-map #<procedure 2dd9a80 at guix/discovery.sc…> . #)
In guix/discovery.scm:
   114:22  1 (_ record-abi-mismatch-error #<record-type <openssh-con…>)
In unknown file:
           0 (display-error #f #<output: file /dev/pts/0> #<record-t…>)

ERROR: In procedure display-error:
Wrong number of arguments to #<procedure display-error (_ _ _ _ _ _)>
make: *** [Makefile:5454: check-system] Error 1
[2] [env] [email-masked]:~/guix
$ 
--8<---------------cut here---------------end--------------->8---

This output shows two problems.  The first problem is that an ABI
mismatch error was thrown.  The second problem is that display-error
encountered a problem while trying to display that error.

It's the second problem that I can't figure out.  Why does display-error
fail in this case?  For context, note that fold-system-tests in
gnu/tests.scm calls test-modules (in the same file), and that
test-modules calls scheme-modules with #:warn set to
warn-about-load-error.

The procedure warn-about-load-error is defined in guix/ui.scm.  It calls
display-error.  That seems to be where the problem occurs.  Based on the
debug output I added, we can see that in warn-about-load-error, the args
variable refers to the following list:

  (record-abi-mismatch-error #<record-type <openssh-configuration>>)

This is strange, since the only place that throws
record-abi-mismatch-error is in guix/records.scm...

--8<---------------cut here---------------start------------->8---
  (define (abi-check type cookie)
    "Return syntax that checks that the current \"application binary
interface\" (ABI) for TYPE is equal to COOKIE."
    (with-syntax ((current-abi (current-abi-identifier type)))
      #`(unless (eq? current-abi #,cookie)
          ;; The source file where this exception is thrown must be
          ;; recompiled.
          (throw 'record-abi-mismatch-error 'abi-check
                 "~a: record ABI mismatch; recompilation needed"
                 (list #,type) '()))))
--8<---------------cut here---------------end--------------->8---

...and based on that code, I expected the args variable to contain many
more elements.  I expected it to look more like this:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> (throw 'record-abi-mismatch-error 'abi-check
                 "~a: record ABI mismatch; recompilation needed"
                 (list 'some-type) '())
Throw to key `record-abi-mismatch-error' with args `(abi-check "~a: record ABI mismatch; recompilation needed" (some-type) ())'.

Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
scheme@(guile-user) [1]> 
--8<---------------cut here---------------end--------------->8---

I don't understand what happened to all the other arguments.  It looks
like the throw invocation in guix/records.scm was written carefully so
that it would throw exactly the arguments that display-error expects to
receive, but some of the arguments apparently went missing (e.g., the
"~a: record ABI mismatch; recompilation needed" message).  I can't
figure out why those arguments are missing.

How can I debug this further?  I'd like to fix this if possible so that
"make check-system" can reliably report errors like this.

Thank you in advance for your help!

-- 
Chris
From ac550495740ba4f8c87a9577145f6760a0ff00cd Mon Sep 17 00:00:00 2001
From: Chris Marusich <[email-masked]>
Date: Fri, 5 Oct 2018 23:39:57 -0700
Subject: [PATCH] Add some debug statements

---
 guix/discovery.scm | 4 +++-
 guix/ui.scm        | 4 ++--
 2 files changed, 5 insertions(+), 3 deletions(-)

diff --git a/guix/discovery.scm b/guix/discovery.scm
index 3fc6e2c9e..af428825e 100644
--- a/guix/discovery.scm
+++ b/guix/discovery.scm
@@ -110,7 +110,9 @@ name and the exception key and arguments."
                       (resolve-interface module))
                     (lambda args
                       ;; Report the error, but keep going.
-                      (warn module args)
+                      (display "XXX before\n")
+                      ((pk warn) (pk module) (pk args))
+                      (display "XXX after\n")
                       #f))))
               (scheme-files (if sub-directory
                                 (string-append directory "/" sub-directory)
diff --git a/guix/ui.scm b/guix/ui.scm
index 96f403acf..f28f80d4b 100644
--- a/guix/ui.scm
+++ b/guix/ui.scm
@@ -381,7 +381,7 @@ ARGS is the list of arguments received by the 'throw' handler."
 (define (warn-about-load-error file args)         ;FIXME: factorize with ↑
   "Report the failure to load FILE, a user-provided Scheme file, without
 exiting.  ARGS is the list of arguments received by the 'throw' handler."
-  (match args
+  (match (pk args)
     (('system-error . rest)
      (let ((err (system-error-errno args)))
        (warning (G_ "failed to load '~a': ~a~%") file (strerror err))))
@@ -398,7 +398,7 @@ exiting.  ARGS is the list of arguments received by the 'throw' handler."
                   file obj)))
     ((error args ...)
      (warning (G_ "failed to load '~a':~%") file)
-     (apply display-error #f (current-error-port) args))))
+     (apply display-error #f (pk (current-error-port)) (pk args)))))
 
 (define (call-with-unbound-variable-handling thunk)
   (define tag
-- 
2.18.0