Keeping it Simple with Log4Fox

David Le Mesurier writes:

Hi Lisa,
I have been looking at your log4fox code as I want to instrument my applications.
Basically I want to be able to instrument them at a client’s site by setting an ini file setting to turn on the code.
I don’t want the user to have to do anything other than tick a box in my application’s preference form.
To log it to a table, what do I need to set in the application to:

A. Instantiate the logging object to log to the table

B. Make a call to the logging code.

I have looked at the sample prg, but I’m afraid that I can’t seem to get my head around what is needed.

And it’s no wonder

Sorry David, this is entirely my fault.

Not because the code I published had any bugs in it; it’s perfectly fine. But, when I wrote that article and published the test program, I was interested in showing the depth and breadth of a complex API, and maybe this doesn’t show you how you’d call the logging API in real life.

There were a couple of other details, now that I look at it, that could be improved or further explained, to help David use the API according to his specification:

I didn’t include an Appender class that logs to a Fox table. I did include a SQL Appender, but it addresses an external table using a handle to a SQL connection.
The SQL Appender I wrote didn’t (and I really didn’t have any reason for this, other than performance/efficiency) write individual rows to a table. It accumulated log events and then wrote the whole log to a text value (much like a stored version of the file you get from the File Appender) when you closed the log.

Maybe it wasn’t clear in the article that writing other Appenders and Formatter objects, if necessary, is really easy.

You’re not likely to need to write Formatters very often, but there isn’t much required if you do. To write an Appender, you really only have to implement one required method, as the article does explain: the .SendLog method that actually addresses your chosen output device.

In many cases you will also need to implement .OpenLog and .CloseLog. For each of these methods you’re going to consider: what does it mean to “open”, “close” and “send” information to my output type? How do these ideas apply?

The ideas of .Open and .Close don’t apply to every output type; for example an Appender that wrote to _SCREEN might decide to CLEAR the _VFP application window and set some font properties, or it might do nothing at all. But .Send applies to every output, because that is the point at which the log message gets rendered.

Hmmm. Anybody see a resemblance to ReportListener design questions here?

You don’t need to worry about anything else. The Logger maintains your Appenders and calls their .DoLog methods. You don’t need to touch the .DoLog method, which simply figures out whether the Appender is supposed to log this event, based on the level of log events it’s currently configured to handle. The Appender base class is going to take care of all the shared details for you. You only need to touch .SendLog, because your method of rendering the output device is specific to that device.

I’ll write a quick Fox Cursor Appender in this post, as a kind of a walkthrough for you.

The published test program instantiates many Appender objects to the Logger’s collection, to show you how they each handle log events according to their own output types and current logging level. This, by the way, is a real life scenario: it is perfectly normal to configure a file Appender to log verbosely while only sending Fatal-level events to an email Appender.

How does the Logger figure out what Appenders your user wants, and what their levels should be?

In the article, I addressed configuration by deriving a specialized class from Log4Fox, which I called Log4FoxConfigAlias. The idea here was that the logger would read a configuration table or cursor, to which you’d point it by telling it the alias containing this information.

The published test program creates that cursor on the fly, with a bunch of records holding instructions about different Appenders. Then it creates a Log4FoxConfigAlias Logger instance, and tells the new object about the cursor. The Log4FoxConfigAlias instance reads the cursor, adds the Appenders to its collection, and configures them, based on the records in that cursor.

David could use Log4FoxConfigAlias if he wants. In fact, he might even instantiate it on-the-fly, as I did, using information from his INI file. But he could also derive a different class, Log4FoxConfigFromINI, which would read his INI file directly.

In this blog-walkthrough, I won’t do either one. I’ll just use the ancestor Logger class, Log4Fox, which doesn’t know how to do any configuration. I’ll do some work in the calling program that you’ll have to imagine is being done by your startup code, or your Application object, or however you normally do this type of thing.

Sidebar: VFP Helper Object techniques

Again, I don’t want to over-complicate things here, but you may want to remember that all these objects are derived from an ancestor called VFPHelperObject.

This class’ raison d’être — which really has nothing to do with Log4Fox or log4j — is to help you integrate a library like this one into your overall application strategy.
VFPHelperObject expresses this principle by handing off error-handling behavior to its “owner object” — presumably your application object — so that its behavior matches the rest of your code when an error occurs.

In the calling program here, and in the published test program, I have to explicitly turn off that behavior, since there is no external owner object. But I hope you can see how useful this practice can be, when you’re assembling a full-scale application from a bunch of pre-built and externally-designed components.

Now for that walkthrough

David wants to know how to log to a table. Well, first you need an Appender that knows how to log to a (presumably Fox) table.

