Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-3480

Changed behaviour (regression) in 2.17.2 lookup plugin or string interpolation

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • 2.17.2
    • None
    • Core

    Description

      Something (breaking) changed in the way lookups and/or string interpolation is done, between versions 2.17.1 and 2.17.2.

      Our situation has some complexities (for historical reason):

      • we can use either a configuration via log4j2.xml file,
        or either the same config built programmatically
      • we have a custom lookup plugin. Let's call it "foo" for the purpose of illustration:

      @Plugin(name = "foo", category = "Lookup")

      The lookup has a few keys.

      • e.g.:   ${foo:version}   ,  ${foo:options}   ,  etc.
        (reason or underlying implementation doesn't matter here - something to do with context based on dynamic modules, threadgroups, etc)
      • The lookup also has the keys ${foo:header} and ${foo:footer} , which contains a larger snippet,   INCLUDING some of its other keys.
        e.g. (simplified adapted example)

      "Here some header text for version $${foo:version} at ** $${date} etc etc"

      These double $$ are important here , see further below.   

      Then we have in our <PatternLayout> configuration the following:
         <PatternLayout>
            <Pattern>... omitted here ...</Pattern<
            <Header>${foo:header}</Header>
            <Footer>${foo:footer}</Footer>
            
            
      As a result, each logfile is started with the well-defined header snippet (this string hard-coded inside the lookup plugin), but that header has some variable content (${foo:version}, ${foo:options}, ${date} ), which is substituted in turn. And each logfile is terminated by the foo:footer. Having this header and footer defined by the lookup ensures that the end-user easily configures them in the fixed header and footer in his log4j2.xml.

      Now in our application we also allow a programmatically built log configuration:
        builder.newLayout("PatternLayout")
           .addAttribute("header", HEADER)
           .addAttribute("header", FOOTER)
       whereby HEADER and FOOTER are the same strings as returned by our custom foo lookup plugin when it returns foo:header and foo:footer. (i.e. containing the double $$ inside)

      Why the double $$ ?
      We have these since many years: The double $$ ensure that the lookups included inside the header and footer (e.g. $${foo:version}, but also the $${date} ) are evaluated at the time that the logfile is actually being written !
      If instead we used a single $ inside the header and footer, the interpolation happened only 1x at time of configuration. Which is not what we want.
       e.g. when using a single $, then the timestamp in the header was stuck to the timestamp at the time that our application loaded the logging config. Whereas of course we'd want the timestamp to be current at the time the new logfile was created.
      If I remember well, the same was true for our custom lookup: to ensure it being re-evaluated at the time the logfile was written, we needed to use a double $$.

       

      Now this worked fine up until log4j 2.17.1.
      both with our programmatic configuration or when configured via log4j2.xml

      This still works in log4j 2.17.2 when we are running with our programmatically built configuration:

      However, in log4j 2.17.2 this no longer works when the configuration is taken from the log4j2.xml file.
      In that case, the expansion of double $${...} no longer works.
      Instead, it just prints something like:  "Here some header text for version ${foo:version} at ${date} etc"
      i.e. the double $$ is substituted by a single $ now, but now no further substitution are done. Not at load time, not later at write time.
      On the other hand, when in the header string, I now use $ inside $$, then this now suddenly works in the log4j2.xml-based configuration with substitution at write-time. Which is clearly a different behavior than up to log4j 2.17.1. And is also a different behavior than the programmatic configuration.

       

      So there's clearly something has changed  unexpectedly in log4j 2.17.2...

      I don't know which change or jira issue may have caused it ?
      Could it have something to do with, which did some changes in the string interpolation? LOG4J2-3424 ?
      Or can it be related to e.g. LOG4J2-3470 ?
      Something else?

          
      I did try using the 2.17.3-SNAPSHOT, but I am still seeing the changed 2.17.2 behavior there...

      Attachments

        Activity

          People

            Unassigned Unassigned
            belpk K P
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated: