Error messages need some imrovement

[Thomas Lynch]

These are exemplar problematical error messages from racket.  If messages like these were more specific it would save a lot of developer's time.  All of these have been solved, rather this is just feedback to developers.

1. this was hard to locate

rac...@misc-lib.rkt> (enter! "db-lib.rkt")
db-lib-init: unbound identifier in module
  in: db-lib-init
  context...:
   standard-module-name-resolver
   /usr/share/racket/collects/racket/rerequire.rkt:18:0: rerequire
   /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
   /usr/share/racket/collects/racket/private/misc.rkt:87:7

2. went away after running raco setup, but curious as to which variable was the problem

rac...@ap.rkt> (enter! "ap.rkt")
  [re-loading /home/deep/liquid-examples/test-ap/ap.rkt]
link: bad variable linkage;
 reference to a variable that is not a procedure or structure-type constant across all instantiations
  reference phase level: 0
  variable module: "/home/deep/liquid-lib/liquid/misc-lib.rkt"
  variable phase: 0
  reference in module: "/home/deep/liquid-lib/liquid/http-session.rkt"
  in: session-context-out
  context...:
   /home/deep/liquid-lib/liquid/http-session.rkt: [running body]
   /home/deep/liquid-examples/test-ap/ap.rkt: [traversing imports]
   /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
   /usr/share/racket/collects/racket/private/misc.rkt:87:7

3. obj:set! is a commonly used method in this code, would be nice to know which invocation.

  rac...@object.rkt> (enter! "node.rkt")
  obj:set!: arity mismatch;
   the expected number of arguments does not match the given number
    expected: 3
    given: 4
    arguments...:
     0
     9
     'field:debug
     "nd:type"
    context...:
     /home/deep/liquid-lib/liquid/node.rkt: [running body]
     /usr/share/racket/collects/racket/rerequire.rkt:18:0: rerequire
     /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
     /usr/share/racket/collects/racket/private/misc.rkt:87:7

