D 2015-01-06T15:34:53.985
L log
N text/x-markdown
P 552813bd7501ae16377ead9771fae1d221780ad5
U mario
W 14396
<h2> Structured and hierarchical logging with :token-parametric API </h2>
* <small> State: ***experimental*** </small>
* <small> Category: logging </small>
* <small> Features: journaling, structured, hierarchical </small>
* <small> Backend: SQLite, <del>JSON</del>, <del>fluentd</del> </small>
* <small> Signature: hybrid, parametric </small>
**logStruck <kbd>`Ε`</kbd>** implements a logging API and SQLite/JSON storage backend.
* It's purpose is storing *structured* log data, and it tries to retain log event hierarchies.
* Implements a hybrid and terse function interface.
* Accepts plain string messages, Ruby-style `:token` categorizers and placeholders, and understands array params.
* 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 go into the `context` array.
<style>
table.dbstruct {
width: 75%;
margin-left: 5%;
}
table.dbstruct td {
vertical-align: top;
}
table.dbstruct tr:nth-child(2n) {
background: #efefef;
}
</style>
<table class=dbstruct>
<tr><td> <kbd>i</kbd> </td> <td>PRIM</td> <td rowspan=3>Where `i` is the primary index, `g` the event group, and `p` the parent reference. Which allowed displaying event group hierarchies. <img src="raw/783ad438cb4577058910a4eaccabbba327789fc3?m=image/png" align=bottom width=485 height=93 alt="log tree"></td></tr>
<tr><td> <kbd>g</kbd> </td> <td>INT</td> </tr>
<tr><td> <kbd>p</kbd> </td> <td>INT</td> </tr>
<tr><td> <kbd>timestamp</kbd> </td> <td>REAL</td> <td>Timestamp with microseconds.</td></tr>
<tr><td> <kbd>timestr</kbd></td> <td>TEXT</td> <td>ISO DateTime string. In GMT/UTC of course.</td></tr>
<tr><td> <kbd>host</kbd> </td> <td>TEXT</td> <td>Hostname.</td></tr>
<tr><td> <kbd>pri</kbd> </td> <td>INT</td> <td>Priority number (0β¦7).</td></tr>
<tr><td> <kbd>**prio**</kbd></td> <td>TEXT</td> <td>Priority string (emergβ¦info)</td></tr>
<tr><td> <kbd>source</kbd> </td> <td>TEXT</td> <td>log|sys|lang|excpt|assert</td></tr>
<tr><td> <kbd>errno</kbd> </td> <td>INT</td> <td>0β¦32767</td></tr>
<tr><td> <kbd>app</kbd> </td> <td>TEXT</td> <td>AppName.php</td></tr>
<tr><td> <kbd>**section**</kbd></td> <td>TEXT</td> <td>Application structure / module / part / section.</td></tr>
<tr><td> <kbd>file</kbd> </td> <td>TEXT</td> <td>path/file.php</td></tr>
<tr><td> <kbd>line</kbd> </td> <td>INT</td> <td>125</td></tr>
<tr><td> <kbd>version</kbd></td> <td>TEXT</td> <td>Meta data from source code.</td></tr>
<tr><td> <kbd>**message**</kbd></td> <td>TEXT</td> <td>Primary log event message string.</td></tr>
<tr><td> <kbd>doc</kbd> </td> <td>TEXT</td> <td>Extra documentation / long message / href.</td></tr>
<tr><td> <kbd>backtrace</kbd></td> <td>JSON</td> <td>Array of `:backtrace`</td></tr>
<tr><td> <kbd>code</kbd> </td> <td>TEXT</td> <td>Extracted code context (3 lines).</td></tr>
<tr><td> <kbd>vars</kbd> </td> <td>JSON</td> <td>Main $vars[] array.</td></tr>
<tr><td> <kbd>context</kbd></td> <td>JSON</td> <td>Additional / user-defined fields.</td></tr>
<table>
## Flexible parametric API
The chief invocation method is <kbd>Ε()</kbd>. 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 <kbd>Ε::<em style=color:#630>option</em>_<em style=color:#226>tokens</em>()</kbd>.
For plain old log messages it's as simple to use as:
Ε("A thing happened.");
Usually you also want to convey a <u>priority</u> however:
Ε("Warnful warning", ':warn');
The <kbd>:token</kbd> 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 <u>application section</u>. Anything that isn't a reserved keyword :token will simply be assumed to refer an application module:
Ε(':auth', "Authorization error", ':notice');
Make up memorable designators to categorize your log messages to your application structure.
An obvious benefit of the :token syntax is that it allows <u>freely ordered</u> parameter lists.
These are all equivalent:
Ε(':warn', ':db', "Database error");
Ε(':db', ':warn', "Database error");
Ε(':warn', "Database error", ':db');
You'd probably want to settle on one of these. But it occasionally helps readability to be flexible, 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 <u>context data</u>, 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.<br>
To retain them in the `vars` column, you have two options:
Ε(':debug', "Front controller state", ['vars' => $RequestVars]);
Or the more fancy <kbd>:vars</kbd> 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 <u>fields</u>, 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 <u>`doc`</u> 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 messsage summary. Supply a human-readable description for non-coders. (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 *primary fields* can alternatively and 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, <kbd>:tokens</kbd> can also refer to data source functions.
You can augment log events with a <kbd>:backtrace</kbd> 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 <kbd>Ε::<em style=color:#630>option</em>_<em style=color:#226>tokens</em>()</kbd>
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 <kbd>:tokens</kbd>!
Around two dozen :token names are reserved keywords / internal field names:
<table class=dbstruct style="width:75%">
<tr><th colspan=3>Priority levels</th></tr>
<tr><td><kbd>:debug</kbd></td> <td>`7`</td> <td>Low-level debug events.</td></tr>
<tr><td><kbd>:info</kbd></td> <td>`6`</td> <td>Process flow infos etc.</td></tr>
<tr><td><kbd>:notice</kbd>, <kbd>:note</kbd></td> <td>`5`</td> <td>Lowest priority language notices.</td></tr>
<tr><td><kbd>:warning</kbd>, <kbd>:warn</kbd></td> <td>`4`</td> <td>Warnings.</td></tr>
<tr><td><kbd>:error</kbd>, <kbd>:err</kbd></td> <td>`3`</td> <td>PHP or system error.</td></tr>
<tr><td><kbd>:critical</kbd>, <kbd>:crit</kbd></td> <td>`2`</td> <td>This can't be good.</td></tr>
<tr><td><kbd>:alert</kbd>, <kbd>:alrt</kbd></td> <td>`1`</td> <td>Turn on the bat light.</td></tr>
<tr><td><kbd>:emergency</kbd>, <kbd>:emerg</kbd></td> <td>`0`</td> <td>Someone call the president.</td></tr>
<tr><th colspan=3>Source / generator</th></tr>
<tr><td><kbd>:log</kbd></td> <td></td> <td>Application origin, normal/manual log calls.</td></tr>
<tr><td><kbd>:sys</kbd></td> <td></td> <td>System-level events and errno codes.</td></tr>
<tr><td><kbd>:lang</kbd></td> <td></td> <td>Language errors, warnings, notices, etc.</td></tr>
<tr><td><kbd>:exception</kbd></td> <td></td> <td>Langauge/runtime exceptions.</td></tr>
<tr><td><kbd>:assert</kbd></td> <td></td> <td>`Assert()` warnings.</td></tr>
<tr><th colspan=3>Field names</th></tr>
<tr><td colspan=3>Any database column / primary field name can be represented as `:token`. It's pretty much only useful to use <kbd>:vars</kbd> however to map the following array parameter.</td></tr>
<tr><th colspan=3>Injector calls</th></tr>
<tr><td><kbd>:backtrace</kbd></td> <td></td> <td>Populates backtrace.</td></tr>
<tr><td><kbd>:server</kbd></td> <td></td> <td>Inserts $_SERVER array into `context`.</td></tr>
<tr><td><kbd>:file</kbd></td> <td></td> <td>Uncovers `file` and `line` from backtrace.</td></tr>
<tr><td><kbd>:version</kbd></td> <td></td> <td>Reads out meta data (file/scm version, and section) from script comments.</td></tr>
<tr><td><kbd>:code</kbd></td> <td></td> <td>Inserts 3 lines of `code` context.</td></tr>
<tr><td><kbd>:p</kbd></td> <td></td> <td>Tries to deduce log event hierarchy from prior calls, sections, and backtraces. (Not yet implemented.)</td></tr>
</table>
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 instantion:
Ε::$db = "$_SERVER[DOCUMENT_ROOT]/config/log.db";
Ε::$app = "YourAppID";
You can of course manually load the library. Most autoloaders would already load it implicitly because of the class reference. (Even 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";
Or likewise adapt properties of the global logger group `Ε()->section=..`.
<br>
<br>
### Notes / Rationale
* So, this is all either genius, or completely bonkers. Time will tell.
* Entirely intended as userland runtime; only suitable for wee projects.
* The function name <kbd>Ε</kbd> isn't completely settled on. (Maybe a bit too much novelty strive.)
* Most logging libraries in PHP are inherently text-store trussed.
Reformatting/parsing into struct-backends is often an afterthought at best.
* 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 excessive 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.
* Alternatively `$p = Ε("first"); Ε("second", "p:$p");` can control it manually.
* 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. (Probably simple.)
* Investigate whether logstash, fluentd or graylog2 make suitable targets. Neither seems to provide incremental log ids on submission. Otherwise each would require a push processing customizations.
Z 98680a6e49311d86baf1589690f21390