Should serialized-appender use a recursive lock?

Question

Should serialized-appender use a recursive lock?

Closed this issue 7 years ago · 6 comments

Consider the following:

(with-simple-restart (abort "Abort")
  (handler-bind 
    ((error (lambda (condition)
               (log:error "caught error: ~A" condition)
               (abort))))
    (log:info "~A")
    :finished))

(log:info "~A") is obviously wrong since there are not enough format arguments. One would expect this error to be caught and reported by the outer "catch-all" handler-bind. However, since the format error is signaled while in appender-do-append, the (log:error "caught error: ~A" condition) code re-enters appender-do-append and causes a recursive lock attempt. As a consequence, a relatively harmless format error in logging code escalates even beyond the intended "catch-all" error handling.

I can imagine two possible improvements:

Catch errors of his kind in log4cl and print a log message like <INFO> [20:08:12] cl-user () - <<error printing log message>>. This approach would similar to the usual <SOME-CLASS <<error printing object>> >-behavior. This solution would not change the control flow, i.e. return :finished in the above example, since no error would be signaled.
Use a recursive lock. In the above example this would lead to the output (in SBCL):

<ERROR> [20:08:12] cl-user () -
  caught error: error in FORMAT: required argument missing
  ~A
   ^

This solution would change the control flow since the format-error would still be signaled.

Make one of the two behaviors selectable as a configuration option or via a special variable *debug-log-statements?* :)

Answer 1 · 2013-10-30T03:27:07.000Z

I'm aware of this problem under a bit of a different angle, something like "(log:info (call-that-uses-logging-itself))" hangs trying to take appender lock recursively.

I was planning to solve it, by making a change from "binary logging idea" issue, which would first compute all format arguments putting them into dynamic-extent vector, and then do the call.

That would solve the above problem, but not your example.

I think ideally it should behave as same as if the lock was not there (is like in single threaded built), which is same as recursive lock.

Imho the debug-log-statements is an overkill. Current behavior is obviously broken, recursive lock makes it behave same as it there was no lock, which satisfies principle of least surprise.

So unless you have objections, I'll just make recursive lock change (may have to wait until weekend) or I'll merge pull request for she same

Jan Moringen notifications@github.com wrote:

Consider the following:

(with-simple-restart (abort "Abort") (handler-bind ((error (lambda (condition) (log:error "caught error: ~A" condition) (abort)))) (log:info "~A") :finished))

(log:info "~A") is obviously wrong since there are not enough format arguments. One would expect this error to be caught and reported by the outer "catch-all" handler-bind. However, since the format error is signaled while in appender-do-append, the (log:error "caught error: ~A" condition) code re-enters appender-do-append and causes a recursive lock attempt. As a consequence, a relatively harmless format error in logging code escalates even beyond the intended "catch-all" error handling.

I can imagine two possible improvements:

Catch errors of his kind in log4cl and print a log message like [20:08:12] cl-user () - <>. This approach would similar to the usual <SOME-CLASS <> >-behavior. This solution would not change the control flow, i.e. return :finished in the above example, since no error would be signaled.

Use a recursive lock. In the above example this would lead to the output (in SBCL):

[20:08:12] cl-user () - caught error: error in FORMAT: required argument missing ~A ^

This solution would change the control flow since the format-error would still be signaled.

Make one of the two behaviors selectable as a configuration option or via a special variable debug-log-statements? :)

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

Answer 2 · 2013-11-02T16:19:49.000Z

I'm aware of this problem under a bit of a different angle, something like "(log:info (call-that-uses-logging-itself))" hangs trying to take appender lock recursively.

Out of curiosity: on which implementation does this happen? At least in SBCL, attempting to re-acquire a non-recursive lock signals an error instead of hanging.

I was planning to solve it, by making a change from "binary logging idea" issue, which would first compute all format arguments putting them into dynamic-extent vector, and then do the call.
That would solve the above problem, but not your example.

I think computing an intermediate value such as the formatted string outside the critical section and then writing it to the stream in the critical section would solve both problems. I wrote "intermediate value" because it may not be a formatted string for some kinds of appenders. This would also minimize the time spent in the critical section.

