Custom appender causes weird blocking when logging

[martinklepsch]

I'm currently trying to reproduce this logback.xml configuration using build-appender, here's what I have:

(require '[unilog.config :as unilog])
(import 'com.papertrailapp.logback.Syslog4jAppender)
(import 'org.productivity.java.syslog4j.impl.net.tcp.ssl.SSLTCPNetSyslogConfig)
(import 'ch.qos.logback.classic.PatternLayout)

(defmethod unilog/build-appender :papertrail                                                 
  [{:keys [host port ident] :as config}]                                                     
  (prn 'creating-papertrail-appender)                                                        
  (assoc config :appender (doto (Syslog4jAppender.)                                          
                            (.setSyslogConfig (doto (SSLTCPNetSyslogConfig. host port)       
                                                (.setIdent ident)))                          
                            (.setLayout (doto (PatternLayout.)                               
                                          (.setPattern "%-5level %logger{35}: %m%n%xEx"))))))

I call start-logging! with a valid config and it does something (it blocks for a second or so) but logging anything does not result in it being added to Papertrail. Do you see any issues with my custom build-appender method? Few other observations:

• It blocks everytime I log now for a second or even more.
• Logging to console happens immediately, but it takes longer for the invocation to return.
• I don't get any other log statements, prints whatever.
• Without the .setLayout call the blocking-on-log described above does not occur.

My guess is there's an exception somewhere that's being swallowed? FWIW I used the appender via logback.xml before and it worked. It ended up causing some issues in CI though (blocked the process, build timed out) which is why I'm now investigating unilog again. Thanks @mpenet for the tip :)

(unilog/start-logging! {:level "info"                                   
                        :console true                                   
                        :appenders [{:appender :papertrail              
                                     :host     "logsX.papertrailapp.com"
                                     :port     0                    
                                     :ident    "my-app"}]})     

[martinklepsch]

@pyr Hey Pierre-Yves, just saw your assigning/labelling here. Is there anything I can do to help? Do you have any idea what the issue may be? I'd be happy to try some things here if you think it could help :)

[pyr]

@martinklepsch Hi, I haven't looked at it yet, assigned it to avoid forgetting, I'll tackle it tomorrow or Tuesday.

Cheers.

[martinklepsch]

Hey, I hope I didn't pressure you into that now, wasn't my intention. :) Thanks though. And let me know if there's anything I should do/try.

[pyr]

It seems to work for me with 0.7.20, can you try with this version. I used a similar set-up to yours with a destination of "localhost" and logging does not block, I do get asynchronous "connection refused" message, obviously.

Cheers,

[martinklepsch]

I tried again with 0.7.2 but didn't have any luck unfortunately. When using the real host I still have the same behavior as described previously (blocking + no error of any kind). When using localhost to provoke "connection refused" I also get the blocking behavior and the connection refused error. Really weird.

These are the dependencies I'm using in case that is useful.

[org.clojure/tools.logging "0.3.1"]
[org.slf4j/slf4j-api "1.7.24"]
[ch.qos.logback/logback-classic "1.2.1"]
[com.papertrailapp/logback-syslog4j "1.0.0"]
[spootnik/unilog "0.7.20"]

I also reproduced this outside the full project with this build.boot file (evaluated the contents of the comment block via the repl. The 111111 port is exemplary.

(set-env! :dependencies '[[org.clojure/tools.logging "0.3.1"]
                          [org.slf4j/slf4j-api "1.7.24"]
                          [ch.qos.logback/logback-classic "1.2.1"]
                          [com.papertrailapp/logback-syslog4j "1.0.0"]
                          [spootnik/unilog "0.7.20"]])

(comment
  (require '[unilog.config :as unilog]
           '[clojure.tools.logging :as log])

  (do
    (import 'com.papertrailapp.logback.Syslog4jAppender)
    (import 'org.productivity.java.syslog4j.impl.net.tcp.ssl.SSLTCPNetSyslogConfig)
    (import 'org.slf4j.LoggerFactory)
    (import 'ch.qos.logback.classic.PatternLayout)
    (import 'ch.qos.logback.classic.Logger)
    (import 'ch.qos.logback.classic.LoggerContext)
    (import 'ch.qos.logback.core.spi.ContextAware)
    (import 'ch.qos.logback.core.spi.LifeCycle))

  (defmethod unilog/build-appender :papertrail
    [{:keys [host port ident] :as config}]
    (prn 'creating-papertrail-appender)
    (assoc config :appender (doto (Syslog4jAppender.)
                              (.setSyslogConfig (doto (SSLTCPNetSyslogConfig. host port)
                                                  (.setIdent ident)))
                              (.setLayout (doto (PatternLayout.)
                                            (.setPattern "%-5level %logger{35}: %m%n%xEx"))))))

  (unilog/start-logging! {:level "info"
                          :console true
                          :appenders [{:appender :papertrail
                                       :host     "logs5.papertrailapp.com"
                                       :port     111111
                                       :ident    "my-app" 
                                       :max-message-length 128000}]})

  (log/info "TEST")

  )

[pyr]

Hi @martinklepsch,

I just tested again with 0.7.22, slf4j-api 1.7.25, logback-classic 1.2.3 and clojure.tools.logging 0.4.0. I used the example code you showed above and changed the destination to localhost. Switching between a started nc listener and a stopped one.

I then used (time (log/info "foo")) which always returned in a few milliseconds. I'm not sure what I can do beyond that to try and resolve the issue.

[martinklepsch]

Hey Pierre-Yves 🙂

Switching between a started nc listener and a stopped one.

Could you explain what you mean by that?

I just tried again with the versions you listed and the appender config from the above snippet and it still takes about 5 seconds until an exception is thrown:

java.lang.IllegalArgumentException: port out of range:111111

Notably this is an illegalArgumentException so I assume it's thrown before any network activity.

Did you try the test snippet with Boot or adapted for Leiningen? Maybe Logback/SLF4J do some special stuff with Classloaders which is where Leiningen and Boot have some differences.

[pyr]

Hi !

So by started/stopped one I mean that I tested with a fake syslog listening and with no listener on the port. The port out of range exception is expected since port 111111 is beyond the maximum allowed value of 65535, so changed that to an arbitrary port.

I tested with boot and set-env just like in your example.

[martinklepsch]

The port out of range exception is expected since port 111111 is beyond the maximum allowed value of 65535, so changed that to an arbitrary port.

Right. I just found it interesting to observe that the delay seems to be caused before any network requests are made.

I'll try reproducing with a proper host/port/actual listener.

[pyr]

Thanks!

From my perspective: small delays when intializing a bad configuration I can understand, delays per logs I wouldn't. If a wrong port is provided there is a delay during start-logging! but not during log operations based on my experiments, if you can confirm that I would close the ticket.

Cheers, and sorry for the slow lead-time in getting this figured out.