Structured and hierarchical logging with :token-parametric API

• State: experimental
• Category: logging
• Features: journaling, structured, hierarchical
• Backend: SQLite, JSON, fluentd, logstash
• Signature: hybrid, parametric

logStruck ł implements a logging API and SQLite/JSON storage backend.

• Its purpose is storing structured log data and retaining log event hierarchies.
• Implements a hybrid and terse function interface.
• Accepts plain string messages, Ruby-style :token categorizers and placeholders, and array data.
• Implicitly captures and maps PHP errors, unhandled exceptions, and most importantly assert()ions.

Unlike other PHP logging frameworks it's not primarily a text/line-oriented message dump.

Quick example

Invocations can be along the lines of:

 ł(':warn', ':wikiauth', "User doesn't have permission", $pageObj, ':vars', $_SESSION);

All the fun is in the :token literals, and passing arrays or objects.

Database scheme, primary fields

All columns in the database scheme are primary fields. Any extra data/values end up in the context array.

<style> table.dbstruct { width: 75%; margin-left: 3%; } table.dbstruct td { vertical-align: top; } table.dbstruct tr:nth-child(2n) { background: #efefef; } </style>

i	PRIM	Where i is the primary index, g the event group, and p the parent reference. Which allows displaying event group hierarchies.
g	INT
p	INT
timestamp	REAL	Timestamp with microseconds.
timestr	TEXT	ISO DateTime string. In GMT/UTC of course.
host	TEXT	Hostname.
pri	INT	Priority number (0…7).
prio	TEXT	Priority string (emerg…info)
source	TEXT	log | sys | lang | excpt | assert
errno	INT	0…32767
app	TEXT	AppName.php
section	TEXT	Application structure / module / part / section.
file	TEXT	path/file.php
line	INT	125
version	TEXT	Meta data from source code.
message	TEXT	Primary log event message string.
doc	TEXT	Extra documentation / long message / href.
backtrace	JSON	Array of :backtrace
code	TEXT	Extracted code context (3 lines).
vars	JSON	Main $vars[] array.
context	JSON	Additional / user-defined fields.

Flexible parametric API

The chief invocation method is ł(). On the outset it's a procedural function, thus available globally. Behind the scenes it keeps a primary logger group. Alternatively it can be invoked via ł::option_tokens().

For plain old log messages it's as simple to use as:

 ł("A thing happened.");

Usually you also want to convey a priority however:

 ł("Warnful warning", ':warn');

The :token attributes are the most interesting concept in this logging API. They simulate Ruby-style symbols. In PHP they need to be enquoted as strings however.

Besides priority levels, an important use is classifying an application section. Anything that isn't a reserved keyword :token will simply be assumed to refer to an application module:

 ł(':auth', "Authorization error", ':notice');

Make up memorable designators to categorize your log messages according to your application structure and code flow.

An obvious benefit of the :token syntax is that it allows freely ordered parameter lists.
These are all equivalent:

 ł(':warn', ':db', "Database error");
 ł(':db', ':warn', "Database error");
 ł(':warn', "Database error", ':db');

You'd probably want to be somewhat consistent though. But flexibility occasionally helps readability, in particular when passing functional :tokens or arrays/lists.

Array data

As mentioned, this logger API isn't meant for just string data. You often want to convey context data, and additional attributes. It's often as simple as just attaching an array to the parameter list:

 ł(':debug', "Front controller state", $RequestVars);

Now those would end up in the context database field.
To retain them in the vars column, you have two options:

 ł(':debug', "Front controller state", ['vars' => $RequestVars]);

Or the more fancy :vars array designator:

 ł(':debug', "Front controller state", ':vars', ⃕$RequestVars);

You might also use this for other fields like :message / :code / :doc, as long as the following parameter is an array.

Data mapping with "field: value"

Plain strings usually end up in the message field. But the structured database scheme has more fields, each with specific purposes. You can easily populate them with the key:value syntax.

 ł("File reading error", "errno: EACCESS");

Here errno is actually an integer field, thus will be converted afterwards.

A more interesting field to take care of is the doc column.

 ł("Cache directory locked", "doc: ?wiki=SetCachePerm");

Nowadays logs are often consumed by machines rather than humans. For some projects you may however wish to be more descriptive. You can augment the coarse and technical message summary. Supply a human-readable description for non-programmers. (In other logging APIs this is usually an afterthought, if at all implemented, seldomly even manageable in log processors/viewers).

While you could use the doc: field for a long prosaic documentation, this needlessly stuffs the datastore. Instead prefer hyperlinks, or references. A "?tktid=12345" or "See setup.txt on chmod cache" are helpful minimums. Relative link references are easiest to process.

All of the primary fields could also be set using the key:value scheme:

 ł('section: auth', "Auth warning");
 ł("message: $php_errormsg");
 ł('source: sys', "Exec failure", "errno: $retval", [$cmd]);
 ł("Regex failed", "code: $rx", "errno: $preg_last_error");

And fields that aren't primary log event columns/fields will end up in the context database array.

 ł("Special needs logging", "var1: $var1", "method: $callback");

This is basically equivalent to using a ["key"=>"value", ...] list. Again, prefer what's more readable in whatever context.

Injectors

As if there wasn't enough flexibility already, :tokens can also refer to data source functions.

You can augment log events with a :backtrace most of the time:

 ł(':warn', "How did we get here?", ':backtrace');

The placeholder token will be substituted by an array, before being pushed to the log store.

Likewise you can interpolate some common vars:

 ł(':debug', "Front Controller startup", ':server');

Or extract pretty much all available meta data:

 ł(':debug', "Debug by logging", ':backtrace', ':file', ':code', ':version');

The built-in error / exception / assert handlers do this automatically for example, to varying degrees.

Hybrid ł::option_tokens()

The :token scheme is pretty neat, but certainly not to everyones liking, and sometimes less readable than plain boring method calls. Therefore the ł() function and ł:: class go hand in hand. Instead of listing tokens as arguments, you can just compact them into a virtual method name:

 ł::debug_auth("Authorization failed", $UserObject);

You can even freely mix in injector callbacks and one array designator:

 ł::warn_db_backtrace_file_vars("DB error", $stmt);

Again, you're the programmer. Make sound choices on a case-by-case basis. Don't be clingy with stale semantics.

All the :tokens!

Around two dozen :token names are reserved keywords / internal field names:

Priority levels
:debug	7	Low-level debug events.
:info	6	Process flow infos etc.
:notice, :note	5	Lowest priority language notices.
:warning, :warn	4	Warnings.
:error, :err	3	PHP or system error.
:critical, :crit	2	This can't be good.
:alert, :alrt	1	Turn on the bat light.
:emergency, :emerg	0	Someone call the president.
Source / generator
:log		Application origin, normal/manual log calls.
:sys		System-level events and errno codes.
:lang		Language errors, warnings, notices, etc.
:exception		Langauge/runtime exceptions.
:assert		Assert() warnings.
Field names
Any database column / primary field name can be represented as :token. It's pretty much only useful to use :vars however to map the following array parameter.
Aliases
Besides the prio levels, there are a few more shortened aliases to common fields. Among them :documentation for :doc, :priority for :prio, :help for :doc, :msg for :message, :language for lang, :exc for :exception, :app as :log generator source alias, :trace and :stack as aliases for :backtrace, and :env for :server
Injector calls
:backtrace		Populates backtrace.
:server		Inserts $_SERVER array into context.
:file		Uncovers file and line from backtrace.
:version		Reads out meta data (file/scm version, and section) from script comments.
:code		Inserts 3 lines of code context.
:p		Tries to deduce log event hierarchy from prior calls, sections, and backtraces. (Not yet implemented.)

Any other :token name can be used freely to classify and group your application flow. They'll be used as section names.

Setup

You obviously need a readily available log.db SQLite store. Best keep it DOCUMENT_ROOT-relative, so it's easy to declare on instantiation:

ł::$app = "YourAppID";
ł()->db = "$_SERVER[DOCUMENT_ROOT]/config/log.db";

You can of course manually load the library. Most autoloaders would already load it implicitly after the first class / static property reference. (Even some PSR-x ones. And they'd even be accidentially correct for once with case-sensitive Unicode lookups here).

While you ought to use :section names for logging calls, you can also override/update the default throughout your application flow with:

ł()->section = "forum";

Albeit this is more useful for declarations on separate logger groups.

$log2 = new ł("app: forum", "min_prio: 6");
$log2(':info', ':template', "New post", [$content]);

Generally $app is a static property, while $section and $min_prio are instance defaults.

Default injectors

The $logger instance in ł() takes a list of default :token options and injectors. You should adapt it directly to enable further features.

   $logger = new ł(":log", ':backtrace', ':file', ':version', ':p');

Which for example implies full event population for all/manual logging calls.

Avoid complexity

• Yes, you could actually run multiple logger groups, or pass around the $logger handler. Don't do it. (Kind of works, but wasn't intended to.)

• The alternative branches and store() implementations are meant to be patched in. It makes zero sense to DI / runtime-bind them. You're only going to use one approach in practice, so don't complicate instantiation.

• Take care with leaking information through logs. It's tempting to include a backtrace for all calls. But in particular authorization-sensitive variable states may only be useful for concrete debugging tasks, not in all log events.

  That's an important consideration for any logging library. But moreso for logStruck due to its much simpler API and usage for debugging.

Notes / Rationale

• So, this is all either genius, or completely bonkers.

• logStruck is decidedly different to most other logging libraries in PHP. It doesn't follow PSR-3 (lowest common denominator) and historic line/text-oriented logging. In particular it tries to avoid parsing+reformatting backends or making structured/JSON logging an afterthought.

• Entirely intended as userland runtime. Mostly suitable for wee projects. It's primary use case is application-level debugging and auditability.

• The function name ł isn't completely settled on. (Maybe a bit too much novelty strive.)

• Extensibility of the database scheme is easily done, but not planned for.

• Alternative logging backends are best implemented in branches.

  • (In the time and age of GitHub forkeritis anyway.)
  • It doesn't seem senseful to impose a configuration-centric instantiation.
  • However making $ł->db just a Callable would be trivial.
  • The API and JSON-logging design is specifically meant to avoid MonoLog-style message formatting / parsing / filter chains. Events are structured from the start, shouldn't be downconverted to suit textdump interfaces.

<!-- -->

• Inspired by structlog, cabin, journald, graylog, PEAR log even, and with logstash/fluentd in mind.

• The fancy ':token' signature is used in place of named params and constant literals in PHP.

• Currently just inserts one-dimensional events. The API mapping is too crude still for spatial message/section/prio collections.

ToDo

• Log events are only associated to a primary group event as of now. The :p filter will allow to regroup events automatically from context information.

  • It'll scan the backtrace for matching prior code paths, and obviously the used :sections to relate events to another.

  • Alternatively control it manually:

      $p = ł("first");
      ł("second", "p:$p");
    

    A logger call returns the new event id. And p: is just the field that keeps the handle.

<!-- -->

• The alternative JSON file-append store just keeps event-local ids/groups=1/parent ids. This needs an insertion transaction or trigger for reconverting into a SQLite store. (Rather simple.)

• To mix application and server-level logging an injector for Apaches UNIQUE_ID might make sense. Still would require log post-processing to turn it into a sequential event id. Or alternatively stash all entries with a UUID.

• Investigate whether logstash (supposedly works with multiline/mutate), fluentd or graylog2 make suitable targets. Neither seems to provide incremental log ids on submission. Each requires post processing on pushed events, or incremental json/sqlite imports.

• Most obiously this implementation hinges an a proper GUI. It's kinda pointless to make another ETL toy, if it wasn't for the absence of hierarchical support in existing log viewers. While a web viewer would suffice, only an actual desktop tool would benefit from the intended JSON → SQLite storage.