Logging using log4j

[Jon]

This describes how to add log4j logging to your scripts. This is a very flexible Java logging package that provides many advantages including:

1. Ability to set the logging level dynamically at runtime without changing your scripts i.e. you can write debug logging into scripts then activate it when you need to, and only for selected scripts.
2. Ability to write to log files or the console or both.
3. Formatted log messages.
4. Multi-user access without file locking problems.
5. Once configured, it can be used by all scripts with the ability to control debugging messages by script, form, project etc.
6. The ability to wrap log files i.e. to stop them growing indefinitely.
7. It's pretty much a de facto standard and is used throughout the Java world.

See http://logging.apache.org/log4j for details.

Here are the steps to configure log4j for use by Ebase scripts:

Step 1: configure the log4j properties file
You only need to do this step once only, then it can be used by all scripts.

Edit file UfsServer/tomcat/webapps/xxx/WEB_INF/classes/log4j.xml on the server and add the following at the bottom, but before the ending </log4j:configuration> tag:

Code: Select all

<appender name="scriptsLog" class="org.apache.log4j.FileAppender">
    <param name="file" value="../logs/ebasescripts.log" />
    <param name="append" value="false" />
    <param name="threshold" value="debug" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d &#91;%t&#93; %-5p %c - %m%n"/>
    </layout>
</appender>

<logger name="ebforms" additivity="false">
    <level value="ALL" />
    <appender-ref ref="scriptsLog"/>
</logger>

This creates an appender, which specifies where the logs are written to; this example writes everything to file ebasescripts.log in the tomcat/logs folder. Note, if you start Ebase as a service you may need to change this to an absolute file path.

It also creates a logger, which is the component that actually does the logging - we will be using this logger from the scripts. The logger names are hierarchical: this one is named "ebforms" and it will be used by anything that requests a logger beginning with this name e.g. a request for a logger "ebforms.project1.script23" will also use this logger. This hierarchical behaviour is one of the features that makes log4j so flexible, hopefully it will become a bit clearer in a moment.

Step 2: restart the server
This is unfortunately necessary and activates the log4j configuration just created.

Step 3: add logging to your scripts
To do this, add the following two lines to each script where you want to use logging:

Code: Select all

importPackage(org.apache.log4j);
var logger = Logger.getLogger("ebforms.project1.js1c");

I suggest a naming convention of ebforms.<PROJECTNAME>.<SCRIPTNAME> but this can be anything you like. So long as this name begins with "ebforms." it will use the logger we configured above.

You can then create a log message with any of the following.

Code: Select all

logger.debug("A debug message");
logger.info("An info message");
logger.error("An error message");
logger.log(Level.INFO, "Another message");

As you can see, log messages have a level - debug, info, error etc (there are quite a few more) - and these levels are also hierarchical. If you activate logging at debug level, all messages will be logged (as debug is the lowest level); but if you activate logging at info level, only info and higher messages (which includes error) will be logged. You specify what level you want to record at any time by changing the Level parameter in the log4j logger e.g.

<level value="INFO" />

That's all you need to start logging with log4j.

[Jon]

This is how to turn on debug logging for just one script, while leaving all others logging at error level. Add an additional logger like this:

Code: Select all

<logger name="ebforms" additivity="false">
    <level value="ERROR" />
    <appender-ref ref="scriptsLog"/>
</logger>

<logger name="ebforms.project1.script23" additivity="false">
    <level value="DEBUG" />
    <appender-ref ref="scriptsLog"/>
</logger>

The first logger is our default that applies to all scripts and specifies only ERROR message logging. The second logger specifies DEBUG message logging and is used by a logger requesting this explicit name:

Code: Select all

var logger = Logger.getLogger("ebforms.project1.script23");

[Jon]

Here's an example of a rolling file appender - it will wrap once the max size (50MB) is reached. Replace the file appender in the log4j.xml file with this one to implement.

Code: Select all

<appender name="scriptsLog" class="org.apache.log4j.RollingFileAppender">
    <param name="file" value="../logs/ebasescripts.log" />
    <param name="append" value="false" />
    <param name="MaxFileSize" value="50MB" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d &#91;%t&#93; %-5p %c - %m%n"/>
    </layout>
</appender> 

[Steve James]

Hi Jon, that's great thanks.

I've found that I need to restart Tomcat if I make a change to log level in log4j.xml, is there a way around this?

Couple of suggestions for future versions of Ebase.
1 - when creating a new js script it would be good to have the lines automatically imported including the default loggername.

