Using Lua for Log Message Filters

Here is how the public API of fplog looks like:

//One time per application call.
FPLOG_API void initlog(const char* appname, fplog::Transport_Interface* transport = 0);

//Mandatory call from every thread that wants to log some data.
//Done to increase flexibility:
//each thread will have its own filters configuration and
//can decide independently which stuff to log.
FPLOG_API void openlog(const char* facility, Filter_Base* filter = 0);

//Optional but advised to call from each thread that logs data right
//before stopping and exiting the thread.
//Doing this will free some memory (amount is really small)
//that is needed to support logging from a given thread.
//Not doing closelog() does not lead to memory leak
//because everything will be deallocated in any case on app exit,
//fplog frees its resources when implementation class instance is destroyed.
FPLOG_API void closelog();

//Scope of filter-related functions is a calling thread -
//all manipulations will apply to calling thread only.
FPLOG_API void add_filter(Filter_Base* filter);
FPLOG_API void remove_filter(Filter_Base* filter);
FPLOG_API Filter_Base* find_filter(const char* filter_id);

FPLOG_API const char* get_facility();

//Should be used from any thread that opened logger,
//calling from other threads will have no effect.
FPLOG_API void write(Message& msg);

It resembles syslog closely however extended with per-thread message filtering capabilities along with few other things. Today I would like to concentrate on the filters because I was playing around with several ideas in this regard for couple of days now and the idea that has beaten the competition is to use Lua for log message filtering.

The thing is log message could contain many fields in addition to mandatory that only the log message author could know, therefore it would be nice to allow a fellow programmer to create as complicated filter passing condition as he likes. Well, but we do not need Lua for that, right? There is Filter_Base class that basically has 1 method that accepts log message and as a result tells true/false meaning message should pass further or be suppressed.

It works in case the only way we would be making adjustments in filtering conditions is by modifying the source code: creating new subclasses of Filter_Base that implement the filtering conditions we see fit. However as soon as there is an idea to change filter without modifying the source code the need for loading filters from something like config file arises.

I was thinking about some simple filters where you have only a small subset of logical operations and comparisons you could do, about regular expressions or some other pattern matching but everything what initially seemed simple turned into rather inflexible and/or complex stuff. Therefore step by step I approached the idea of using some existing scripting solution for filters and Lua was the obvious choice – lightweight and easily embedded into C++ code.

So, it goes like this:

  • there is an instance of Lua interpreter running all the time inside fplog – it is not created and destroyed for each message;
  • json.lua module in addition to all the standard Lua libs is loaded;
  • fplog_message object is available from Lua script, this object is an actual log message converted from json to native Lua tables structure (nested tables are possible – same as nested json objects);
  • Lua filter script should call filter_result function with true/false parameter in the end to inform the C++ code to either pass the message further or suppress it.

Of course the performance might be an issue, especially taking into account my intent of trying out fplog on embedded devices that could run Linux. Each log message would need to go via one or more Lua-based filters before it is potentially transported to a log collecting daemon via IPC. I will definitely need to run some tests and of course Lua-based filtering would be optional – if you do not need to be able to fine-tune logging “on-the-fly” via config files or some other methods then you will not be forced to use Lua filters.

Actually even without Lua you could implement several filters inside your application the will be pre-made and hardcoded but still it does not prohibit you from using config file to select a combination of pre-made filters to apply.

Android Support

Been thinking about supporting Android lately – if this is feasible and how easy it would be.. To be frank it would be troublesome porting sprot & spipc to Java and I am not even sure this is interesting enough to spend my free time on it.

However, as Android has Linux at its core running native code should be relatively easy, so my idea for now is to use this possibility – compile the whole solution with NDK, there is even Boost for Android so everything should be covered.

fplog, which is a client-side API will have to be wrapped JNI style to be usable out of Java apps. Also I am planning to include fplogd daemon as a resource for installable APK package and run the fplogd process from Java like it is described here.

The project is pretty far from running on Android but at least I see the way it could be done and I will try that after I see fplog working on Windows and normal desktop Linux.

SProt Client Mode State Diagram

Client side of sprot is finally ready too. Well, at least main logic is defined. While I was at it I understood that sequence numbers of data frames will be needed to resolve situations when server accepted a frame X and sent an ack but client did not receive this ack from server  for whatever reason and retransmitted the same X frame. In a such situation the server should just ignore the frame and answer with ack again.

Introduction of the sequence numbers caused some changes on diagrams posted previously, so those posts were updated. The sequence number will be reset each time mode switch frame is received and mode switch is performed, also because it’s only a single byte sequence number will be reset to 0 after reaching value of 255.
sprot client states

SProt Server Mode State Diagram

Here is how message exchange looks like from sprot server perspective. Diagram could be optimized by having a generic frame received state followed by crc check and sending nack in case of failure, but I realized it too late – already spent more than hour drawing that thing so I just left it “as is”.
sprot server states

Meet SProt, FPLog Communication Protocol