4.  liquid.scrbl is the top file that includes all the sections..


      §lambda1:/home/deep/liquid-doc/liquid> raco setup --pkgs liquid-doc
      raco setup: version: 6.1 [3m]
      raco setup: installation name: 6.1
      raco setup: variants: 3m
      raco setup: main collects: /usr/share/racket/collects
      raco setup: collects paths:
      raco setup:   /home/mordecai/.racket/6.1/collects
      raco setup:   /usr/share/racket/collects
      raco setup: main pkgs: /usr/share/racket/pkgs
      raco setup: pkgs paths:
      raco setup:   /usr/share/racket/pkgs
      raco setup:   /home/mordecai/.racket/6.1/pkgs
      raco setup: links files:
      raco setup:   /usr/share/racket/links.rktd
      raco setup:   /home/mordecai/.racket/6.1/links.rktd
      raco setup: main docs: /usr/share/doc/racket
      raco setup: --- updating info-domain tables ---
      raco setup: --- pre-installing collections ---
      raco setup: --- installing foreign libraries ---
      raco setup: --- installing shared files ---
      raco setup: --- compiling collections ---
      raco setup: --- parallel build using 2 jobs ---
      raco setup: 1 making: <pkgs>/liquid-doc/compiled
      raco setup: 1 making: <pkgs>/liquid-doc/liquid
      raco setup: --- creating launchers ---
      raco setup: --- installing man pages ---
      raco setup: --- building documentation ---
      raco setup: 1 running: <pkgs>/liquid-doc/liquid/liquid.scrbl
      prog:3:0: read: expected a `)' to close `('
        possible cause: indentation suggests a missing `)' before line 7
        context...:
         /usr/share/racket/pkgs/scribble-lib/scribble/private/manual-code.rkt:56:0: typeset-code15
         /home/deep/liquid-doc/liquid/multiple-continuations-architecture.scrbl: [running body]
         /home/deep/liquid-doc/liquid/architecture.scrbl: [traversing imports]
         /home/deep/liquid-doc/liquid/liquid.scrbl: [traversing imports]
         /usr/share/racket/pkgs/racket-index/setup/scribble.rkt:895:0: load-doc/ensure-prefix
         /usr/share/racket/pkgs/racket-index/setup/scribble.rkt:1146:13
         /usr/share/racket/collects/setup/parallel-do.rkt:420:20: loop

  Turns out that it isn't in liquid.scrbl, it is in two include files down.  It is not
  on line 7, but was well into the file, and it wasn't part of the document structure, but
  it was in a quoted example ..  in multiple-continuations-architecture.scrbl:

      #lang scribble/manual
      @(require (for-label racket/base
                           ))              

      @title[#:style '(toc)]{Multiple Continuations Architecture}

      @section{The Basic Approach}

      As a matter of convention, we simplify function calls by not using variable arguments, but
      instead where variable arguments are required we use explicit lists.  We make this more
      convenient by introducing the Unicode capital lambda, Λ, as a synonym for @racket[list].
      In Emacs I have added both λ and Λ to my key map as alt-l  and alt-shift-l.

      Our basic approach is to pass continuation functions as arguments.  By convention the
      first function is the 'normal flow'.  By convention we call the first function
      continuation-ok.  For example, this is the definition for an extended hash ref that takes
      continuation functions.  It is implemented as a wrapper.  Of course it would be better to
      have a native version.

...


      @codeblock|{
        ...
        (define a 7)
        (x-hash-ref table a
          (λ(v) (display "found: ")(displayln v))
          (λ()  (displayln "did not find 7 ")  <---  scrble is mad this isn't balanced
          )
        ...
        }|

5.  ended up having to write a lot of special code for debugging this, the bug was not in
obj:add-type as indicated in the message, and certainly not on line 141.

  racket@> (enter! "object.rkt")
  ...
  (0.type-type)
  (obj:has-type 0 0)
  application: not a procedure;
   expected a procedure that can be applied to arguments
    given: 302
    arguments...:
     4
    context...:
     x-hash-ref
     /home/deep/liquid-lib/liquid/object.rkt:141:4: obj:add-type
     /home/deep/liquid-lib/liquid/object.rkt: [running body]
     /usr/share/racket/collects/racket/rerequire.rkt:18:0: rerequire
     /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
     /usr/share/racket/collects/racket/private/misc.rkt:87:7

6. but where?

  rac...@object.rkt> (obj-test-1)
  =: contract violation
    expected: number?
    given: #f
    argument position: 1st
    other arguments...:
     12
    context...:
     /usr/share/racket/collects/racket/private/misc.rkt:87:7


7. oh the cruelty of it! ;-)

  "object.rkt"> (obj-test-1)
  (4.type:summable)
  (5.test-1-obj1)
  (6.test-1-obj2)
  (args type:summable + (test-1-obj1 test-1-obj2))
  (conts #<procedure> #<procedure> #<procedure>)
  (##  at  (/home/deep/liquid-lib/liquid/object.rkt 221 4))
  (--  expected length of 3 )
  (--  for:  (#<procedure>))
  ; uncaught exception: 'exception:check [,bt for context]
  "object.rkt"> ,bt
  ; uncaught exception: 'exception:check
  "object.rkt">


8. you might think that a person could just look for the first summable in the module,
but no, as that one is well defined.  so I have to search for all 'summable' .. why
doesn't the compiler tell me which one?


  rac...@object.rkt> (enter! "object.rkt")
    [re-loading /home/deep/liquid-lib/liquid/object.rkt]
  summable: unbound identifier in module
    in: summable
    context...:
     /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
     /usr/share/racket/collects/racket/private/misc.rkt:87:7


9.  racket reports arity error, but does not say for which function ...  (turns out to be in obj:set! which I found
by walking through a trace).   line 421, which it cites, is simply the line of the define (obj-test-2) ...

  rac...@object.rkt> (obj-test-2)
  >(obj:make "type:summable")
  (47.type:summable)
  <47
  >(obj:make "test-2-obj1")
  (48.test-2-obj1)
  <48
  >(obj:make "test-2-obj2")
  (49.test-2-obj2)
  <49
  >(obj:add-type 48 47)
  > (obj:is 47)
  < #t
  > (obj:is 48)
  < #t
  > (obj:has-type 48 47)
  > >(obj:is 47)
  < <#t
  > (x-hash-ref
     '(#hasheq((47 . #hasheqv())
               (46 . #hasheqv((46 . #hasheqv())))
               (49 . #hasheqv())
               (48 . #hasheqv()))
       48)
     '(#<procedure> #<procedure>))
  > >(be #t)
  < <#<procedure:beit>
  > >(be #f)
  < <#<procedure:beit>
  > (x-hash-ref '(#hasheqv() 47) '(#<procedure:beit> #<procedure:beit>))
  < #f
  > (x-hash-ref
     '(#hasheq((47 . #hasheqv())
               (46 . #hasheqv((46 . #hasheqv())))
               (49 . #hasheqv())
               (48 . #hasheqv()))
       48)
     '(#<procedure> #<procedure>))
  < #<void>
  <48
  >(obj:add-type 49 47)
  > (obj:is 47)
  < #t
  > (obj:is 49)
  < #t
  > (obj:has-type 49 47)
  > >(obj:is 47)
  < <#t
  > (x-hash-ref
     '(#hasheq((47 . #hasheqv())
               (46 . #hasheqv((46 . #hasheqv())))
               (49 . #hasheqv())
               (48 . #hasheqv((47 . #hasheqv()))))
       49)
     '(#<procedure> #<procedure>))
  > >(be #t)
  < <#<procedure:beit>
  > >(be #f)
  < <#<procedure:beit>
  > (x-hash-ref '(#hasheqv() 47) '(#<procedure:beit> #<procedure:beit>))
  < #f
  > (x-hash-ref
     '(#hasheq((47 . #hasheqv())
               (46 . #hasheqv((46 . #hasheqv())))
               (49 . #hasheqv())
               (48 . #hasheqv((47 . #hasheqv()))))
       49)
     '(#<procedure> #<procedure>))
  < #<void>
  <49
  #<procedure>: arity mismatch;
   the expected number of arguments does not match the given number
    expected: 2
    given: 3
    arguments...:
     47
     49
     '(x 21)
    context...:
     /home/deep/liquid-lib/liquid/object.rkt:421:0: obj-test-2
     /usr/share/racket/collects/racket/private/misc.rkt:87:7
  rac...@object.rkt>

10.

  rac...@kw.rkt> (with-db (current-example-db) (db:alloc-name))
  lifted.0.3: undefined;
   cannot reference an identifier before its definition
    in module: "/home/deep/liquid-lib/liquid/kw.rkt"
    context...:
     /usr/share/racket/collects/racket/private/misc.rkt:87:7


  §lambda1:/home/deep/liquid-lib/liquid> grep lifted *.rkt

  §lambda1:/home/deep/liquid-lib/liquid>


11.

  rac...@kw.rkt> (enter! "kw.rkt")
    [re-loading /home/deep/liquid-lib/liquid/kw.rkt]
  _: wildcard not allowed as an expression
    in: _
  rac...@kw.rkt>


12.  doesn't tell which function the error came from, nor give a source line number

      line 851 is the entry point (semantic-relation:lookup-ids-test-1) , which doesn't
      take arguments, sort is called in multiple places ... which one?

    rac...@dataplex-lib.rkt> (semantic-relation:lookup-ids-test-1)
    <: contract violation
      expected: real?
      given: '(1 4 7 10)
      argument position: 1st
      other arguments...:
       '(1 7 10)
      context...:
       /usr/share/racket/collects/racket/private/sort.rkt:213:0: sort
       /home/deep/liquid-lib/liquid/dataplex-lib.rkt:851:4: semantic-relation:lookup-ids-test-1
       /usr/share/racket/collects/racket/private/misc.rkt:87:7
    rac...@dataplex-lib.rkt>

13. error is where in the function?

    rac...@kw.rkt>   (define (display-sm an-sm)
        (with-db (current-example-db)
          (let*(
                 [t0 (semantic-relation:match dp-ex1 R1 '_)] ; returns a list of rows, each row item is a singleton sp value
                 [t1  (map (λ(row)(map (λ(item)(car item)) row))  t0)] ; strips parens off of the singleton row items
                 )
            (map (λ(row)displayln(row)) t1) ;; <----- error on this line
            )))

    rac...@kw.rkt> (display-sm R1)
    application: not a procedure;
     expected a procedure that can be applied to arguments
      given: '("k1" "c1")
      arguments...: [none]
      context...:
       stdin::739: display-sm
       /usr/share/racket/collects/racket/private/misc.rkt:87:7
    rac...@kw.rkt> display-sm
    #<procedure:display-sm>


    and tried at the prompt, the error goes away:

    rac...@kw.rkt>   (define (display-sm an-sm)
        (with-db (current-example-db)
          (let*(
                 [t0 (semantic-relation:match dp-ex1 R1 '_)] ; returns a list of rows, each row item is a singleton sp value
      ;;           [t1  (map (λ(row)(map (λ(item)(car item)) row))  t0)] ; strips parens off of the singleton row items
                 [t1 '()]
                 )
            (map (λ(row)displayln(row)) t1)
            )))
    rac...@kw.rkt> (display-sm R1)
    '()
    rac...@kw.rkt> t0
    '((("k1") ("c1")) (("c2") ("c3")))
    rac...@kw.rkt> (map (λ(row)(map (λ(item)(car item)) row))  t0)
    '(("k1" "c1") ("c2" "c3"))
    rac...@kw.rkt> (define t1  (map (λ(row)(map (λ(item)(car item)) row))  t0))


14.  this identifier dosn't appear in this file ...  if it is created by a
     macro, then which macro?  which invocation of the macro?

    Process Racket REPL finished
    Welcome to Racket v6.1.
    racket@> (enter! "kw.rkt")
    shape-relation:values:index-by-sp-id: unbound identifier in module
      in: shape-relation:values:index-by-sp-id
    racket@>

15. turned out to be code generated by a syntax transformer, sure would have been helpful to have been
    told where it was called from, which macro, and where in the macro ...

    racket@> (enter! "extentions-lib.rkt")
    when: bad syntax
      in: (when else-flag)
      context...:
       standard-module-name-resolver
       /usr/share/racket/collects/racket/rerequire.rkt:18:0: rerequire
       /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
       /usr/share/racket/collects/racket/private/misc.rkt:87:7
    racket@>


16. ok ... so there is an error somewhere in the module having to do with redefining test-Λ-0


   rac...@sequence-lib.rkt> (enter! "sequence-lib.rkt")
     [re-loading /home/deep/liquid-lib/liquid/sequence-lib.rkt]
   (wrap test:  #f)
   (wrap test:  #f)
   (wrap test:  #f)
   hooking test: test-unwrap
   define-values: assignment disallowed;
    cannot re-define a constant
     constant: test-Λ-0
     in module: "/home/deep/liquid-lib/liquid/sequence-lib.rkt"
     context...:
      /home/deep/liquid-lib/liquid/sequence-lib.rkt: [running body]
      /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
      /usr/share/racket/collects/racket/private/misc.rkt:87:7


problem is, this is the only occurance of that identifier in the module:

  ;; does the job of list
  (define (test-Λ-0)
    (equal? '(1 2 3) (Λ 1 2 3))
    )
  (test-hook test-Λ-0)

17.  error is somewhere in extensions-lib.rkt, presumably in one of the many wrap calls,
will trace wrap .. oh, can't do that as this fails on load ..  line 157 in sequence-lib
and is first line of wrap, so there is no hint as to where in wrap this problem occurs (or
where wrap was called from).


    rac...@extentions-lib.rkt> (enter! "extentions-lib.rkt")
      [re-loading /home/deep/liquid-lib/liquid/extentions-lib.rkt]
    cdr: contract violation
      expected: pair?
      given: 'Λ
      context...:
       /home/deep/liquid-lib/liquid/sequence-lib.rkt:157:2
       /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
       /usr/share/racket/collects/racket/private/misc.rkt:87:7

... problem turned out to be in the cond/list program in extentions-lib.rkt, (define seq-op Λ) was supposed
to be (define seq-op 'Λ).   found by stubbing out the program and bring pieces to life one by one.

18. Not sure how we are supposed to know that this error occurs in http-server.rkt, as the
    top of the trace is the name of a macro in test lib.  Perhaps because it was the
    module loaded?  When finding the top of the trace, we discover in http-server.rkt,
    that the macro is only called once, so that narrows it down.  In other examples, a
    simple macro can be used many times.  Solving these is a real mystery thriller because
    it bombs on load, so you can't set traces.

    racket@> (enter! "http-server.rkt")
    string-append: contract violation
      expected: string?
      given: 'server-pages-init
      argument position: 1st
      other arguments...:
       "-trace"
      context...:
       /home/deep/liquid-extensions/liquid/test-lib.rkt:121:2
       /usr/share/racket/collects/syntax/wrap-modbeg.rkt:46:4
       standard-module-name-resolver
       standard-module-name-resolver
       /usr/share/racket/collects/racket/rerequire.rkt:18:0: rerequire
       /usr/share/racket/collects/racket/enter.rkt:54:0: dynamic-enter!6
       /usr/share/racket/collects/racket/private/misc.rkt:87:7
    racket@>

[Robby Findler]

Hi Thomas: you may wish to use errortrace to get more source locations
for error messages. It is enabled by default in DrRacket, but you have
to load it explicitly when you are working with the command-line
racket. Probably racket-mode has some support for it too, but I'm not
sure if it is turned on automatically there or not.

It isn't turned on by default for command-line racket because of the
fairly substantial performance penalty. But it isn't too bad if you
are just looking for a source location.

Here is an example of how one might use it.

☕ racket ~/tmp.rkt
<: contract violation
expected: real?
given: '(2 3)

argument position: 1st
other arguments...:

'(1 2)
context...:
/Users/robby/git/plt/racket/collects/racket/private/sort.rkt:213:0: sort
/Users/robby/tmp.rkt:2:0: f
/Users/robby/tmp.rkt: [running body]
☕ [robby@gongguan] ~
☕ racket -l errortrace -t ~/tmp.rkt
<: contract violation
expected: real?
given: '(2 3)

argument position: 1st
other arguments...:

'(1 2)
errortrace...:
/Users/robby/git/plt/racket/collects/racket/private/kw.rkt:1114:47:
(sort7 (quote #f) (quote #f) (quote #f) (quote #f) temp1 <2)
/Users/robby/tmp.rkt:3:2: (reverse (sort (quote ((1 2) (2 3) (3 ....))) <))
/Users/robby/tmp.rkt:7:0: (f 11)
context...:
/Users/robby/git/plt/racket/collects/racket/private/sort.rkt:213:0: sort
/Users/robby/tmp.rkt:2:0: f
/Users/robby/tmp.rkt: [running body]
☕ [robby@gongguan] ~
☕
☕ [robby@gongguan] ~
☕ cat ~/tmp.rkt
#lang racket
(define (f x)
(reverse
(sort '((1 2) (2 3) (3 4))
<)))

(f 11)


Robby

> --
> You received this message because you are subscribed to the Google Groups
> "Racket Developers" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to racket-dev+...@googlegroups.com.
> To post to this group, send email to racke...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/racket-dev/0996f438-af34-42a1-89e0-3d6c6df45149%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Greg Hendershott]

On Fri, Oct 30, 2015 at 7:55 AM, Robby Findler
<ro...@eecs.northwestern.edu> wrote:
> Hi Thomas: you may wish to use errortrace to get more source locations
> for error messages. It is enabled by default in DrRacket, but you have
> to load it explicitly when you are working with the command-line
> racket. Probably racket-mode has some support for it too, but I'm not
> sure if it is turned on automatically there or not.

In racket-mode for Emacs this is controlled by the
racket-error-context variable, which defaults to 'low. Setting it to
'high uses errortrace.

Also, you can have your cake and eat it, too. You can leave this set
to 'low; that's used when you C-c C-c to racket-run. But with a prefix
-- C-u C-c C-c -- it will run with errortrace. As a result, you can
use a lower level normally for speed. But if/when you get a vague
error message, you can re-run to get a better message.

More info:
https://github.com/greghendershott/racket-mode/blob/master/Reference.md#racket-error-context


Personally, I usually run with 'high / errortrace all the time. I did
however tweak the errortrace instrumentation to warn when I use `time`
or `time-apply` -- so that I don't make stupid performance claims on
the Racket mailing list. Er, I mean I added this for a friend who did
that once. :)

[Thomas Lynch]

ok, I've been waiting for one of these squirrelly ones to come up so I can try this error trace lib out. ..

I've done something wrong here. No trace.. Line 294 is just the first line of a macro definition, so no hint as to where it is used..   .. (Haha though it is just a typo, this one is obvious..)  

dash el errortrace right  .. racket -l errortrace

§lambda1:/home/deep/liquid-parser/liquid> racket -t producer.rkt

symbol->string: contract violation

  expected: symbol?

  given: "producer-type::a-simple-byte-producer"

  context...:

   /home/deep/TCA-object/liquid/object.rkt:294:4

   standard-module-name-resolver

§lambda1:/home/deep/liquid-parser/liquid> racket -l errortrace -t producer.rkt 

symbol->string: contract violation

  expected: symbol?

  given: "producer-type::a-simple-byte-producer"

  errortrace...:

  context...:

   /home/deep/TCA-object/liquid/object.rkt:294:4

   /usr/share/racket/pkgs/errortrace-lib/errortrace/errortrace-lib.rkt:434:2: errortrace-annotate

   /usr/share/racket/pkgs/errortrace-lib/errortrace/errortrace-lib.rkt:482:4

   standard-module-name-resolver

[Robby Findler]

Do you have .zo files compiled without errortrace turned on? If so, please throw them away and try again. 

Robby 

[Thomas Lynch]

Ah,  I don't think I have any .zo files.  Can they be located elsewhere than the pwd?  Here is a smaller example:

§lambda1:/home/deep/3_doc> tar -czf snap1.tgz snap1

§lambda1:/home/deep/3_doc> cd snap1

§lambda1:/home/deep/3_doc/snap1> ls
arith-lib.rkt  mc-lambda.rkt  sequence.rkt

§lambda1:/home/deep/3_doc/snap1> racket -l errortrace -t mc-lambda.rkt
moniker: unbound identifier in module
  in: moniker
  errortrace...:
  context...:

   /usr/share/racket/pkgs/errortrace-lib/errortrace/errortrace-lib.rkt:434:2: errortrace-annotate
   /usr/share/racket/pkgs/errortrace-lib/errortrace/errortrace-lib.rkt:482:4
   standard-module-name-resolver

A valid syntax transformer returns code with a function that is not available to the module, "moniker".  Here racket does not tell the name or where the syntax transformer is located,  it does not give the module or line where the expansion occurs. 

[Robby Findler]

The .zo files are generally located in the compiled/ subdirectory next
to the file you are running. You would get them if you run "raco make
mc-lambda.rkt", for example. And that was my guess with the previous
error, not the current one.

With this error, it looks like a macro is expanding into a free
variable and the source location information on the free variable
isn't available for some reason. One reason might be that the
identifier is synthesized by the macro, but the macro doesn't put any
source location into the variable. Here is an example program that has
that property:

#lang racket
(define-syntax (m stx)
(syntax-case stx ()
[(_ x)
(identifier? #'x)
(with-syntax ([x2 (datum->syntax
#'x
(string->symbol (format "~a2" (syntax-e #'x))))])
#'x2)]))

(let ([x 1])
(m x))

This one can be fixed by making the transformer pick a source location
for the identifier that is in the macro itself like this:

#lang racket
(define-syntax (m stx)
(syntax-case stx ()
[(_ x)
(identifier? #'x)
(with-syntax ([x2 (datum->syntax
#'x
(string->symbol (format "~a2" (syntax-e #'x)))
#'here)])
#'x2)]))

(let ([x 1])
(m x))

Or it may make more sense to pick a source location from the input to
the macro like this:

#lang racket
(define-syntax (m stx)
(syntax-case stx ()
[(_ x)
(identifier? #'x)
(with-syntax ([x2 (datum->syntax
#'x
(string->symbol (format "~a2" (syntax-e #'x)))
stx)])
#'x2)]))

(let ([x 1])
(m x))


Robby

[Thomas Lynch]

It is not the very nature of errors that we do not expect them, and do not predict them with specificity, so it is incumbant upon racket to give location infomration with errors, rather than for the programmer to do so?  Or am I missing something here?

Here is another example:

   §lambda1:/home/deep/3_doc/snap-p> racket -l errortrace -t producer.rkt
   in: unbound identifier in module
     in: in
     errortrace...:

   §lambda1:/home/deep/3_doc/snap-p>

Very little information to go by here, and 'in' was not a variable in said module.  Turned out to be a typo. 

Does every identifier in a syntax transformer have to be handled as you show above for error tracing to work, and what if there are errors in the extra code, what locates those?

[Greg Hendershott]

On Thu, Nov 12, 2015 at 6:02 PM, Thomas Lynch
<thomas...@reasoningtechnology.com> wrote:
> It is not the very nature of errors that we do not expect them, and do not
> predict them with specificity, so it is incumbant upon racket to give
> location infomration with errors, rather than for the programmer to do so?
> Or am I missing something here?

I think you're missing where you discard the location information
Racket gives you? :)

Following Robby's cue and glancing at your `provide-with-trace` macro
in test-lib.rkt, it seems like that's the source (no pun intended) of
this? View-from-orbit it seems to be:

(define-syntax (provide-with-trace stx)
(datum->syntax
(manipulate-stuff-as-raw-s-expression
(syntax->datum stx)))

This will "slice off" all the interesting source location information
from the original syntax, `stx`. (Unlike some other lisps, Racket
syntax transformers get not just the s-expression datum, but full
syntax objects -- which also include information about things like
source location and lexical scope.)


I think it would be easier If you instead use `syntax-case` or
`syntax-parse` in the usual way -- supplying a `#'` a.k.a. `syntax`
template that uses pieces of the original syntax from the pattern.
Most likely it will preserve all the source info you want,
automatically.


As a quick experiment, change it to a do-nothing "identity" macro that
returns the original, full syntax-object as-is:

(define-syntax (provide-with-trace stx)
stx)

And see if this (plus errortrace) gives you good-enough error
messages. (This assumes you can still run your program OK without the
extra tracing stuff defined.)

If it does, then you could look into rewriting the macro in the
"normal" way to preserve syntax object info.

[Thomas Lynch]

Ok then, here are two simple examples of error traces.

In both examples we have the trace from common LISP and from racket. 

In the first example I use a syntax proceedure as described in the guide 16.2.2 and as
shows up in my code.  In this example both traces match.  I did not have to use
syntax-case to get a trace.

In the second example common lisp gives a correct trace, but racket leaves a function
out of the trace back.  Not a macro, a function.  I show the macro involved implemented
in all three ways described in the guide, as a proceedure as per the first example, as
a syntax rule, and, yes, using syntax-case.  In all three cases it appears that
racket leaves a function out of the trace, though common LISP does not.

In any case, functions missing from the trace are confusing to developers, as one
looks in the wrong place for the erros.

Well hope I got these examples right anyway.  Apologies in advance if there is
an error in here.  I hope you will point out where it is. ;-)


