with-output-to-string resutl can't be pased to log:info about log4cl

[avodonosov]

The workaround is of course

(log:info (log:make-logger) (with-output-to-string (s) (format s "hello")))

[7max]

(log:info "hello") => works

(log:info (with-output-to-string (s) (format s "hello"))) =>

value "hello" is not of the expected type LOG4CL-IMPL::LOGGER.
[Condition of type TYPE-ERROR]

The logging macros already expand into arguments to FORMAT on their
own, there are no need for indirection, ie (log:info "number is ~d" (function-returning-number))

The first argument of logging macros is expected to be a logger to log into,
and the rest are and &rest args as in FORMAT

Since usually the logging is done with a format-like control-string,
when the first argument is a constant string, logger defaults to
(log:make-logger) automatically, without need to specify it.

So (log:info "string" ...rest...) is equivalent of (log:info (log:make-logger) "string" ...rest...)

If you need the control string to be determined dynamically, you need
to specify a logger as 1st argument, like so:

(log:info (log:make-logger) (with-output-to-string (s) (format s "hello")))

[avodonosov]

Since usually the logging is done with a format-like control-string,
when the first argument is a constant string, logger defaults
to (log:make-logger) automatically, without need to specify it.

I submitted this issue because was surprised that
omitting (log:make-logger) is done for constant string,
but not for any string. If it's not a bug, then let's close the issue.

The logging macros already expand into arguments to FORMAT on their own,
there are no need for indirection

My use case was to print stacktrace to log. The initial attempt was

(log:error (with-output-to-string (s)
             (format s
                     "Error of type ~A during tests on ~A: ~A~%"
                     (type-of c) (implementation-identifier lisp) c)
             (trivial-backtrace:print-backtrace-to-stream s)
             (format s "~&~%Continuing for the remaining lisps.")))

Can be rewritten as

(log:error "Error of type ~A during tests on ~A: ~A~%~%Continuing for the remaining lisps."
           (type-of c)
           (implementation-identifier lisp)
           (with-output-to-string (s)
             (trivial-backtrace:print-backtrace-to-stream s)))

[avodonosov]

I want also to note a disadvantage of the both above variants for backtrace printing. I've got 11 logr4cl calls in the backtrace (in the below bactrace items 12 - 2 inclusive):

