Generating logging information using Racket

Question

Background:

I intend to generate debug messages for the code I'm developing. I wrote a macro to avoid writing the logging calls in each function. I know this limits the ability to generate more customized debug messages, but in return it isolates logging from code. And that is what I'm aiming for. This macro approach has other drawbacks too, for example it limits creation of function bindings to this macro only, but I think I can live with that.

Following is the definition of the macro and an example demonstrating its usage.

(define-syntax (define-func stx)
  (syntax-case stx ()
    [(define-func (func-name args ...) body1 body2 ...)
     (if (and (identifier? #'func-name)
              (andmap symbol? (syntax->datum #'(args ...))))
       (syntax (define (func-name args ...)
                 (log-debug (format "Function-name ~a:" (syntax-e #'func-name)) (list args ...))
                 body1
                 body2 ...))
       (raise-syntax-error 'define-func "not an identifier" stx))]
    [else (raise-syntax-error 'define-func "bad syntax" stx)]))



(define-func (last l)
  (cond [(null? l) null]
        [(null? (rest l)) (first l)]
        [else (last (rest l))]))


(define-func (main)
  (last (list 1 2 3 4 5 6 7 8 9))
  (logger))

log-debug and logger are defined in separate module

The output produced is somewhat like following:

Function-name last: 
args: 
:-> (7 8 9) 


Function-name last: 
args: 
:-> (8 9) 


Function-name last: 
args: 
:-> (9)

Now I want to make it more readable. By readability I mean to provide some kind of indentation so that the person reading the log could make sense of call flow. For example something like following:

Function-name last: 
args: 
:-> (7 8 9) 

    Function-name last: 
    args: 
    :-> (8 9) 

        Function-name last: 
        args: 
        :-> (9)

It is easier to figure out who called whom and so forth. I have an idea that can do this. It involves a variable that keeps track of indentation then after logging the function name I will increase the indent and after evaluation of body and before returning the value decrements the value. Something like following:

(define indent 0)

(define-syntax (define-func stx)
  (syntax-case stx ()
    [ (... ...)
      (...
      (log-debug ...)
      (increment indent)
      (let [(retval (body1 body2 ...)]
        (decrease indent)
        retval))]))

increment and decrease increases and decreases indentation respectively.

Problem:

It works even for function that returns void. I'm not sure whether its the correct behavior. In racket void is a special value, but I'm not sure that creating a binding to void is right way to go.

Is there any better way to achieve the same? If not are there any problems in this design? I'm open to any idea/change as long as they keep the logging and code separate.

thanks for the help!

What you describe seems similar to trace. But maybe it's not quite what you need. Or maybe you want to reinvent it for the value of learning more about macros. Just wanted to make sure you knew about it. — Greg Hendershott

Chris Jester-Young Chris Jester-Young · Accepted Answer · 2013-09-13T16:47:52

I have several suggestions for you:

It's probably better to use a parameter instead of a variable, for "global" stuff like your indentation level, since the original value is restored for you at the end of the parameterize expression.
All those raise-syntax-error checks you have in your macro are totally superfluous: syntax-case already provides guards (also known as fenders) that allow you to do any validation of macro "arguments" necessary:
```
(define-syntax (define-func stx)
  (syntax-case stx ()
    [(_ (func-name args ...) body1 body2 ...)
     (andmap identifier? (syntax->list #'(func-name args ...)))
     #'(define (func-name args ...)
         (log-debug (format "Function-name ~a:" 'func-name)
                    (list args ...))
         body1
         body2 ...)]))
```
I've also fixed up your code in several places, as you can see above:
1. I used (_ ...) instead of (define-func ...), since in syntax-case (unlike syntax-rules), the latter will actually bind a pattern variable called define-func, which will affect any recursive macro calls you may want to do (I'll grant that you don't have one here, but it's a good habit to have anyway).
2. Rather than completely flatten the #'(args ...) in the guard, I just turned it into a list of syntax objects so you can test using identifier?. This is more intention-revealing than testing using symbol?, and allows us to also test func-name in the same expression.
3. You don't need to use (syntax-e #'func-name) inside the expanded code! Just quote it.

Generating logging information using Racket

1 Answers