search

7max / log4cl

Common Lisp logging framework, modeled after Log4J
Apache License 2.0
103 stars 32 forks source link

with-output-to-string resutl can't be pased to log:info #4

Closed avodonosov closed 12 years ago

avodonosov commented 12 years ago

(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]

This is CCL-1.8, Windows.

avodonosov commented 12 years ago

The workaround is of course

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

7max commented 12 years ago

(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 commented 12 years ago

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 commented 12 years ago

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:

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 commented 12 years ago

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 commented 12 years ago

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 commented 12 years ago

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.