Code: Select all

importPackage(org.apache.log4j); 
var logger = Logger.getLogger("ebforms.project.script");

2 - Most of our forms still have FPL scripts so tracing logs isn't too time consuming. Our form writers have started using JS and use log('blurb'); a lot. It would be good if the log statement automatically adds the scriptname to the log entry. This would make tracing easier.

Thanks

[Jon]

Steve,

Unfortunately the restart is unavoidable at the moment. We are planning to introduce some sort of log4j built-in support in V5.0, and at that point we'll try and avoid the restart. We'll also try and add the script name to each log entry in V5.0.

Regards
Jon

[LKirby]

Hi Jon,

I was just thinking about what Steve said about including

Code: Select all

importPackage(org.apache.log4j); 
var logger = Logger.getLogger("ebforms.project.script");

on every new script created and I was wondering if something like this was possible in v5 if there was an option to further Steve's idea by being able to customise the default 2 lines added to every script as I'd think many people are always adding a few common lines to every script created. For example, I usually find myself having something this at the start of every script:

Code: Select all

importPackage(com.ebasetech.xi.api);
importPackage(com.ebasetech.xi.services);
importPackage(org.apache.log4j);

var logger = Logger.getLogger("ebforms.project.script");

var eo = event.owner,
sm = system.securityManager;

// Script comment on what what it does

[Jon]

OK noted. We haven't gotten around to looking at more logging options in V5 but it hasn't been forgotten.

Regards
Jon

[Segi]

I added that code at the bottom of UfsServer/tomcat/webapps/UFS/WEB_INF/classes/log4j.xml right before the closing /log4j:configuration tag and restarted eBase. I get this warning when starting up the server and logging doesn't work:

Code: Select all

log4j:WARN Continuable parsing error 54 and column 23
log4j:WARN The content of element type "log4j:configuration" must match "(renderer*,throwableRenderer?,appender*,plugin*,(category|logger)*,root?,(categoryFactory|loggerFactory)?)".

[Jon]

I don't think the warning messages on the server log stop it from working - I have these on my system too. If you can't get it to work can you add your script code to this log. Add the log4j config as well if it's not the same as the example.

Regards
Jon

[Segi]

Jon,

I used the log4j code exactly as provided above

Code: Select all

<appender>
    <param>
    <param>
    <param>
    <layout>
        <param>
    </layout>
</appender>

<logger>
    <level>
    <appender>
</logger>

I used this in a script:

Code: Select all

importPackage(org.apache.log4j);

var logger = Logger.getLogger("ebforms.project1.js1c");
logger.debug("A debug message"); 
logger.info("An info message"); 

no output is written to the file

[Jon]

OK, I assume that your log4j looks like this:

<appender name="scriptsLog" class="org.apache.log4j.FileAppender">
<param name="file" value="../logs/ebasescripts.log" />
<param name="append" value="false" />
<param name="threshold" value="debug" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/>
</layout>
</appender>

<logger name="ebforms" additivity="false">
<level value="ALL" />
<appender-ref ref="scriptsLog"/>
</logger>

Can you check that the ebasescripts.log file is created in UfsServer/tomcat/logs as soon as you start the server - it will be empty initially. On my Windows system this file is created in UfsServer/tomcat/logs because the home directory is UfsServer/tomcat/bin and the file location in log4j.xml is ../logs/ebasescripts.log. If this file does not exist in UfsServer/tomcat/logs on your system, I suggest you have a look around and see if it's been created somewhere else - this will be the case if your home directory is different. In particular if you start Ebase as a service, the home directory will be different.

If this is indeed the problem, you can always change the log4j.xml file to provide an absolute file path instead of a relative path.

Everything else looks OK.

Regards
Jon

[Segi]

Jon,

The file is created in logs/ebasescripts.log when I start the server and is empty, even after I write to it

Update: I figured out why it wasn't working and it is fixed now.

[Jon]

Hmm, well there isn't much else that can go wrong.

The name specified in the Logger.getLogger() statement must begin with the string specified in the log4j.xml logger i.e. ebforms.
Other than that the level specified in the logger in log4j.xml should be All.

One more thing you might try. Change the appender-ref in log4j.xml so it says ref="SYSLOG" instead of ref= "scriptsLog", then restart the server. Your logging messages should now come out in the console window instead of going to the file. This tests that your script code is correct and that log4j is working OK.

Regards
Jon