7

We use log4j 1.2.x for logging in our product and are looking to migrate to log4j 2.x in near future. One of the functionality we have implemented is to log the system information and other important parameters on every new roll-over logfile that gets generated. The way we implemented in log4j 1.2.x is that we have extended RollingFileAppender class of log4j and have overridden the rollOver() method, below is the part snippet of the implementation

@Override
public void rollOver() {

    super.rollOver(); //We are not modifying it's default functionality but as soon as rollOver happens we apply our logic 

    // 
    // Logic to log required system properties and important parameters.
    //

}

Now as we want to migrate to log4j2 we are looking at a new solution to achieve same functionality. But as I see the source code for log4j2 it is very different from older source code. The RollingFileAppender class does not contain rollover() method as it has been moved to RollingManagerhelper and it has been set to private as-well.

Developing a complete new package and extending/implementing some abstract/helper classes from log4j2 is one of the possible solution for us but that would require a lot of coding/copying as we do not modify what RollingFileAppender does rather we only need small extension to it. Is there a simple solution to it?

UPDATE

I created a custom lookup according to the suggestion in answers and below is how I created it;

@Plugin(name = "property", category = StrLookup.CATEGORY)
public class CustomLookup extends AbstractLookup {

private static AtomicLong aLong = new AtomicLong(0);

@Override
public String lookup(LogEvent event, String key) {

    if (aLong.getAndIncrement() == 0) {
        return "this was first call";
    }
    if (key.equalsIgnoreCase("customKey")) {
        return getCustomHeader();
    } else {
        return "non existing key";
    }
}

private static String getCustomHeader() {

    // Implementation of custom header
    return "custom header string";

}}

But this did not work as mentioned; this always prints this was first call in the header. I also tried putting breakoint on the first if condition and what I noticed was that it only gets called once. So what I fear is that the customLookup class only gets initialized on the startup when log4j2 is initialising its properties from xml config. I don't know how else I could implemented this custom lookup class.

UPDATE 2

After the above implementation I tried it in bit different way which is as below;

private static AtomicLong aLong = new AtomicLong(0);

@Override
public String lookup(LogEvent event, String key) {
    return getCustomHeader(key);
}

private static String getCustomHeader(final String key) {

    if (aLong.getAndIncrement() == 0) {
        return "this was first call";
    }
    if (key.equalsIgnoreCase("customKey")) {
        // Implementation for customKey
        return "This is custom header";
    } else {
        return "non existing key";
    }
}

But this does the same thing as-well. log4j2 creates the headers at while initialising from its xml config file and then uses the headers from memory. The return value of overridden lookup() method can not be changed dynamically as it only gets called during initialisation. Any more help would be highly appreciated.

Remko Popma
  • 35,130
  • 11
  • 92
  • 114
madteapot
  • 2,208
  • 2
  • 19
  • 32
  • 1
    If you want to use runtime variable substitution use double $$ when specifying variable key in log4j2 properties file. – TrueCurry May 26 '15 at 13:22

2 Answers2

9

An alternative to using the built-in lookups is to create a custom lookup. This can be accomplished in a few lines of code with a log4j2 plugin. Your custom lookup then provides the exact value you want to show in the file header at each roll over.

The plugin code would look something like this:

package com.mycompany;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.lookup.AbstractLookup;
import org.apache.logging.log4j.core.lookup.StrLookup;

/**
 * Looks up keys from a class SomeClass which has access to all
 * information you want to provide in the log file header at rollover.
 */
@Plugin(name = "setu", category = StrLookup.CATEGORY)
public class SetuLookup extends AbstractLookup {

    /**
     * Looks up the value of the specified key by invoking a
     * static method on SomeClass.
     *
     * @param event The current LogEvent (ignored by this StrLookup).
     * @param key  the key to be looked up, may be null
     * @return The value of the specified key.
     */
    @Override
    public String lookup(final LogEvent event, final String key) {
        return com.mycompany.SomeClass.getValue(key);
    }
}

Then, in your configuration you can use the header of the pattern layout to output this at every rollover:

<RollingFile name="RollingFile" fileName="logs/app.log"
             filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}.log.gz">

  <!-- use custom lookups to access arbitrary internal system info -->
  <PatternLayout header="${setu:key1} ${setu:key2}">
    <Pattern>%d %m%n</Pattern>
  </PatternLayout>
  <Policies>
    <TimeBasedTriggeringPolicy />
  </Policies>
</RollingFile>

The log4j2 manual has details on building/deploying custom plugins. Brief summary:

The easiest way is to build your jar with Maven; this will cause the log4j2 annotation processor to produce a binary index file in the jar so your plugin can be found quickly by log4j2.

The alternative is to specify the package name of your plugin class in your log4j2.xml configuration's packages attribute:

<Configuration status="warn" packages="com.mycompany">
  ...

UPDATE: Note that in your lookup implementation you can get as creative as necessary. For example:

package com.mycompany;

public class SomeClass {
    private static AtomicLong count = new AtomicLong(0);

