duplicate log entries

[wadcom]

Hi,

I'm using mulog 0.9.0 in a single-threaded application and see duplicate entries in the output log stream. The contents of the entries are completely identical, including trace ids and timestamps. Not all entries are duplicated. I've tried using :file-json publisher and the "advanced console" one, with similar results.

If this is not a known issue, how can I troubleshoot it?

Thanks!

[BrunoBonacci]

Hi @wadcom ,

can you please share some of your setup code? Typically you get duplicate events logged in one of the following conditions:

1. you started the publisher twice, maybe accidentally
2. the publisher failed to publish the logs in the current buffer, for example, due to a timeout on the receiving end, and it will attempt to publish the same records again until it gets a successful response.

Please share some examples so that I help you eliminate the issue

[wadcom]

Hi @BrunoBonacci,

the setup is trivial:

(defn- init-mulog [fname]
  ;; https://github.com/BrunoBonacci/mulog/blob/master/doc/publishers/advanced-file-publisher.md
  (let [console-pub {:type :console :pretty? true}
        file-pub {:type :file-json :filename fname}
        pub-spec (if fname file-pub console-pub)
        mulog-shutdown (mu/start-publisher! pub-spec)]
    (.addShutdownHook (Runtime/getRuntime)
                      (Thread. #(do (println "Flushing log publisher")
                                    (Thread/sleep 5000)
                                    mulog-shutdown)))))

I am sure I do not start the publisher twice. I've nailed this down to the volume of logs I'm producing. My application emits about 2.5k log messages per second (I guess I took "you can log plenty" too literally...), so I think the publisher just can't keep up.

On the other hand, since it uses ring buffers, I'd expect it to drop messages rather than produce duplicates.

Please let me know if I can provide any additional info.

Also, given that the default initial buffer size is 1000 and publishing happens every 200ms, is it reasonable to assume that mulog's expected maximum throughput is 5k msgs/sec in default configuration?

[BrunoBonacci]

Hi @wadcom

since you are using the JSON publisher on a file, you should check whether the conversion to JSON is successful and the writing to a file is successful too.

For example, if you log a clojure map with numerical keys (or any type other than strings and keywords) you will get an error during the conversion.

;; this is valid in Clojure but not in JSON
{:a {1 2}}

you could check if a publisher fails to publish the data by logging to two different publishers and looking for an event name called :mulog/publisher-error. see https://cljdoc.org/d/com.brunobonacci/mulog/0.9.0/doc/special-publishers/multi-publisher

Additionally, note that in your code the mulog-shutdown is a function to be called therefore it needs to be wrapped in brackets (mulog-shutdown).

[BrunoBonacci]

Hi @wadcom,

have you managed to isolate any :mulog/publisher-error event?

[wadcom]

Hey @BrunoBonacci,

I haven't tried using two different publishers: I've reduced the volume of logs and changed the shutdown code to properly call the shutdown hook as you suggested. This has fixed the problem for now.

I'll keep your comments in mind if this situation repeats though. Thanks for your help (and for the excellent logging library)!

[BrunoBonacci]

Great, I guess it could have been the improper shutdown causing the publisher to register it twice.

I'll close this for the moment, should you have further issues, feel free to reopen it or open a new one.