As one of the features of FPLog should be an ability to send arbitrary large log messages, communication protocol with packet assembly is required. The same protocol will be used for application to fplogd and fplogd to log collecting server communications. For now I am thinking about having only blocking IO but it might change later. Also this simple protocol (or just “SProt”) might be moved to a separate library. Maybe I am reinventing a wheel a bit with this protocol but in this project I do have such luxury because the goal is not to make it happen as fast as I can but to gain knowledge and practice my craft to become better, I have enough of reusing stuff at work so at least here I can make dumb choices from time to time :)

Here is an overview of the frames protocol consists of, state diagrams and logic will be described in later posts.

sprot frames*CRC7 polynomial 0×91 was used for CRC calculations.

FPLog Design Overview

Spent several hours thinking, selecting the drawing tool and finally making the sketch. Decided to try some diagramming tools available for Android tablets and found one that I liked very much (DrawExpress Diagram) – it allowed me to produce quality schematics pretty fast, learning curve is very merciful and the tool supports various connector types to show OOP relations, “bring to front” / “send to back” functions to create composite objects like boxes inside boxes, etc. Of course there is a group selection ability and finally the most interesting part – the tool is gesture-based, there is a number of simple to remember gestures that draw stuff on screen.

However not everything was as smooth as I wanted it to be: when I was making final strokes to fplog draft design the application crashed and it started to crash every time I tried opening fplog.de file.. I thought that I would have to start over and was quite disappointed as you may imagine but there was a possibility the format of the file is human-readable like XML or something and there is a chance I can fix the corrupted file to make DrawExpress work with this file again.

Docked my Galaxy Note 10.1, fired a terminal, switched to root to see all files (yes, my tablet is rooted) and executed

find / -type f -name "*fplog*"

That gave me a file inside “/data/data/com.drawexpress.full/files/” so I copied it to a non-root accessible folder, chmod to 777 and copied to my PC over FTP.
When I opened fplog.de file I was pleased to find simple JSON inside, it looked like there were all objects sorted by creation time followed by array of connectors that connected all these objects. When the editor crashed I was trying to add couple of connectors, so I decided to remove several connectors from the end of the file. Well, few JSON objects later I was overwriting my original fplog.de file on my tablet with the one edited on PC.
Rejoice! It worked and DrawExpress stopped crashing, here is the design I was so eager to save:

fplog_design_draft

FPLog Begins

In my previous post on logging I wrote about how it could be future-proofed and now I would like to give this concept some development.. literally – I want to develop a logging solution based on the concept presented earlier.

The solution will consist of client and server parts.
Client:

  • C++ and Java API
  • Various transports (Ethernet, Bluetooth, Serial, USB)
  • Windows, Linux and Android support

Server:

  • MongoDB as persistent storage
  • GUI application in Java and Spring
  • Windows and Linux support

With this project I would like to practice multiplatform development, refresh my rusty Java in the process and finally create a logging solution that I can use later in some other projects. Well, let’s see how it goes, hopefully not like 99.999% of such hobby side projects (hint: dev/null :) )

By the way the name of the project is ‘fplog’ which reflects the idea of this solution being future-proof.

Future-proof Logging

Some time ago I had a project that required working with lots of exchange orders, these orders were arriving into the system in hundreds per second: some were filled, others modified or canceled. In other words there was always some processing involved that needed to leave some traces in order to understand what happened with the particular order in case of some client dispute.

Project was developed from scratch therefore it was my decision on how to introduce logging there. As the feature seemed low priority not much time was invested in it and as a result a simple unstructured text logging with timestamp & priority was implemented. It was very human-readable and seemed pretty good until the project went public…

Every week I got a few gigabytes of text logs to process in order to find this or that problem or just to make sure the system is functioning as designed and everything is fine. During that time there were couple of severe problems detected very late because of this very inconvenient and time-consuming process.
After thinking over this mess several things became clear: text files are very inconvenient logs storage and a Nagios probe (or some other automated solution) should be reading the log in my place.

Logging mechanism improvements were in order: introduce some structure to log messages (make some mandatory and optional parameters that every log message has) and use database for logs storage.
After implementing these improvements we could easily search DB for errors ourselves or setup some Nagios probes that regularly do it for us.

To be fair I must confess that I left the company before improved logging mechanism was introduced, it was only half-way there, meaning that only some of the log messages were stored to DB – only those messages that were a consequence of some exception happening in the code and automatic probes could analyze only this portion of log searching the DB for the red flags so to say.

Anyway even this portion of the log stored inside the DB showed that some problems still remained with this approach: SQL database with its fixed schema was too rigid and inflexible storage for the log messages which can have arbitrary number of arbitrary parameters.
The answer is to store the logs into a NoSQL schema-less document database in an easily-parsable form which allows any parameters for a specific message.

I should give a guy who wrote this post a credit for making a case of using JSON as log message format, he also mentions systems that can be used for storing, searching and presenting the logged information.

All of the above makes me think that using the structured logging and storing everything to schema-less DB provides a pretty flexible solution that could withstand a test of time and in particular the everchanging requirements which is the hardest test for any system. Even the syslog protocol has some place for structured log information since RFC 5424 (see 6.3. STRUCTURED-DATA section) although this RFC is still in a proposal state.