    public static String getValue(final String key) {
        if (count.getAndIncrement() == 0) { // is this the first call?
            return ""; // don't output a value at system startup
        }
        if ("FULL".equals(key)) {
            // returns info to shown on rollover, nicely formatted
            return fullyFormattedHeader();
        }
        return singleValue(key);
    }
    ....
}
Remko Popma
  • 35,130
  • 11
  • 92
  • 114
  • Of course feel free to use a different plugin name than `setu`. :-) – Remko Popma Dec 11 '14 at 08:56
  • looks promising. will give it a try – madteapot Dec 11 '14 at 14:36
  • I gave it a try but two problems one is that the key in the header attribute needs to be completely formatted as required to be logged, eg. if using more than one key in the header there is no way to separate in different lines. Second is major problem, the requirement is to print system properties at the start of new rollover file not at the start of program execution. header is logged at the start of each execution and at each rollover which simply doesn't make sense. – madteapot Dec 11 '14 at 16:52
  • I updated my answer with suggestions for how one could solve the issues you raised. As for alternative solutions, as you noted in the question, trying to subclass `RollingFileAppender` would be a very cumbersome way to do this. Long-term it may be a good idea to raise a feature request for a more extendable/customizable rollover mechanism on the Log4j2 Jira issue tracker. Right now, I do believe that using a lookup in the header is the simplest solution. It should be possible to solve any issues in the `SomeClass.getValue()` implementation. – Remko Popma Dec 12 '14 at 00:47
  • Given that this is the best solution (but not enough) I would award the bounty to you but keep the question open. Its a shame such a simple functionality is not available in very popular library. But thanks for your help.. – madteapot Dec 12 '14 at 12:31
  • Thank you for the bounty. I thought I addressed all the issues you raised. What is missing that would allow you to close this question? – Remko Popma Dec 13 '14 at 12:24
  • I think you misunderstood the requirement. The requirement is to log system properties at the rollover of each log file (not everytime the program is run). now in our logging proerties we specify log files to be of 10MB. But using the header attribute of log4j2 properties it logs the header everytime the program starts (this is what we don't want) and at the start of each new rollover logfile (this is what we want). – madteapot Dec 13 '14 at 18:14
  • Did you see my update? I showed how one can use a counter to avoid generating any output the first call (program startup) and only generate output on subsequent calls (rollover). Did this not work as expected? – Remko Popma Dec 14 '14 at 04:37
  • Hi thank you very much for the updated answer. I gave it a try but it did not work as expected. Please refer to the update part in my question. Once again I really appreciate your help. – madteapot Dec 15 '14 at 09:52
  • Thanks for the update. This is not expected: I expect the header to do a lookup at every rollover, without this value being cached anywhere. Let's follow up in the Log4j2 Jira ticket https://issues.apache.org/jira/browse/LOG4J2-921 – Remko Popma Dec 16 '14 at 05:22
  • Hi Remko. I tried with 2 `$` in the header attribute as mentioned in comment on the Jira ticket and it worked as expected. It does not print the header on first startup but prints it on rollover. But I am wondering, as a user how am I to know that I should have used 2 `$`s but anyway you went out of your way to help and thank you ever so much for this. :) – madteapot Dec 16 '14 at 09:26
  • Hi Remko i have created a fully working lookup class and have tested it as working, thank you very much for that. I am now looking to improve performance of this lookup and have posted a question on codeReview http://codereview.stackexchange.com/questions/74172/is-this-approach-in-constructing-a-long-string-correct-what-is-better-way-to-ac . If you don't mind and have any advice for making it more efficient please let me know by answer or comment on there. Thank you once again. – madteapot Dec 19 '14 at 14:48
2

This can be accomplished with configuration. You can use the header of the pattern layout to output information. This will be included at every rollover.

<RollingFile name="RollingFile" fileName="logs/app.log"
             filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}.log.gz">

  <!-- use built-in lookups for system info or system properties -->
  <PatternLayout header="${java:runtime} - ${java:vm} - ${java:os}">
    <Pattern>%d %m%n</Pattern>
  </PatternLayout>
  <Policies>
    <TimeBasedTriggeringPolicy />
  </Policies>
</RollingFile>
Remko Popma
  • 35,130
  • 11
  • 92
  • 114
  • Thank you for the response @Remko but one question. The product we have is huge and we setup multiple system properties at runtime, basically it is an engine that runs continuously on server and interacts with webservice, gui tools and db at backend. using this approach we need to write all the property names precisely in header. Is there any way of using some kind of loop to include all system properties in header. – madteapot Dec 04 '14 at 08:43
  • You could configure a single system property in the header and programmatically update the value of that property by appending the values of all other system properties you are interested in, would that work? – Remko Popma Dec 05 '14 at 00:16
  • Thanks for the suggestion; I will have to give it a try but that means whenever in my code I set any system property I will have to add it to this system property. Sound like it would work but I think this would be considered as workaround by the management and not an actual solution. thanks for your suggestion anyway – madteapot Dec 05 '14 at 08:47