I think ideally it should behave as same as if the lock was not there (is like in single threaded built), which is same as recursive lock.
Imho the debug-log-statements is an overkill. Current behavior is obviously broken, recursive lock makes it behave same as it there was no lock, which satisfies principle of least surprise.
So unless you have objections, I'll just make recursive lock change (may have to wait until weekend) or I'll merge pull request for she same

The solution in the previous paragraph seems better to me although it requires more effort to implement.

Btw: I would really appreciate the binary logging idea for writing custom appenders.

Answer 3 · 2013-11-04T13:05:19.000Z

You are right about recursive lock on SBCL, gives an error instead of hanging now, maybe my memory is from other implementation?

I assume you mean using with-output-to-string to save log statement into temp string? Reason its designed as is, is one of design goal was to minimize consing.

Right now even if you have a lot of debug/trace statements, and setting root level to debug, the consing impact is still low (when not using pretty printer), because everything gets printed directly to the eventual stream. Seems weird to give that up and introduce consing into design just to solve a concurrency issue.

What is the problem with recursive lock solution? I tested it and everything seems to work fine

(handler-bind ((error (lambda (e)
                                 (log:error "Got error" e)
                                 (abort))))
           (log:info "~d")
           (log:info "After the error"))
; 
; caught WARNING:
;   Too few arguments (0) to FORMAT "~d": requires at least 1.
;   See also:
;     The ANSI Standard, Section 22.3.10.2
; 
; compilation unit finished
;   caught 1 WARNING condition
<ERROR> [08:03:42]  [repl-thread] cl-user () -
  Got error E: #<SB-FORMAT:FORMAT-ERROR {100E149383}> 
; Evaluation aborted on #<SB-INT:FORMAT-TOO-FEW-ARGS-WARNING "Too few arguments (~D) to ~S ~S: requires at least ~D." {100DF7E613}>.

Answer 4 · 2013-11-05T07:54:38.000Z

I assume you mean using with-output-to-string to save log statement into temp string?

Yes, at least for string-stream based appenders.

Right now even if you have a lot of debug/trace statements, and setting root level to debug, the consing impact is still low (when not using pretty printer), because everything gets printed directly to the eventual stream. Seems weird to give that up and introduce consing into design just to solve a concurrency issue.

I see. My point was that running formatter code in the critical section may block other threads longer than just writing a precomputed value to the stream. However, as you pointed out, formatting directly to the target stream avoids consing.

What is the problem with recursive lock solution?

I don't think there is any functional problem; the tradeoff is wrt. performance: less consing vs. smaller critical section. I'm not sure which one is more important.

Apart from that, it would be cool if one could write appenders that just receive the "raw" logging data without formatters being involved.

Answer 5 · 2013-11-06T04:33:22.000Z

The "able to write appenders without formatting being involved" is exactly what binary logging wish list issue is about, it would introduce new type of appender that receives a vector of values being logged, to do with as it wishes, from maintaining of circular buffet of last 1000 debug messages to cl-storing it to binary log file, for future analysis with some tool

Jan Moringen notifications@github.com wrote:

I assume you mean using with-output-to-string to save log statement into temp string?

Yes, at least for string-stream based appenders.

Right now even if you have a lot of debug/trace statements, and setting root level to debug, the consing impact is still low (when not using pretty printer), because everything gets printed directly to the eventual stream. Seems weird to give that up and introduce consing into design just to solve a concurrency issue.

I see. My point was that running formatter code in the critical section may block other threads longer than just writing a precomputed value to the stream. However, as you pointed out, formatting directly to the target stream avoids consing.

What is the problem with recursive lock solution?

I don't think there is any functional problem; the tradeoff is wrt. performance: less consing vs. smaller critical section. I'm not sure which one is more important.

Apart from that, it would be cool if one could write appenders that just receive the "raw" logging data without formatters being involved.

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

Answer 6 · 2018-03-28T15:54:15.000Z

Has been addressed in sharplispers#8.