New module log-bracketed; should probably be something else

[David Storrs]

I often find that for debugging I want to see a log message saying "I'm about to do X" followed by X followed by "I'm done with X" and I want it to return the result of X.

I wrote this macro and posted it to the package server:  https://pkgs.racket-lang.org/package/log-bracketed

In retrospect, the syntax is bad and I should change it.  Can anyone suggest something better?

  (define (on-complete x) (log-test-debug "entering on-complete") x)
  (struct person (name) #:transparent)

  (log-bracketed test-debug "on-complete" "time: ~a" (current-seconds) (on-complete (person 'bob)))
  (log-bracketed test-debug "on-complete" "" "no user-specified logging information")

Spits out:

test: about to on-complete. time: 1630611613
test: entering on-complete
test: after on-complete. time: 1630611613. result: (person 'bob)
(person 'bob)
test: about to on-complete
test: after on-complete. result: "no user-specified logging information"
"no user-specified logging information"

The problem is that this looks like it's a simple logging message when in fact it's real code that should not be ignored.  I'm trying to think of a better way to do it...maybe something like this?:

  (with-bracketing-logs ([test-debug "on-complete" "time: ~a" (current-seconds)])

     (on-complete (person 'bob))

[Martin DeMello]

I do like the second form better, especially since the actual code being run is not obscured by simply being the last argument to a long log function.

martin

--
You received this message because you are subscribed to the Google Groups "Racket Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to racket-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/racket-users/CAE8gKocZha-NpiFAAKT1c8QTG3MDFRnvxCD4T0P269EncZW3KQ%40mail.gmail.com.

[Sorawee Porncharoenwase]

Thoughts:

• Perhaps the logger should be optional. The default value would be (current-logger).
• The event name (like on-complete) could also be optional. The default would be the source location of the macro invocation site
• Instead of “time: ~a”, I think it would be nice to support many “pairs”, which are formatted like raise-arguments-error.

Example:

(define (on-complete x)
  (log-test-debug "I'm in on-complete")
  x)

(with-log ()
  1)

(with-log (#:logger test-debug
           #:msg "on-complete"
           ["time" (current-seconds)])
  (on-complete (person 'bob)))

would output:

test: entering test.rkt:5:1
test: exiting test.rkt:5:1
        result: 1
1
test: entering on-complete
        time: 123
test: I'm in on-complete
test: exiting on-complete
        time: 124
        result: (person 'bob)
(person 'bob)

To view this discussion on the web visit https://groups.google.com/d/msgid/racket-users/CAFrFfuEqt1NVjE2Ft1JVArvWnKUBvK7jPVoLqPhYCd-dB00A3Q%40mail.gmail.com.

[David Storrs]

First of all, thank you.  I like the idea of the event name being optional and the logger defaulting but I'm not keen on the syntax.  It's very verbose for something that might occasionally be wrapped around a single line of code. The raise-arguments-error formatting would be a nice default but I prefer to give the option to use a format string if you want something different.

On Thu, Sep 2, 2021 at 2:06 PM Martin DeMello <martin...@gmail.com> wrote:

I do like the second form better, especially since the actual code being run is not obscured by simply being the last argument to a long log function.

Cool.  I'll move towards that.

[jackh...@gmail.com]

This looks quite a bit like you're trying to implement tracing, which is like logging, but instead of emitting messages associated with points in time, you emit messages for ranges of time. Rust has an excellent library for tracing. Perhaps that will provide some good inspiration?