I didn’t write one of those before, so I’ll do one now, and this time it will log each event to a separate row in the table rather than writing the full log to a memo field, as I did in the SQL Appender before.

For this walkthrough I’ll specify as follows:

You tell the Appender where to log by telling it what alias to use. You also tell the Appender in what DataSession the Appender should find the LogAlias (I figure most people use an Application object with a private data session for work like this)
Because this Appender is writing separate rows to the table for each event, you should be able to find the Open and Close events in the table easily. However, we’ll add a member property to the Appender called LogRunName, because multiple instances of the application may be writing to the same table, and we’ll include this value in a separate column of the LogAlias table.
For this walkthrough, I’ll use GETENV(“UserName”) to distinguish rows between different users logging to a network table, which would work if the application was a singleton for each user — you could also generate a unique key for this purpose.
The Appender will expect, and validate, a LogAlias structure that looks like this:
CREATE CURSOR (THIS.LogAlias) ;
(event_run char(50), event_date datetime, event_log varchar(250))

Ready?

DEFINEing Class log4FoxCursorAppender AS log4FoxAbstractAppender

What will our new Appender class need to do? Well, it’s going to need a few member properties, matching our specification:

LogDataSession = 1
LogAlias = “EventLog”
LogRunName = “Log Run Name”

Remember what I said before? There’s definitely one method we have to implement: .SendLog. It will look like this:

PROTECTED PROCEDURE SendLog(whatever)
IF THIS.LogOpen
      LOCAL iSession
iSession = SET(“DATASESSION”)
      SET DATASESSION TO (THIS.LogDataSession)
INSERT INTO (THIS.LogAlias) VALUES ;
(THIS.LogRunName, DATETIME(), whatever)
SET DATASESSION TO (iSession)
   ENDIF
ENDPROC

… really only a few obvious lines of code.

You may think the check for .LogOpen is unnecessary (why isn’t this behavior somewhere else, like .DoLog in the ancestor class?). But some output destinations don’t really have a need for the concept of a log being opened at all. SQL Appender, for example, doesn’t care whether you’ve previously opened a log by checking for a handle; it can accumulate contents and open the log later, if it wants. What a log being “open” means, and whether you care about it, as well as at what moments you care about it, is highly dependent on output device, and therefore is handled by each Appender.

In this class, THIS.LogOpen means that the class has previously checked for its alias and either verified its structure or opened a cursor with the right structure, in the correct data session, of course.

So how do you suppose it does that? Let’s look at the rest of the class code, which is similarly straightforward:

PROCEDURE OpenLog()
* Let’s set some values here that probably
* aren’t useful to expose, since this
* class is always going to want them set
* a certain way.
* If you create a different Formatter (Layout)
* object you probably will have different need
THIS.Layout.IncludeDateTimeStamp = .F. && because this Appender
&& has a separate column for it
THIS.Layout.IncludeLogEvent = .T.

* in real life you would probably expose *this*
* one, or else generate a unique key for the run here:
THIS.LogRunName = “Log run: ” + GETENV(“UserName”)

   IF THIS.loglevel < LOGLEVEL_NONE
      LOCAL iSession, iSelect,iArea
iSession = SET(“DATASESSION”)
      SET DATASESSION TO (THIS.LogDataSession)
iSelect = SELECT(0)
iArea = SELECT(THIS.LogAlias)
IF iArea > 0 AND THIS.ValidateLogCursor(iArea)
         SELECT (THIS.LogAlias)
ELSE
IF iArea > 0
USE IN (iArea)
         ENDIF
SELECT 0
         CREATE CURSOR (THIS.LogAlias) ;
(event_run char(50), ;
event_date datetime, ;
event_log varchar(250))
      ENDIF
THIS .LogOpen = .T.
      SELECT (iSelect)
SET DATASESSION TO (iSession)
      THIS.DoLog(THIS.GetStandardLogOpenedMessage(),LOGLEVEL_INFO)
ENDIF
ENDPROC

PROTECTED PROCEDURE ValidateLogCursor(iArea)
   * validate to suit your needs
RETURN ;
   LEN(FIELD(“event_run”,iArea)) > 0 AND ;
LEN(FIELD(“event_date”,iArea)) > 0 AND ;
   LEN(FIELD(“event_log”,iArea)) > 0
ENDPROC

PROCEDURE CloseLog()
   IF THIS.LogOpen
      THIS.DoLog(THIS.GetStandardLogClosedMessage(),LOGLEVEL_INFO)
      * we won’t close the cursor, we’ll just indicate that
* something in the calling code decided to close the
* log at this moment. It isn’t necessarily the end
* of an application run; perhaps there is going to be
* some activity that doesn’t need to be logged.