--------------------------------------------------------------------------------
1.1 in common LISP (gcl), error manifesting in well formed macro

  bt-example.gcl:
    (defmacro plus (x y) `(+ ,x ,y))
    (defun f (x y) (g x y))
    (defun g (x y) (plus x y))


      >(load "bt-example.gcl")

      Loading bt-example.gcl
      Finished loading bt-example.gcl
      T

      >(f 3 2)

      5

      >(f 3 'a)

      Error: TYPE-ERROR :DATUM A :EXPECTED-TYPE NUMBER
      Fast links are on: do (si::use-fast-links nil) for debugging
      Signalled by +.
      TYPE-ERROR :DATUM A :EXPECTED-TYPE NUMBER

      Broken at +.  Type :H for Help.
          1  Return to top level.
      >>:bt

      #0   + {loc0=3,loc1=a,loc2=type-error,loc3=nil,loc4=+,loc5="",loc6="",loc7=:datum,loc8=...} [ihs=6]
      #1   G {} [ihs=5]
      #2   F {} [ihs=4]
      #3   EVAL {loc0=nil,loc1=nil,loc2=nil,loc3=(system:lambda-block f (x y) ...),loc4=3,loc5=a} [ihs=3]
      NIL
      >>

  Ok, so it gives a back trace to the function that called the macro, and then to the
  expanded function that had the error. All functions are mentioned, but the macro is not.

1.2. Same example in racket.

  bt-example.rkt

    #lang racket
    (define-syntax (plus stx)
      (let(
            [datum (syntax->datum stx)]
            )
        (let(
              [x (cadr datum)]
              [y (caddr datum)]
              )
          (define program `(+ ,x ,y))
          (datum->syntax stx program)
          )))
    (define (f x y) (g x y))
    (define (g x y) (plus x y))

    (f 3 2)
    (f 3 'a)

    §> racket -l errortrace -t "bt-example.rkt"
    5
    +: contract violation
      expected: number?
      given: 'a
      argument position: 2nd
      other arguments...:
       3
      errortrace...:
       /home/deep/3_doc/racket_err_mess/bt-example.rkt:15:16: (g x y)
       /home/deep/3_doc/racket_err_mess/bt-example.rkt:19:0: (f 3 (quote a))
      context...:
       /home/deep/3_doc/racket_err_mess/bt-example.rkt:15:0: f
       /home/deep/3_doc/racket_err_mess/bt-example.rkt: [running body]

    §>

  Similar result as per gcl.  All functions mentioned, no mention of the
  syntax transformer.

--------------------------------------------------------------------------------
2.1 in common LISP, this time the well formed macro calls a well formed function,
where an error manifests:

  bt2-example.gcl:
    (defun h (x y) (+ x y))
    (defmacro plus (x y) `(h ,x ,y))
    (defun f (x y) (g x y))
    (defun g (x y) (plus x y))

    >(load "bt2-example.gcl")

    Loading bt2-example.gcl
    Finished loading bt2-example.gcl
    T

    >(f 3 2)

    5

    >(f 3 'a)

    Error: TYPE-ERROR :DATUM A :EXPECTED-TYPE NUMBER
    Fast links are on: do (si::use-fast-links nil) for debugging
    Signalled by +.
    TYPE-ERROR :DATUM A :EXPECTED-TYPE NUMBER

    Broken at +.  Type :H for Help.
        1  Return to top level.
    >>:bt

    #0   + {loc0=3,loc1=a,loc2=type-error,loc3=nil,loc4=+,loc5="",loc6="",loc7=:datum,loc8=...} [ihs=7]
    #1   H {} [ihs=6]
    #2   G {} [ihs=5]
    #3   F {} [ihs=4]
    #4   EVAL {loc0=nil,loc1=nil,loc2=nil,loc3=(system:lambda-block f (x y) ...),loc4=3,loc5=a} [ihs=3]
    NIL
    >>

 All functions cited.  F->G->H->+ then blam. The macro is not cited.


2.1 now in racket

  bt2-example.rkt
    #lang racket
    (define (h x y) (+ x y))
    (define-syntax (plus stx)
      (let(
            [datum (syntax->datum stx)]
            )
        (let(
              [x (cadr datum)]
              [y (caddr datum)]
              )
          (define program `(h ,x ,y))
          (datum->syntax stx program)
          )))
    (define (f x y) (g x y))
    (define (g x y) (plus x y))
    (f 3 2)
    (f 3 'a)

  §> racket -l errortrace -t bt2-example.rkt
  5
  +: contract violation
    expected: number?
    given: 'a
    argument position: 2nd
    other arguments...:
     3
    errortrace...:
     /home/deep/3_doc/racket_err_mess/bt2-example.rkt:3:16: (+ x y)
     /home/deep/3_doc/racket_err_mess/bt2-example.rkt:21:0: (f 3 (quote a))
    context...:
     /home/deep/3_doc/racket_err_mess/bt2-example.rkt:3:0: h
     /home/deep/3_doc/racket_err_mess/bt2-example.rkt: [running body]

  §>

  f -> + and blam .. and nice to know + is inside of 'h'.  ah .. but what happened to g?
  Is leaving g out of the trace an error?  Because when I go looking for an invocation
  of 'h' (or '+') inside of 'f', but in fact it is inside of 'g'.

2.2 racket using syntax rules, same result, no mention of g in the trace

  bt2-ex-rules.rkt:
    (define (h x y) (+ x y))

    (define-syntax plus
      (syntax-rules()
        [(plus x y) (h x y)]
        ))


    (define (f x y) (g x y))
    (define (g x y) (plus x y))

    (f 3 2)
    (f 3 'a)

  racket -l errortrace -t bt2-ex-rules.rkt
    5
    +: contract violation
      expected: number?
      given: 'a
      argument position: 2nd
      other arguments...:
       3
      errortrace...:
       /home/deep/3_doc/racket_err_mess/bt2-ex-rules.rkt:3:16: (+ x y)
       /home/deep/3_doc/racket_err_mess/bt2-ex-rules.rkt:15:0: (f 3 (quote a))
      context...:
       /home/deep/3_doc/racket_err_mess/bt2-ex-rules.rkt:3:0: h
       /home/deep/3_doc/racket_err_mess/bt2-ex-rules.rkt: [running body]

2.3 racket using syntax case, same result, no mention of g in the trace:
 
  bt2-ex-case.rkt:
    #lang racket

    (define (h x y) (+ x y))

    (define-syntax (plus stx)
      (syntax-case stx ()
        [(plus x y) #'(h x y)]
        ))


    (define (f x y) (g x y))
    (define (g x y) (plus x y))

    (f 3 2)
    (f 3 'a)

  §> racket -l errortrace -t bt2-ex-case.rkt
  5
  +: contract violation
    expected: number?
    given: 'a
    argument position: 2nd
    other arguments...:
     3
    errortrace...:
     /home/deep/3_doc/racket_err_mess/bt2-ex-case.rkt:3:16: (+ x y)
     /home/deep/3_doc/racket_err_mess/bt2-ex-case.rkt:15:0: (f 3 (quote a))
    context...:
     /home/deep/3_doc/racket_err_mess/bt2-ex-case.rkt:3:0: h
     /home/deep/3_doc/racket_err_mess/bt2-ex-case.rkt: [running body]