parameterized logging

[Sean Kanaley]

Hi all,

Is there a way to automatically send say a prefix string with many already coded logger invocations?

For example, to go from:

------------------------------------

(thread

...

(log-debug "information specific to particular thread, without mention of which thread"))

------------------------------------

to:

------------------------------------

(thread

...

(parameterize ([current-logger-prefix "thread identifier"])

...

(log-debug "information specific to particular thread, without mention of which thread")))

------------------------------------

where the latter log-debug is defined to do (format "~a: ~a" (current-logger-prefix) message).

Since the receiver is in a different thread, directly coding a receiver to use the parameter won't work. And since it's asynchronous, relying on globals won't work.

The use case if somebody has a different idea altogether is a webserver supporting multitenancy. The request handler for tenant "X" should log as "X: <original log string>".

It looks like this would be easy to add to racket/private/logger if there's no way short of mass refactoring, so it's not hopeless.

[Neil Van Dyke]

I was just now coding something similar (to add info like
`port-next-location` to errors and warning logging).  Ideas:

1. If changing the module with the logging forms is practical, and you
just don't want the changes to be too messy, you could make syntax that
expands to the logging syntax:

(define-logger somemodule)
(define-syntax log-somemodule-debug/foo
  (log-with-foo-syntax log-somemodule-debug))
;;...
(log-somemodule-debug/foo "aaa ~S" bbb)
;;=expand=>
(log-somemodule-debug "~S: aaa ~S" (current-foo) bbb)
;; current-foo is a parameter within your thread.
;; if the format string wasn't a literal, expand would use string-append.

2. I don't know offhand whether this works, and I'm not sure of the
overhead: using `current-logger` and `make-logger` (with its topic
argument for your thread ID), something like:

(define (my-thread-proc foo)
  (parameterize ((current-logger (make-logger foo
                                              (current-logger)
                                              ...OTHER...)))
    ...THREAD-BEHAVIOR...))

3. There's now a `with-intercepted-logging` form, which might let you do
what you want.

[Sean Kanaley]

Thanks, Neil. Unfortunately #2 didn't work. The historically written define-logger calls like log-something-debug overwrites the "foo" topic with "something". If only they were appended together. #3 can't intercept logs of define-logger loggers (if a woodchuck could...) even with topic/level hardcoded because the #:logger keyword is also needed. So it seems like the usage would be a series of nested with-intercepted-loggings, one for each define-logger. Lastly, #1 is what I'm trying to avoid :)

To be fair, either #1 or #3 is fully *practical*, but the Racketeer in me would prefer to fully automate this. The "proper" solution seems to require a Racket change.

Is #3 a bug? Or I might be getting confused at the timing with the define-logger = current-logger being used to write the log and the interceptor reverting to the previous logger, but the code that seems like it should work here:

#lang racket/base

(require racket/logging)

(define-logger x)

;works, no define-logger topic though

(let ([thread-id "hurray"])

  (with-intercepted-logging

      (λ (v)

        (printf "~a: ~a~n" thread-id (vector-ref v 1)))

    (λ ()

      (log-debug "we interrupt this program to bring you this important message"))

    'debug))

;doesn't work

(let ([thread-id "hurray"])

  (with-intercepted-logging

      (λ (v)

        (printf "~a: ~a~n" thread-id (vector-ref v 1)))

    (λ ()

      (log-x-debug "we interrupt this program to bring you this important message"))

    'debug))

;works but messy for many define-loggers

(let ([thread-id "hurray"])

  (with-intercepted-logging

      #:logger x-logger

      (λ (v)

        (printf "~a: ~a~n" thread-id (vector-ref v 1)))

    (λ ()

      (log-x-debug "we interrupt this program to bring you this important message"))

    'debug))

[David Storrs]

I realize it's not ideal Racket, but I've gotten a lot of mileage out of the following:

;;----------------------------------------------------------------------                       

(define prefix-for-say (make-parameter ""))

(define-syntax (say stx)
  (syntax-case stx ()
    [(say a ...)
     #'(displayln (~a (prefix-for-say) a ...))]
    ))

(define-syntax (__WHERE:__ stx) ; Note the ':'             

  (with-syntax ((fpath (syntax-source stx))
                (line  (syntax-line stx)))
    (syntax-case stx ()
      [_ #'(~a "file:" fpath " (line:" line "): ")])))

;;----------------------------------------------------------------------                       

I then sprinkle my code with:

(say __WHERE:__ "the thing was: " thing ", and it had " num-owners " owners)

which gets me output like:

file:/Users/dstorrs/some/path/to/file.rkt (line:131): the thing was: <thing>, and it had 7 owners

For threading, I have this:

(define/contract (threaded thnk)
  (-> (-> any) any)

  (define current-prefix (prefix-for-say))

  (define thread-label
    (cond [(empty-string? current-prefix) (~a (rand-val "thread") ": ")]
          [else (~a (rand-val "thread") " / " current-prefix)]))

  (parameterize ([prefix-for-say thread-label])
    (thread (thunk (begin0 (thnk) (sleep 0)))))) ; sleep 0 suggests that the thread run now                   

(define (foo x)  (threaded (thunk (bar x))))

(define (bar x)  (threaded (thunk (say x))))

(foo "hello, world")

And I get output like this:

thread-261855 / thread-861893: hello, world

There are improvements that I could make to this -- for example, make 'threaded' a macro so you don't need to pass a thunk, then special-case it so that thunks were executed so that existing code continues to work. Also, 'say' could have an option that lets you use println instead of displayln, or automatically map ~v over arguments. And obviously this system doesn't take advantage of Racket's hierarchical logging infrastructure.  That said, it's simple and it works really well for me.

--
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+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.