glassfish
  1. glassfish
  2. GLASSFISH-15011

Duplicate INFO messages from logger while creating http listeners

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1
    • Fix Version/s: 3.1_dev
    • Component/s: web_container
    • Labels:
      None

      Description

      In WebContainer.createHttpListener, one print the an INFO message as follows:
      if (_logger.isLoggable(Level.INFO)) {
      _logger.log(Level.INFO, "webContainer.HTTP.listenerAndPort", new Object[]

      {listener.getName(), listener.getAddress(), listener.getPort()});
      }

      This messages will be printed two or three times when we run
      asadmin create-http-listener --listeneraddress <ip> --listenerport <port> --defaultvs <vs> <listener>

      I confirmed that it is the same logger call by adding an AtomicInteger in message as follows:
      svn diff .
      Index: web-glue/src/main/java/com/sun/enterprise/web/WebContainer.java
      ===================================================================
      — web-glue/src/main/java/com/sun/enterprise/web/WebContainer.java (revision 43372)
      +++ web-glue/src/main/java/com/sun/enterprise/web/WebContainer.java (working copy)
      @@ -167,6 +167,7 @@
      * The current <code>WebContainer</code> instance used (single).
      */
      protected static WebContainer webContainer;
      + private static java.util.concurrent.atomic.AtomicInteger ac = new java.util.concurrent.atomic.AtomicInteger();

      /**
      * Are we using Tomcat deployment backend or DOL?
      @@ -857,7 +858,8 @@
      connector.setMapper(mapper);

      if (_logger.isLoggable(Level.INFO)) {
      - _logger.log(Level.INFO, "webContainer.HTTP.listenerAndPort", new Object[]{listener.getName(), listener.getAddress(), listener.getPort()}

      );
      + _logger.log(Level.INFO, "webContainer.HTTP.listenerAndPort", new Object[]

      {ac.getAndIncrement() + ":: " + listener.getName(), listener.getAddress(), listener.getPort()}

      );
      + Thread.currentThread().dumpStack();
      }

      connector.setName(listener.getName());

        Activity

        Hide
        naman_mehta added a comment -

        I couldn't understand your diff in the bug description. Can you give me more details on the same? Are you asking me to verify your diff?

        Show
        naman_mehta added a comment - I couldn't understand your diff in the bug description. Can you give me more details on the same? Are you asking me to verify your diff?
        Hide
        Shing Wai Chan added a comment -

        The diff in description above put an id in logger message so that one can distinguish different call of the logger in this case.

        Show
        Shing Wai Chan added a comment - The diff in description above put an id in logger message so that one can distinguish different call of the logger in this case.
        Hide
        naman_mehta added a comment -

        For this issue logging module is working fine. Logging module logs all messages as per the code.

        If you keep debug in WebContainer.java line number 857 which has below code.

        if (_logger.isLoggable(Level.INFO)) {
        _logger.log(Level.INFO, "webContainer.HTTP.listenerAndPort", new Object[]

        {listener.getName(), listener.getAddress(), listener.getPort()}

        );
        }

        Above line is executed multiple times with same data and looks like logging same data in server.log file. In turn it looks like logging issue but it's not logging issue. It's revisiting same code again and again which is causing this issue.

        To resolve this, log message only once in the code after whole operation is completed. Keep all log messages in some buffer and add unique data at the last. Your suggested solution works but doesn't look perfect to me.

        Show
        naman_mehta added a comment - For this issue logging module is working fine. Logging module logs all messages as per the code. If you keep debug in WebContainer.java line number 857 which has below code. if (_logger.isLoggable(Level.INFO)) { _logger.log(Level.INFO, "webContainer.HTTP.listenerAndPort", new Object[] {listener.getName(), listener.getAddress(), listener.getPort()} ); } Above line is executed multiple times with same data and looks like logging same data in server.log file. In turn it looks like logging issue but it's not logging issue. It's revisiting same code again and again which is causing this issue. To resolve this, log message only once in the code after whole operation is completed. Keep all log messages in some buffer and add unique data at the last. Your suggested solution works but doesn't look perfect to me.
        Hide
        Santiago Pericas-Geertsen added a comment -

        This is not a logging problem. There are two change events received by WebConfigListener.changed:114. The first is for the creation of the new HTTP listener. The second is to update the virtual server with the new list of HTTP listeners.

        The first event creates the new HTTP listeners and logs the action. The second event deletes and re-creates all of the listeners, including the one created by the first event. Suppose A and B are listeners in server S. When adding a new listener C, the log shows:

        (from first event change)
        created C
        (from second event change – delete and re-create)
        created A
        created B
        created C

        It appears the first event is triggering the second. Perhaps someone can comment on whether this behavior is different from earlier versions of GF.

        Show
        Santiago Pericas-Geertsen added a comment - This is not a logging problem. There are two change events received by WebConfigListener.changed:114. The first is for the creation of the new HTTP listener. The second is to update the virtual server with the new list of HTTP listeners. The first event creates the new HTTP listeners and logs the action. The second event deletes and re-creates all of the listeners, including the one created by the first event. Suppose A and B are listeners in server S. When adding a new listener C, the log shows: (from first event change) created C (from second event change – delete and re-create) created A created B created C It appears the first event is triggering the second. Perhaps someone can comment on whether this behavior is different from earlier versions of GF.
        Hide
        Shing Wai Chan added a comment -

        I do notice multiple call before filing this issue.
        The multiple call issue is filed on issue 15012.
        It was closed and have the status Santiago described.

        But in my debug, I have added an AtomicInteger in the code. In other words, each message is different. The following is a snapshot of previous log from Mac OS 10.5.8:

        [#|2010-12-03T14:59:57.185-0800|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=107;_ThreadName=pool-13-thread-1;|WEB0169: Created HTTP listener [4:: http-listener-2] on host/port [0.0.0.0:8181]|#]

        [#|2010-12-03T14:59:57.185-0800|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=17;_ThreadName=Thread-1;|WEB0169: Created HTTP listener [4:: http-listener-2] on host/port [0.0.0.0:8181]|#]

        Show
        Shing Wai Chan added a comment - I do notice multiple call before filing this issue. The multiple call issue is filed on issue 15012. It was closed and have the status Santiago described. But in my debug, I have added an AtomicInteger in the code. In other words, each message is different. The following is a snapshot of previous log from Mac OS 10.5.8: [#|2010-12-03T14:59:57.185-0800|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=107;_ThreadName=pool-13-thread-1;|WEB0169: Created HTTP listener [4:: http-listener-2] on host/port [0.0.0.0:8181] |#] [#|2010-12-03T14:59:57.185-0800|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=17;_ThreadName=Thread-1;|WEB0169: Created HTTP listener [4:: http-listener-2] on host/port [0.0.0.0:8181] |#]
        Hide
        Santiago Pericas-Geertsen added a comment -

        After further investigation, I was able to reproduce the message duplication problem shown in Shin Wai's comment. There are cases in which the exact same message is logged more than once. It looks like an issue in the logging module, but it's quite hard to debug due the blocking queues, threads, etc. Currently investigating the use of the blocking queue in class GFFileHandler.

        Show
        Santiago Pericas-Geertsen added a comment - After further investigation, I was able to reproduce the message duplication problem shown in Shin Wai's comment. There are cases in which the exact same message is logged more than once. It looks like an issue in the logging module, but it's quite hard to debug due the blocking queues, threads, etc. Currently investigating the use of the blocking queue in class GFFileHandler.
        Hide
        Shing Wai Chan added a comment -

        Sending src/main/java/com/sun/enterpris/web/WebContainer.java
        Sending src/main/java/com/sun/enterprise/web/logger/FileLoggerHandler.java
        Transmitting file data ..
        Committed revision 43827.

        Show
        Shing Wai Chan added a comment - Sending src/main/java/com/sun/enterpris/web/WebContainer.java Sending src/main/java/com/sun/enterprise/web/logger/FileLoggerHandler.java Transmitting file data .. Committed revision 43827.

          People

          • Assignee:
            Shing Wai Chan
            Reporter:
            Shing Wai Chan
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: