{"size": 5872, "ext": "scrbl", "max_stars_repo_path": "scribblings/in-out-logged.scrbl", "max_stars_repo_name": "dstorrs/in-out-logged", "max_stars_repo_stars_event_min_datetime": "2021-10-09T00:09:25.000Z", "max_stars_repo_stars_event_max_datetime": "2022-01-15T23:01:50.000Z", "max_issues_repo_path": "scribblings/in-out-logged.scrbl", "max_issues_repo_name": "dstorrs/in-out-logged", "max_issues_repo_issues_event_min_datetime": null, "max_issues_repo_issues_event_max_datetime": null, "max_forks_repo_path": "scribblings/in-out-logged.scrbl", "max_forks_repo_name": "dstorrs/in-out-logged", "max_forks_repo_forks_event_min_datetime": null, "max_forks_repo_forks_event_max_datetime": null}
{"max_stars_count": 2, "max_issues_count": null, "max_forks_count": null, "avg_line_length": 34.1395348837, "max_line_length": 121, "alphanum_fraction": 0.6689373297}
#lang scribble/manual

@(require (for-label racket)
          racket/sandbox
          scribble/example)

@title{in-out-logged}
@author{David K. Storrs}

@defmodule[in-out-logged]

@section{Description}

Macro:  @racket[in/out-logged]

Wraps a chunk of code such that log messages are output when the code begins and ends.

Returns the result(s) of the code.  These results can be shown in the `out'
message if so desired.

@racket[in/out-logged] can optionally be given a series of values to be included
in the `in' and `out' messages.  A good use case for this is to output the
@racket[current-inexact-nanoseconds] to get a rough approximation of how long
the code takes when you don't want to do a full profiler run.

If there are an even number of arguments then they are understood to be
key/value pairs and will be arranged as such, meaning "\n\t key <whitespace>
value", with nice alignment between elements.

If there are an odd number of arguments then they will be displayed on one line.

If you want control of how they are displayed then you can use the
@racket[#:with] keyword to provide a format string and a series of values to
format into it.


@section{Synopsis}

@(define eval
   (call-with-trusted-sandbox-configuration
    (lambda ()
      (parameterize ([sandbox-output 'string]
                     [sandbox-error-output 'string]
                     [sandbox-memory-limit 50])
        (make-evaluator 'racket)))))

@racketblock[
 (in/out-logged (#:to <logger-name>
                 #:at <logger-level>
                 #:results (id ...+)
                 <key/value pair> ...)
    code ...)

 (in/out-logged (#:to <logger-name>
                 #:at <logger-level>
                 #:results (id ...+)
                 #:with <format-str> <value> ...)
   code ...)
]

All keywords are optional.

By default output is sent to @racket[(current-logger)] at @racket['debug] level.

Valid levels are as per the Racket logging system.  In decreasing order of importance:

@racketblock[
  'fatal 'error 'warning 'info 'debug
]

@section{Examples}

@racketblock[

 (define-logger foo)

 (define (on-complete op . args)
   (log-foo-debug "message from inside on-complete")
   (apply op args))

 (code:comment "log around a literal value")
 > (in/out-logged ("literal") 'ok)
entering literal. 
leaving literal. 

 (code:comment "return the result of a function call")
 > (in/out-logged
     ("on-complete" #:at 'error #:to foo-logger)
     "a pointless string to show multiple expressions in the body"
     (on-complete + 1 2 3))
entering on-complete. 
message from inside on-complete
leaving on-complete. 

 > (in/out-logged ("on-complete, explicitly foo-logger" #:to foo-logger) (on-complete + 1 2 3))
foo: entering on-complete, explicitly foo-logger. 
message from inside on-complete
foo: leaving on-complete, explicitly foo-logger. 

 (code:comment "log in/out messages at 'info level")
 > (in/out-logged ("on-complete at 'info level" #:to foo-logger #:at 'info) (on-complete + 1 2 3))
foo: entering on-complete at 'info level. 
message from inside on-complete
foo: leaving on-complete at 'info level. 

 (code:comment "order of keywords doesn't matter")
 > (in/out-logged ("on-complete, vary keyword order" #:at 'debug #:to foo-logger )
                  (on-complete + 1 2 3))
foo: entering on-complete, vary keyword order.
message from inside on-complete
foo: leaving on-complete, vary keyword order.

 (code:comment "For convenience, we'll set foo as our default logger")
 > (current-logger foo-logger)

 (code:comment "include arguments to be displayed in the 'entering' message. By default they are shown as key/val pairs")
 > (in/out-logged ("on-complete with arguments"
                   "time" (current-seconds)
                   "thread-id" 17)
                  (on-complete + 1 2 3))
foo: entering on-complete with arguments. 
	time     	1642022093
	thread-id	17
foo: message from inside on-complete
foo: leaving on-complete with arguments. 
	time     	1642022093
	thread-id	17

 (code:comment "use a specified format string instead of the default key/value pairs")
 > (in/out-logged ("on-complete with an explicit format string"
                   #:with "time is: ~a, username is: ~a." (current-seconds) 'bob)
                  (on-complete + 1 2 3))
foo: entering on-complete with an explicit format string. time is: 1642022093, username is: bob.
foo: message from inside on-complete
foo: leaving on-complete with an explicit format string. time is: 1642022093, username is: bob.

 (code:comment "multiple value return is fine. also, let's use 'error level for demonstration")
 > (in/out-logged ("values at 'error level" #:at 'error)
                  (values 1 2))
foo: entering values at 'error level. 
foo: leaving values at 'error level. 

 (code:comment "display the results of the code in the 'leaving' message")
 > (in/out-logged ("values and show multiple returns" #:results (x y))
                  (values 1 2))
foo: entering values and show multiple returns.
foo: leaving values and show multiple returns. results: (values 1 2)

 (code:comment "display the results of the code in the 'leaving' message, only one result")
 > (in/out-logged ("values and show one return" #:results (x y))
                  'ok)
foo: entering values and show one return.
foo: leaving values and show one return. results: (values 'ok)

 (code: comment "results and arguments")
 > (in/out-logged ("on-complete with arguments"
                #:to foo-logger
                #:at 'info
                #:results (result)
                "time" (current-seconds)
                "thread-id" 17)
               (on-complete + 1 2 3))
foo: entering on-complete with arguments. 
	time     	1642024707
	thread-id	17
foo: message from inside on-complete
foo: leaving on-complete with arguments.  results: (values 6)
	time     	1642024707
	thread-id	17

]