* What will *your* class do when you decide it’s
* time to close the log?
* You might decide it’s a good time to
* run a report form on the log contents,
* if you are in LOGLEVEL_DEBUG…
* you might store the contents of the cursor
* to a SQL table…

* Of course you could perform that activity
* at a different time, using a separate
* public method.

THIS.LogOpen = .F.
ENDIF
DODEFAULT ()
ENDPROC

… and that’s the whole class.

Note: I will be adding this class to the log4fox.prg in the standard article download, and I will also add the code for the sample invocation of the class, that we’ll look at next.

How do we instantiate it at runtime?

David wants to know how to “instantiate the logging object to log to the table”.

You do that by creating a Log4Fox object (or a derived class, such as Log4FoxConfigAlias) and ensuring that it has an Appender in its collection that knows how to log to a table. (We have one of those now.)

If we’re using Log4FoxConfigAlias as our Logger object, as I did for the article, we can put a row in Log4FoxConfigAlias’s configuration table that says we want our new Appender. Log4FoxConfigAlias does this work in its Configuration_Assign method. As I explained in the article, it just has to instantiate each Appender object in its table and pass the Appender a reference to itself.

loX = CREATEOBJECT(ALLTRIM(logger), THIS)

… the Appenders know how to add themselves into the Logger’s collection. (Remember: these two object types are tightly coupled.)

Log4FoxConfigAlias passes other information to each Appender it creates, too, using information in its configuration table: for example, it tells each Appender what level of log events it should include.

If David writes a Log4FoxConfigINI derived class that looks in an INI file, it will do pretty much the same thing, using the INI file instead of a table for its resource.

However, David doesn’t really have to do that. He can use the ancestor class Log4Fox if he wants, and that’s what I’ve done in the simple DAVID_LOG4FOX.PRG:

loLogger = NEWOBJECT(“Log4Fox”,”Log4Fox.PRG”,””,NULL,.T.)
*&* but ordinarily this object would belong to an owner, like so:
*&* loLogger = CREATEOBJECT(“Log4Fox”,THIS.Application,.F.)

… and then he can (presumably, having read some information from his INI file externally) add the Appenders he’d like to use to his Logger object, and configure them as needed, like this:

NEWOBJECT(“log4foxEmailAppender”,”Log4Fox.PRG”,””,loLogger)
NEWOBJECT(“log4foxCursorAppender”,”Log4Fox.PRG”,””,loLogger) && new!

* read from configuration info here

* for now I’ll suggest some useful values that
* aren’t actually being read from anywhere, but
* obviously could be

* I am going to assume that David wants
* his application preference form
* to write to the INI with this or
* any other information this class needs, but
* I’ll skip that part too.

FOR EACH loX AS FoxOBJECT IN loLogger.Appenders
loX.SetLogLevel(LOGLEVEL_DEBUG)
ENDFOR

How do I log stuff?

This was David’s last question, and it’s probably so simple he just didn’t believe it.

You’ve got your Logger object, and you just tell it to log whenever you feel like it. You forget all about the mechanics about how each Appender will output the logging information, and how each Appender’s Formatter object will construct the information to be sent to the Appender’s output device.

You just instrument your code with calls that look like this:

loLogger.OPEN() && or MyApplicationObject.Logger.OPEN(), etc
loLogger.LOG(“This is a test at level LOGLEVEL_INFO”, LOGLEVEL_INFO)
loLogger.LOG(“This is a test at level LOGLEVEL_FATAL”, LOGLEVEL_FATAL)
loLogger.CLOSE()

… honestly, that’s all you have to do.

The .Open call will cause each of the Appenders to do whatever it needs to do to initialize a log run (some Appenders will need to do a lot of work, some will do none.)

The first .Log call above will be logged by any Appender that successfully initialized its device and is set to log events all the way down to the “info” level, which is pretty verbose.

The second .Log call above will be logged by pretty much any Appender that successfully initialized, considering that it’s hard to imagine wanting any Appender not wanting to include a “fatal” level event in its log.

Okay?

Did I leave anything out?

I did tell David that I generally use XML configuration files, rather than INIs or configuration tables. In a follow-up post, he asked me, “What sort of stuff does the xml config file contain”? Here’s a simple example:

<log4j:configuration xmlns:log4j=”http://jakarta.apache.org/log4j/”>

</log4j:configuration>
But I don’t have to explain it. You can read many, many, beautifully detailed explanations of the architecture written by other people about log4j, log4net, or any of the other variants, and get an idea of how such a configuration file exposes the API’s features; I really did follow the log4j principles in my VFP implementation, albeit in a simplified form.

Note: log4j also allows configuration programmatically, or by “property files”, which are similar to INIs. You can see an extensive example of a log4j property file here.

Have event-filled, and fully-loggable, fun.