Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1611

SocketAppender doesn't submit log messages sent right before the jvm exits

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.2.9
    • Fix Version/s: 1.4.6
    • Component/s: logback-classic
    • Labels:
      None

      Description

      We are in the process of migrating a big old project from Log4j1 to Logback. Since concepts and features are relatively close the migration itself worked pretty straight forward. Through our regression test suite, we noticed a change - actually a regression - in behavior in the following though:

      We have a ch.qos.logback.classic.net.SimpleSocketServer running to which a couple of other Java processes send log messages via ch.qos.logback.classic.net.SocketAppender s. I guess it's important to mention that these are pretty much plain Java Main processes, no Jetty or any other web- or application container, just plain Java processes.

      We found that in some cases, the last log messages logged right before the end of the main() method, so right before the JVM exits, aren't submitted to the server component. After reading through the docs, we added the 

      <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook"/>

      (btw: the Doc is still broken, see LOGBACK-1090). The ShutdownHook closes the logging contet, which I would've expected to flush any pending log messages and finish transmitting them to the server. However, this doesn't seem to be the case because simply adding this hook didn't solve the problem. What did though was explicitly adding a delay before the context shutdown (I didn't find how to specify a delay in the documentation by the way - luckily, stack overflow came to the rescue).

      <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook">
          <delay>500</delay>
      </shutdownHook>

      This finally made logback send out all messages before the VM exited. It seems like a flaky solution though since the required timing may vary based on various factors. It would be far better if logback's SocketAppender flushed and closed everything cleanly when the logging context closes.

       

        Attachments

          Activity

            People

            Assignee:
            logback-dev Logback dev list
            Reporter:
            netmikey Mike M.
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated: