Log4j 2
  1. Log4j 2
  2. LOG4J2-378

Logging generates file named ${sys on some systems

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta8, 2.0-beta9
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:

      Issues occurs on Win7/64 system under Tomcat 7.0.42 / Oracle JDK 1.7.0_25; fails to occur on RHEL 5.2 system under Tomcat 7.0.26 / Oracle JDK 1.7.0_03

      Description

      In a webapp I'm setting a system property in my apps ServletContextListener, and using that system property in my log4j2.xml file, like so:

      <appender type="FastFile" name="File" fileName="${sys:catalina.home}/logs/${sys:application-name}.log">
      

      On my Windows machine, a log file named "${sys." (always 0 bytes) is being created instead of a log file with the application-name. The same war deployed on one of our linux servers does not create a ${sys." file and instead creates a log file with the intended application-name.

      I should note that the files DO appear in the directory that sys:catalina.home should resolve to. They appear elsewhere when I don't use sys:catalina.home so I'm quite sure that this variable is resolving correctly and it is the sys:application-name which is the problem.

        Activity

        Hide
        Eric Schwarzenbach added a comment - - edited

        What I suspect is happening is that my app's ServletContextListener contextInitialized method is getting called before Log4jServletContextListener's on the server (where the problem does not occur), but that they are getting called in the opposite order on my local machine (where the problem does occur). sys:catalina.home does not depend on my app's ServletContextListener contextInitialized method being called before Log4jServletContextListener's but sys:application-name, I believe, does.

        The javadoc seems to suggest that the intention is for it Log4jServletContextListener's to always occur first. This raises several issues:

        1) Is the fact that they get called in different orders on different machines a failure of (some version / implementation of) Tomcat to call them in the right order? Or a failure of the log4j code to ensure things are set up so as to guarantee this order? Or is the order even specified and guarranteeable?

        2) Is Log4jServletContextListener's contextInitialized being called first necessarily desirable? If Log4jServletContextListener always gets called before the application's context listener, how is a web application to set up variables for use in the log4j configuration, particularly, for example (which is what I am doing), to get the webapp's name from the servlet context path to name the log files? Is there some better way to do this? (Ideally without requiring configuration to be loaded twice...which is what I ended up happening with logback when I tried to set it up to do this same thing.)

        According to the servlet spec "The Web container registers the listener instances according to the interfaces they implement and the order in which they appear in the deployment descriptor. During Web application execution, listeners are invoked in the order of their registration." Since Log4jServletContextListener doesn't appear in my web.xml, I assume it should call them "according to the interfaces they implement". I have no idea what that is supposed to mean, though.

        Show
        Eric Schwarzenbach added a comment - - edited What I suspect is happening is that my app's ServletContextListener contextInitialized method is getting called before Log4jServletContextListener's on the server (where the problem does not occur), but that they are getting called in the opposite order on my local machine (where the problem does occur). sys:catalina.home does not depend on my app's ServletContextListener contextInitialized method being called before Log4jServletContextListener's but sys:application-name, I believe, does. The javadoc seems to suggest that the intention is for it Log4jServletContextListener's to always occur first. This raises several issues: 1) Is the fact that they get called in different orders on different machines a failure of (some version / implementation of) Tomcat to call them in the right order? Or a failure of the log4j code to ensure things are set up so as to guarantee this order? Or is the order even specified and guarranteeable? 2) Is Log4jServletContextListener's contextInitialized being called first necessarily desirable? If Log4jServletContextListener always gets called before the application's context listener, how is a web application to set up variables for use in the log4j configuration, particularly, for example (which is what I am doing), to get the webapp's name from the servlet context path to name the log files? Is there some better way to do this? (Ideally without requiring configuration to be loaded twice...which is what I ended up happening with logback when I tried to set it up to do this same thing.) According to the servlet spec "The Web container registers the listener instances according to the interfaces they implement and the order in which they appear in the deployment descriptor. During Web application execution, listeners are invoked in the order of their registration." Since Log4jServletContextListener doesn't appear in my web.xml, I assume it should call them "according to the interfaces they implement". I have no idea what that is supposed to mean, though.
        Hide
        Ralph Goers added a comment -

        Your interpretation of the problem seems correct. Since the variable couldn't be found the string itself would be used. But since a ":" isn't allowed in a file nane on Windows it looks like it truncated the name to "${sys", although I am not sure why it would be "${sys.".

        As you noted, the order that the listeners are invoked is specified in the servlet spec so I don't know why there would be a difference between the behavior on Windows vs Linux.

        Is it possible for you to just add the -Dapplication-name to setenv.sh?

        Show
        Ralph Goers added a comment - Your interpretation of the problem seems correct. Since the variable couldn't be found the string itself would be used. But since a ":" isn't allowed in a file nane on Windows it looks like it truncated the name to "${sys", although I am not sure why it would be "${sys.". As you noted, the order that the listeners are invoked is specified in the servlet spec so I don't know why there would be a difference between the behavior on Windows vs Linux. Is it possible for you to just add the -Dapplication-name to setenv.sh?
        Hide
        Eric Schwarzenbach added a comment -

        Sorry is it really is just "${sys" and not "${sys." I must have made a cut and paste error.

        > Is it possible for you to just add the -Dapplication-name to setenv.sh?

        No, because there are multiple webapps on the server. The actual purpose behind what I am doing is to have multiple apps, even multiple copies of this particular app (copies of same war deployed with different names as different apps) each logging to files prefixed with the webapp name to make them distinguishable.

        It seems not unlikely that one or more version of tomcat just has a bug that causes it to run these methods in the wrong order. And I can explore that and pursue getting a newer version installed. However I want to address those two broader issues first, since I might have to change how I'm doing this in a way that this becomes moot:

        1) what really does the servlet spec dictate should happen here? (See the last para of me previous comment...what does "according to the interfaces they implement" mean?

        2) If the spec does dictate something about the order that log4j can control...should the log4j contextInitialized come first?

        If so then what I'm trying to do won't work...the fact that it works on one server is itself the bug. In which case is there some other way I can accomplish this? I realize that is kind of outside the scope of this bug, except that the consideration of making use cases like this one impossible could be a consideration for answering or reconsidering question 2.

        Show
        Eric Schwarzenbach added a comment - Sorry is it really is just "${sys" and not "${sys." I must have made a cut and paste error. > Is it possible for you to just add the -Dapplication-name to setenv.sh? No, because there are multiple webapps on the server. The actual purpose behind what I am doing is to have multiple apps, even multiple copies of this particular app (copies of same war deployed with different names as different apps) each logging to files prefixed with the webapp name to make them distinguishable. It seems not unlikely that one or more version of tomcat just has a bug that causes it to run these methods in the wrong order. And I can explore that and pursue getting a newer version installed. However I want to address those two broader issues first, since I might have to change how I'm doing this in a way that this becomes moot: 1) what really does the servlet spec dictate should happen here? (See the last para of me previous comment...what does "according to the interfaces they implement" mean? 2) If the spec does dictate something about the order that log4j can control...should the log4j contextInitialized come first? If so then what I'm trying to do won't work...the fact that it works on one server is itself the bug. In which case is there some other way I can accomplish this? I realize that is kind of outside the scope of this bug, except that the consideration of making use cases like this one impossible could be a consideration for answering or reconsidering question 2.
        Hide
        Ralph Goers added a comment - - edited

        To get the webapp name you could do

        <appender type="FastFile" name="File" fileName="${sys:catalina.home}/logs/${web:servletContextName}.log">
        

        Note that the web lookup was recently added and will be in beta9. You can test it in trunk.

        Show
        Ralph Goers added a comment - - edited To get the webapp name you could do <appender type= "FastFile" name= "File" fileName= "${sys:catalina.home}/logs/${web:servletContextName}.log" > Note that the web lookup was recently added and will be in beta9. You can test it in trunk.
        Hide
        Eric Schwarzenbach added a comment -

        Thanks, Ralph. I've now tried this out with beta9, and now it creates a 0 byte file named "${web" (on Win7/64 / 7.0.42 / Oracle JDK 1.7.0_40-b43). It does also create (and log to) a file named from the display-name in my web.xml, like "My Web Application.log". I was looking for the actual name it was deployed to...for example if it deployed to TOMCAT_HOME/webapps/myapp and I was accessing it at someserver.com/myapp, I'd like to see "myapp.log". Is there another web: variable that might do that?

        Show
        Eric Schwarzenbach added a comment - Thanks, Ralph. I've now tried this out with beta9, and now it creates a 0 byte file named "${web" (on Win7/64 / 7.0.42 / Oracle JDK 1.7.0_40-b43). It does also create (and log to) a file named from the display-name in my web.xml, like "My Web Application.log". I was looking for the actual name it was deployed to...for example if it deployed to TOMCAT_HOME/webapps/myapp and I was accessing it at someserver.com/myapp, I'd like to see "myapp.log". Is there another web: variable that might do that?
        Hide
        Eric Schwarzenbach added a comment - - edited

        What happens on Ubuntu seems to be slightly different. The 0 byte file created there is "${web:servletContextName}.log" (I suppose just because the : is more acceptable there than on windows). But in addition to that I am getting a log file being created with the display-name (e.g. "My Web Application.log") AND with the context name (e.g. "myapp.log").

        Show
        Eric Schwarzenbach added a comment - - edited What happens on Ubuntu seems to be slightly different. The 0 byte file created there is "${web:servletContextName}.log" (I suppose just because the : is more acceptable there than on windows). But in addition to that I am getting a log file being created with the display-name (e.g. "My Web Application.log") AND with the context name (e.g. "myapp.log").
        Hide
        Eric Schwarzenbach added a comment -

        It looks like the "myapp.log" file was somehow being caused by a different webapp. Something really odd is going on here. I had two webapps deployed, one was a previous iteration of the same app (still using log4j beta8, and still logging to "...${sys:application-name}.log". Getting rid of the old webapp causes "myapp.log" to no longer be created. Note the the old webapp did not have the name "myapp" anywhere in it at all, that was completely new to this new build of my app.

        Further though the same messages were logged in "My Web Application.log" and "myapp.log" the format was slightly different. While "My Web Application.log" had lines like:

        2013-09-23 15:39:39,644 INFO a.b.c.d.SomeServiceImpl [pool-2-thread-1] SomeServiceImpl created

        "myapp.log" had lines like

        2013-09-23 15:39:51,419 INFO ? [pool-2-thread-1] SomeServiceImpl created

        I'm not making this stuff up, I promise!

        Show
        Eric Schwarzenbach added a comment - It looks like the "myapp.log" file was somehow being caused by a different webapp. Something really odd is going on here. I had two webapps deployed, one was a previous iteration of the same app (still using log4j beta8, and still logging to "...${sys:application-name}.log". Getting rid of the old webapp causes "myapp.log" to no longer be created. Note the the old webapp did not have the name "myapp" anywhere in it at all, that was completely new to this new build of my app. Further though the same messages were logged in "My Web Application.log" and "myapp.log" the format was slightly different. While "My Web Application.log" had lines like: 2013-09-23 15:39:39,644 INFO a.b.c.d.SomeServiceImpl [pool-2-thread-1] SomeServiceImpl created "myapp.log" had lines like 2013-09-23 15:39:51,419 INFO ? [pool-2-thread-1] SomeServiceImpl created I'm not making this stuff up, I promise!
        Hide
        Eric Schwarzenbach added a comment -

        It occurs to me that configuration element name attribute was the same in the log4j2.xml files of the two webapps. Might that cause some...confusion between the two? The "SomeServiceImpl created" message could have come from either app, and given the timestamp differences, it makes me think the myapp.log message was coming from the first app, however it was just picking up the sys:application-name set by myapp.

        Show
        Eric Schwarzenbach added a comment - It occurs to me that configuration element name attribute was the same in the log4j2.xml files of the two webapps. Might that cause some...confusion between the two? The "SomeServiceImpl created" message could have come from either app, and given the timestamp differences, it makes me think the myapp.log message was coming from the first app, however it was just picking up the sys:application-name set by myapp.
        Hide
        Eric Schwarzenbach added a comment -

        Bump...

        I know I noted some mistakes in my first comments about the bug still existing in beta9, but the basic problem still occurs:

        using $

        {web:servletContextName}

        .log in an appender file name still winds up creating a 0 byte file named $

        {web:servletContextName}

        .log (under linux), and it also creates one using the value from the display-name element of the web.xml rather than the name of the war file / webapp folder.

        Show
        Eric Schwarzenbach added a comment - Bump... I know I noted some mistakes in my first comments about the bug still existing in beta9, but the basic problem still occurs: using $ {web:servletContextName} .log in an appender file name still winds up creating a 0 byte file named $ {web:servletContextName} .log (under linux), and it also creates one using the value from the display-name element of the web.xml rather than the name of the war file / webapp folder.
        Hide
        Maksym Kurdyukov added a comment - - edited

        Similar problem with:

        <RollingRandomAccessFile name="rolling-file" fileName="${sys:log.dir}/service.${date:yyyy-MM-dd}.log">
        

        I've defined log.dir system variable and it was resolved, but not 'date'.
        Debug shows me using of org.apache.logging.log4j.core.lookup.Interpolator which was created by default (without 'date' lookup plugin).
        I'm not familiar with internal design of log4j2. Can I use 'date' lookup plugin in patterns not related to log messages?

        Impl. version: 2.0-beta9

        Show
        Maksym Kurdyukov added a comment - - edited Similar problem with: <RollingRandomAccessFile name= "rolling-file" fileName= "${sys:log.dir}/service.${date:yyyy-MM-dd}.log" > I've defined log.dir system variable and it was resolved, but not 'date'. Debug shows me using of org.apache.logging.log4j.core.lookup.Interpolator which was created by default (without 'date' lookup plugin). I'm not familiar with internal design of log4j2. Can I use 'date' lookup plugin in patterns not related to log messages? Impl. version: 2.0-beta9
        Hide
        Ralph Goers added a comment -

        Added date and ctx to default interpolator in revision 1572722. Please verify and close. System properties were added to the default interpolator in revision 1517427.

        Show
        Ralph Goers added a comment - Added date and ctx to default interpolator in revision 1572722. Please verify and close. System properties were added to the default interpolator in revision 1517427.
        Hide
        Christopher Thielen added a comment -

        I'm still seeing this behavior with one Maven+Spring project through Eclipse (but not the other) both using log4j2 version 2.0.2.

        Show
        Christopher Thielen added a comment - I'm still seeing this behavior with one Maven+Spring project through Eclipse (but not the other) both using log4j2 version 2.0.2.

          People

          • Assignee:
            Unassigned
            Reporter:
            Eric Schwarzenbach
          • Votes:
            2 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development