[04:23:44] [error] <test-grid-agent> - Unhandled seriours-condition of type SIMPLE-ERROR: Error in main! Ha-ha!.
 (2839260) : 0 (PRINT-CALL-HISTORY :CONTEXT NIL :PROCESS NIL :ORIGIN NIL :DETAILED-P NIL :COUNT 1152921504606846975 :START-FRAME-NUMBER 0 :STREAM #<STRING-OUTPUT-STREAM  #x210172EC0D> :PRINT-LEVEL 2 :PRINT-LENGTH 5 :SHOW-INTERNAL-FRAMES NIL :FORMAT :TRADITIONAL) 853
 (28393C8) : 1 (PRINT-BACKTRACE-TO-STREAM #<STRING-OUTPUT-STREAM  #x210172EC0D>) 85
 (28393F8) : 2 (FUNCALL #'#<(:INTERNAL #:|log-stmt3130| (TEST-GRID-AGENT:MAIN (T)))> #<SYNONYM-STREAM to *TERMINAL-IO* #x21006AA61D>) 197
 (2839468) : 3 (FUNCALL #'#<Anonymous Function #x2100BA4B1F> #<SYNONYM-STREAM to *TERMINAL-IO* #x21006AA61D> #<LOG4CL-IMPL::FORMAT-INFO #x2100C05A1D> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 589
 (28394C8) : 4 (FUNCALL #'#<(:INTERNAL LOG4CL-IMPL::COMPILE-PATTERN-FORMAT)> #<SYNONYM-STREAM to *TERMINAL-IO* #x21006AA61D> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 181
 (2839528) : 5 (FUNCALL #'#<#<STANDARD-METHOD LOG4CL-IMPL:LAYOUT-TO-STREAM (LOG4CL-IMPL:PATTERN-LAYOUT T T T T)>> #<LOG4CL-IMPL:PATTERN-LAYOUT #x2100C05E5D> #<SYNONYM-STREAM to *TERMINAL-IO* #x21006AA61D> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 125
 (2839568) : 6 (FUNCALL #'#<#<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND (LOG4CL-IMPL:STREAM-APPENDER T T T)>> #<LOG4CL-IMPL:CONSOLE-APPENDER #x2100C058BD> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 141
 (28395A8) : 7 (%CALL-NEXT-METHOD (NIL #<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND #> . 5272288)) 989
 (2839628) : 8 (FUNCALL #'#<#<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND :AROUND (LOG4CL-IMPL:SERIALIZED-APPENDER T T T)>> #<LOG4CL-IMPL:CONSOLE-APPENDER #x2100C058BD> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 293
 (28396A8) : 9 (%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND :AROUND #> #<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND #>) 5272288) 669
 (2839728) : 10 (FUNCALL #'#<(:INTERNAL LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS LOG4CL-IMPL::LOG-WITH-LOGGER)> #<LOGGER +ROOT+> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 901
 (28397B8) : 11 (FUNCALL #'#<(:INTERNAL LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS LOG4CL-IMPL::LOG-WITH-LOGGER)> #<LOGGER TEST-GRID-AGENT> #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 1293
 (2839800) : 12 (LOG-WITH-LOGGER #<LOGGER TEST-GRID-AGENT> 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 85
 (2839840) : 13 (FUNCALL #'#<(:INTERNAL (TEST-GRID-AGENT:MAIN (T)))> #<SIMPLE-ERROR #x21016E80FD>) 453

It may be tolerated, but it's a little bit misleading, because I what to show the reader where error happened, and the reader may get an impression that the error happened in the log4cl, while actually it has happened in MAIN.

It would be good if log4cl develop some idiom for backtrace printing, because backtraces are very useful feature of logs. And for printing conditions.

It is of course desirable that log printing code be compact.

The solution I use now:

                (let ((bt (with-output-to-string (s)
                            (trivial-backtrace:print-backtrace-to-stream s))))
                  (log:error "Unhandled seriours-condition of type ~A: ~A~%~A"
                              (type-of c) c bt))

Now the backtrace doesn't have the log4cl lines as the bactraces is evaluated outside:

[04:49:44] [error] <test-grid-agent> - Unhandled seriours-condition of type SIMPLE-ERROR: Error in main! Ha-ha!
 (2929678) : 0 (PRINT-CALL-HISTORY :CONTEXT NIL :PROCESS NIL :ORIGIN NIL :DETAILED-P NIL :COUNT 1152921504606846975 :START-FRAME-NUMBER 0 :STREAM #<STRING-OUTPUT-STREAM  #x21018233AD> :PRINT-LEVEL 2 :PRINT-LENGTH 5 :SHOW-INTERNAL-FRAMES NIL :FORMAT :TRADITIONAL) 853
 (29297E0) : 1 (PRINT-BACKTRACE-TO-STREAM #<STRING-OUTPUT-STREAM  #x21018233AD>) 85
 (2929810) : 2 (FUNCALL #'#<(:INTERNAL (TEST-GRID-AGENT:MAIN (T)))> #<SIMPLE-ERROR #x21018236DD>) 157
 (2929868) : 3 (SIGNAL #<SIMPLE-ERROR #x21018236DD>) 981
 (29298C0) : 4 (%ERROR #<SIMPLE-ERROR #x21018236DD> NIL 5395229) 117
 (29298E8) : 5 (FUNCALL #'#<(:INTERNAL TEST-GRID-AGENT::AS-SINGLETON-AGENT-BODY (TEST-GRID-AGENT:MAIN (T)))>) 181
 (2929918) : 6 (EXECUTE-AS-SINGLETON #<TEST-GRID-AGENT::AGENT-IMPL #x2101808DED> #<COMPILED-LEXICAL-CLOSURE (:INTERNAL TEST-GRID-AGENT::AS-SINGLETON-AGENT-BODY #) #x2101825F6F>) 437
 (2929998) : 7 (FUNCALL #'#<#<STANDARD-METHOD TEST-GRID-AGENT:MAIN (T)>> #<TEST-GRID-AGENT::AGENT-IMPL #x2101808DED>) 573
 (29299E0) : 8 (CALL-CHECK-REGS TEST-GRID-AGENT:MAIN #<TEST-GRID-AGENT::AGENT-IMPL #x2101808DED>) 221

But the lisp code with the separate LET to compute backtrace is somewhat long comparing to log4j:

        log.error("Unhandled exception", e);

I don't know how to improve it and the current version is OK for me. But some considerations:

If the parameters to (log:info ...) were evaluated, it would allow more compact variant for backtraces

(log:error "Error of type ~A: ~A~%~A~%"
           (type-of c) c
           (with-output-to-string (s)
             (trivial-backtrace:print-backtrace-to-stream s))

without having the log4cl calls in backgrace.

Maybe it will be good if macroexpansion of log:error, log:info, log:warn produced
the code which evaluates the parameters in the same scope?

To save performance we may want to disable the parameters evaluation
when the corresponding log level is disabled.

So at the first sight the expansion for log:debug could be

`(when (log:debug)
  (log:debug-impl ,@params))

But if speak from java experience, I almost never use

if (log.isDebugEnabled()) {
  log.debug("something"); 
}

if (log.isInfoEnabled()) {
  log.info("something"); 
}

It is rarely necessary because:

• parameters are very often constants, and so have no evaluation cost
• the INFO log level is almost always enabled so the IF never saves performance, but instead wastes it
• the log.debug statemetns are very rare in my code (it's lot of work to write even info logs
  and error stack traces are enough to investigate 99% of problems without any debug logging)

So, to conclude, I am for evaluating the parameters in the same scope,
definitely not including (when (log:info) ...) into the macro-expansion of
log:info, and think it's not important to have (when (log:debug) ...)
in the macro-expansion of the log:debug.

[7max]

Slime has a similar problem with bunch of slime internals and SBCL
debugger internals littering top of the stack trace.

So for SBCL I can fix it by doing (let ((stack-top-hint
(current-frame))) ... do the log statement ...), but this won't be portable.

How do you see the API for printing backtraces? From top of my head variants are:

1. Add :print-backtrace t to all logging macros, so one can do

   (log:error :print-backtrace t "Error ~S happened" c)

   Cons: format of printing backtraces pretty much have to be hardcoded into log4cl

2. Similar to above, but instead of adding keyword argument, add a set of logging macros with bt or backtrace in their name,
   ie (log:error-backtrace "Error ~S happened" c)

   Cons: polluting namespace, but its already pretty polluted with
   one-letter shortcuts anyway, and I had requests to add more
   shortcuts, for example (log:ee "error because of" expr1) to be same
   as (log:sexp-error "error because of" expr1)

Pros for 1/2 is log4cl may print the frames and variables as pretty printed blocks, similar to (log:expr), so that
output will be nicely wrapped/indented.

1. Wrap all public API of trivial-backtrace within log4cl
   package, that will filter out log4cl frames. All log4cl logging
   goes through log4cl-impl::log-to-logger-appenders function, so it
   seem trivial to skip frames until we hit it.

   Cons: will have to track changes to trivial-backtrace API, but it seems pretty small
   Pros: User controls what they want to print and how;

So far I'm inclined to go with 3.

Also please do not be discouraged that I'm not fixing this right away,
I'm in the middle of some refactoring on log4cl to add Slime
integration (as a separate system, it adds highlighting for the log
statements in Slime (for category, file, message) and makes the logger
names right-clickable with menu to set/reset log levels). Once I
finish that, I'll start on the other features/bugs list.

Regards,
Max

At Mon, 6 Aug 2012 19:21:57 -0700,
Anton Vodonosov wrote:

I want also to note a disadvantage of the both above variants for backtrace printing. I've got 11 logr4cl calls in the backtrace (in
the below bactrace items 12 - 2 inclusive):

[04:23:44] [error] - Unhandled seriours-condition of type SIMPLE-ERROR: Error in main! Ha-ha!.
(2839260) : 0 (PRINT-CALL-HISTORY :CONTEXT NIL :PROCESS NIL :ORIGIN NIL :DETAILED-P NIL :COUNT 1152921504606846975 :START-FRAME-NUMBER 0 :STREAM #<STRING-OUTPUT-STREAM #x210172EC0D> :PRINT-LEVEL 2 :PRINT-LENGTH 5 :SHOW-INTERNAL-FRAMES NIL :FORMAT :TRADITIONAL) 853
(28393C8) : 1 (PRINT-BACKTRACE-TO-STREAM #<STRING-OUTPUT-STREAM #x210172EC0D>) 85
(28393F8) : 2 (FUNCALL #'#<(:INTERNAL #:|log-stmt3130| (TEST-GRID-AGENT:MAIN (T)))> #<SYNONYM-STREAM to TERMINAL-IO #x21006AA61D>) 197
(2839468) : 3 (FUNCALL #'#<Anonymous Function #x2100BA4B1F> #<SYNONYM-STREAM to TERMINAL-IO #x21006AA61D> #<LOG4CL-IMPL::FORMAT-INFO #x2100C05A1D> # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 589
(28394C8) : 4 (FUNCALL #'#<(:INTERNAL LOG4CL-IMPL::COMPILE-PATTERN-FORMAT)> #<SYNONYM-STREAM to TERMINAL-IO #x21006AA61D> # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 181
(2839528) : 5 (FUNCALL #'#<#<STANDARD-METHOD LOG4CL-IMPL:LAYOUT-TO-STREAM (LOG4CL-IMPL:PATTERN-LAYOUT T T T T)>> #<LOG4CL-IMPL:PATTERN-LAYOUT #x2100C05E5D> #<SYNONYM-STREAM to TERMINAL-IO #x21006AA61D> # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 125
(2839568) : 6 (FUNCALL #'#<#<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND (LOG4CL-IMPL:STREAM-APPENDER T T T)>> #<LOG4CL-IMPL:CONSOLE-APPENDER #x2100C058BD> # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 141
(28395A8) : 7 (%CALL-NEXT-METHOD (NIL #<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND #> . 5272288)) 989
(2839628) : 8 (FUNCALL #'#<#<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND :AROUND (LOG4CL-IMPL:SERIALIZED-APPENDER T T T)>> #<LOG4CL-IMPL:CONSOLE-APPENDER #x2100C058BD> # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 293
(28396A8) : 9 (%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND :AROUND #> #<STANDARD-METHOD LOG4CL-IMPL:APPENDER-DO-APPEND #>) 5272288) 669
(2839728) : 10 (FUNCALL #'#<(:INTERNAL LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS LOG4CL-IMPL::LOG-WITH-LOGGER)> #<LOGGER +ROOT+> # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 901
(28397B8) : 11 (FUNCALL #'#<(:INTERNAL LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS LOG4CL-IMPL::LOG-WITH-LOGGER)> # # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 1293
(2839800) : 12 (LOG-WITH-LOGGER # 2 #<COMPILED-LEXICAL-CLOSURE (:INTERNAL #:|log-stmt3130| #) #x2960E3F>) 85
(2839840) : 13 (FUNCALL #'#<(:INTERNAL (TEST-GRID-AGENT:MAIN (T)))> #<SIMPLE-ERROR #x21016E80FD>) 453

It may be tolerated, but it's a little bit misleading, because I what to show the reader where error happened, and the reader may get
an impression that the error happened in the log4cl, while actually it has happened in MAIN.

It would be good if log4cl develop some idiom for backtrace printing, because backtraces are very useful feature of logs. And for
printing conditions.

It is of course desirable that log printing code be compact.

The solution I use now:

                        (let ((bt (with-output-to-string (s)
                                    (trivial-backtrace:print-backtrace-to-stream s))))
                          (log:error "Unhandled seriours-condition of type ~A: ~A~%~A"
                                     (type-of c) c bt))

Now the backtrace doesn't have the log4cl lines as the bactraces is evaluated outside:

[04:49:44] [error] - Unhandled seriours-condition of type SIMPLE-ERROR: Error in main! Ha-ha!
(2929678) : 0 (PRINT-CALL-HISTORY :CONTEXT NIL :PROCESS NIL :ORIGIN NIL :DETAILED-P NIL :COUNT 1152921504606846975 :START-FRAME-NUMBER 0 :STREAM #<STRING-OUTPUT-STREAM #x21018233AD> :PRINT-LEVEL 2 :PRINT-LENGTH 5 :SHOW-INTERNAL-FRAMES NIL :FORMAT :TRADITIONAL) 853
(29297E0) : 1 (PRINT-BACKTRACE-TO-STREAM #<STRING-OUTPUT-STREAM #x21018233AD>) 85
(2929810) : 2 (FUNCALL #'#<(:INTERNAL (TEST-GRID-AGENT:MAIN (T)))> #<SIMPLE-ERROR #x21018236DD>) 157
(2929868) : 3 (SIGNAL #<SIMPLE-ERROR #x21018236DD>) 981
(29298C0) : 4 (%ERROR #<SIMPLE-ERROR #x21018236DD> NIL 5395229) 117
(29298E8) : 5 (FUNCALL #'#<(:INTERNAL TEST-GRID-AGENT::AS-SINGLETON-AGENT-BODY (TEST-GRID-AGENT:MAIN (T)))>) 181
(2929918) : 6 (EXECUTE-AS-SINGLETON #<TEST-GRID-AGENT::AGENT-IMPL #x2101808DED> #<COMPILED-LEXICAL-CLOSURE (:INTERNAL TEST-GRID-AGENT::AS-SINGLETON-AGENT-BODY #) #x2101825F6F>) 437
(2929998) : 7 (FUNCALL #'#<#<STANDARD-METHOD TEST-GRID-AGENT:MAIN (T)>> #<TEST-GRID-AGENT::AGENT-IMPL #x2101808DED>) 573
(29299E0) : 8 (CALL-CHECK-REGS TEST-GRID-AGENT:MAIN #<TEST-GRID-AGENT::AGENT-IMPL #x2101808DED>) 221

But the lisp code with the separate LET to compute backtrace is somewhat long comparing to log4j:

    log.error("Unhandled exception", e);

I don't know how to improve it and the current version is OK for me. But some considerations:

If the parameters to (log:info ...) were evaluated, it would allow more compact variant for backtraces

(log:error "Error of type ~A: A%A%"
(type-of c) c
(with-output-to-string (s)
(trivial-backtrace:print-backtrace-to-stream s))

without having the log4cl calls in backgrace.

Maybe it will be good if macroexpansion of log:error, log:info, log:warn produced
the code which evaluates the parameters in the same scope?

To save performance we may want to disable the parameters evaluation
when the corresponding log level is disabled.

So at the first sight the expansion for log:debug could be

`(when (log:debug)
(log:debug-impl ,@params))

But if speak from java experience, I almost never use

if (log.isDebugEnabled()) {
log.debug("something");
}

if (log.isInfoEnabled()) {
log.info("something");
}

It is rarely necessary because:

• parameters are very often constant,
• the INFO log level is always enabled so the IF is never saves performance, but instead wastes it
• the log.debug statemetns are very rare in my code (it's lot of work to write even info logs and error stack traces are enough to
investigate 99% of problems without any debug logging)

So, to conclude, I am for evaluating the parameters in the same scope,
definitely not including (when (log:info) ...) into the macro-expansion of
log:info, and think it's not important to have (when (log:debug) ...)
in the macro-expansion of the log:debug.

—
Reply to this email directly or view it on GitHub.

[7max]

Actually I have a better idea, as part of log4cl refactoring, instead
of customizing per-package logging configuration by adding methods
specialized on package, I'm adding a single function to set
per-package.

As part of that I can add some setting to automatically print
backtrace for certain log levels, like this:

(log:setup :package                 *package*
           :category-separator      "."
           :category-case           :downcase
           :expr-format             "~a => ~s"
           :print-backtrace-level   :error)

Then any (log:error) or (log:fatal) will print its log message, and
automatically print the backtrace afterward.

[avodonosov]

Also please do not be discouraged that I'm not fixing this right away,

I do not expect it to be fixed right now, moreover it is not clear how to deal with backtracks.
I just decided to collect here some information which hopefully may be useful sometime in the future.

For my needs the current version of log4cl is satisfying.