<?php
/**
* title: logStruck
* description: SQlite group/structured logging backend
* version: 0.1.1
* api: php
* type: handler
* category: logging
* state: experimental
* depends: php:sqlite >= 3.7, php >= 5.4
* autoexec: true
* config:
* { class: var, type: str, name: "Å‚::$app", description: "default application name" }
* { class: prop, type: str, name: "Å‚()->db", description: "SQLite storage location" }
* license: Public Domain
* doc: https://fossil.include-once.org/hybrid7/wiki/log
*
*
* Implements a terse but parametric logging API for structured journaling.
* Primarily meant for userland and application-level inspection.
*
* Uses SQLite as primary storage. Retains process/runtime grouping with
* tree-style event relationships. Classifies priority, :section and
* generator/source. Common fields are primary keys, while arbitrary and
* extra values are stored as JSON blobs. Automatically registers PHP
* error, exception and assertion handler. Eschews configurability for
* alternative storage backends.
*
* Function signatures
* · Main logging function is ł("..")
* · Ruby-style ':token' names for priority and section names
* · HTTP-style 'field: value' parameters
* · Passed arrays stored as JSON blobs
* · Interpolation tokens :server, :backtrace, :file, :code, :version, :p
* · Calling ł::$PRIO_$MODULE("..") readily sets prio and module etc.
*
* Usage examples
* Å‚(':alert', "No foobar() result")
* Å‚(":warn", ":openid", "No endpoint found", $handle);
* Å‚("Page not found", ':exception', [$pagename])
* Å‚(':alert', "INSERT failed", ':database', $PDO->errorInfo(), ["vars"=>$params])
* Å‚(':assert', "Got #$num args.", ':debug', ":plugin", "\$wiki->add()", $args, "doc: ?tktid=2421")
* Å‚(':emerg', "no space left on device", ':sys', "errno: $errno", ':vars', $fileobject);
*
*
* Fields, message strings, data arrays and :tokens may be in any order, but some
* coherency is advisable of course. Only :section identifiers and :error level
* tokens should be used prudently.
*
* It's however as important to retain context values where available. Passing an
* indexed `get_defined_vars()` is most useful. But an unordered [$x, $y] list
* often allows debugging too.
*
*
* Database structure:
*
* CREATE TABLE log (
* i INTEGER PRIMARY KEY ASC NOT NULL, -- log event ROWID
* p INTEGER, -- associate subevents: parent log event
* g INTEGER, -- associate subevents: primary group id
* timestamp REAL, -- 1420305717.25732
* timestr CHAR( 19, 20 ), -- 2015-01-01T22:33:55
* pri INT, -- 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7
* prio VARCHAR( 0, 10 ), -- crit | err | ... | info | debug
* source VARCHAR( 0, 20 ), -- log | error | assert | exception | errno
* errno INT, -- 0..255
* host TEXT, -- srv3
* app VARCHAR( 0, 64 ), -- $app
* section VARCHAR( 0, 64 ), -- $section
* file TEXT, -- file.php
* line INT, -- 125
* version TEXT, -- file.php version / revision
* message TEXT, -- ordinary summary text message
* doc TEXT, -- end-user description / href
* backtrace TEXT, -- JSON
* code TEXT, -- excerpt
* vars TEXT, -- JSON
* context TEXT, -- JSON {_SERVER:{}, ...}
* );
* CREATE TRIGGER log_group AFTER INSERT ON log
* BEGIN UPDATE log SET g = i WHERE g IS NULL; END;
*
*
* Redundancy of timestamp/str and pri/prio for self-documenting storage;
* just like `doc` is meant to formalize technical error summaries.
*
* Database keys are also used as internal dict names. Anything that doesn't
* map will be merged into `context`.
*
*
*/
/**
* Automatically declare PHP handlers for Errors, Assertions, Exceptions.
*
*/
set_error_handler("Å‚::error_handler");
set_exception_handler("Å‚::exception_handler");
assert_options(ASSERT_CALLBACK, "Å‚::assert_handler");
/**
* Hybrid logger invocation.
* ‾‾‾‾‾‾‾‾‾‾
* Accepts message, :prio, :section, [array], and :injector params
* in any order. Instantiates a main logging group on first call.
*
*/
function Å‚(/*...*/) {
// keep one logger object around, which retains event parent/group id
static $logger;
if (!isset($logger)) { // set default values and interpolators here
$logger = new Å‚(":log");
}
// submit log event
if (func_num_args()) {
return $logger->__invoke( func_get_args() );
}
// just return logger
else {
return $logger;
}
}
/**
* Semi-static class which combines message struct assembling and storage.
* · UTF-8 identifier to deter cargo culters, and simplify source discoverabiliy.
* · SQLite storage gets reopened/closed mercilessly to prevent locking.
*
*/
class Å‚ {
/**
* Built-in identifiers
* ‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾
* · Declares a list of built-in :token names.
* · Maps error number magic values.
* · And lastly defines the list of primary database field names.
*
*/
// Log level / priority names
static $prio = ["emergency", "alert", "critical", "error", "warning", "notice", "info", "debug"];
// Event generator / source
static $source = ["sys", "log", "lang", "assert", "exception"];
// Token aliases
static $alias = [
// prios
"emerg" => "emergency",
"alrt" => "alert",
"crit" => "critical",
"err" => "error",
"warn" => "warning",
"note" => "notice",
"informational" => "info",
"debug" => "debug",
// fields
"priority" => "prio",
"documentation" => "doc",
"help" => "doc",
"msg" => "message",
// sources
"language" => "lang",
"exc" => "exception",
"app" => "log",
// injectors
"trace" => "backtrace",
"stack" => "backtrace",
"env" => "server",
];
// PHP error constants and priority mapping
static $phperr = [
E_ERROR => "ERROR", E_WARNING => "WARNING", E_NOTICE => "NOTICE", E_PARSE => "PARSE", E_STRICT => "STRICT", E_DEPRECATED
=> "DEPRECATED", E_RECOVERABLE_ERROR => "RECOVERABLE_ERROR", E_USER_ERROR => "USER_ERROR", E_USER_WARNING =>
"USER_WARNING", E_USER_NOTICE => "USER_NOTICE", E_USER_DEPRECATED => "USER_DEPRECATED", E_CORE_ERROR => "CORE_ERROR",
E_CORE_WARNING => "CORE_WARNING", E_COMPILE_ERROR => "COMPILE_ERROR", E_COMPILE_WARNING => "COMPILE_WARNING",
];
static $phpprio = [
':error' => 0x1111, # E_RECOVERABLE_ERROR | E_USER_ERROR | E_CORE_ERROR | E_ERROR
':warn' => 0x2222, # E_DEPRECATED | E_USER_WARNING | E_CORE_WARNING | E_WARNING
':notice' => 0x4C88, # E_USER_DEPRECATED | E_USER_NOTICE | E_STRICT | E_COMPILE_WARNING | E_NOTICE
':crit' => 0x0044, # E_PARSE | E_COMPILE_ERROR
];
// Indexed errno map
static $errno = [
"EOK", "EPERM", "ENOENT", "ESRCH", "EINTR", "EIO", "ENXIO", "E2BIG", "ENOEXEC", "EBADF", "ECHILD", "EAGAIN", "ENOMEM", "EACCES", "EFAULT", "ENOTBLK", "EBUSY",
"EEXIST", "EXDEV", "ENODEV", "ENOTDIR", "EISDIR", "EINVAL", "ENFILE", "EMFILE", "ENOTTY", "ETXTBSY", "EFBIG", "ENOSPC", "ESPIPE", "EROFS", "EMLINK", "EPIPE",
"EDOM", "ERANGE", "EDEADLK", "ENAMETOOLONG", "ENOLCK", "ENOSYS", "ENOTEMPTY", "ELOOP", "EWOULDBLOCK", "ENOMSG", "EIDRM", "ECHRNG", "EL2NSYNC", "EL3HLT",
"EL3RST", "ELNRNG", "EUNATCH", "ENOCSI", "EL2HLT", "EBADE", "EBADR", "EXFULL", "ENOANO", "EBADRQC", "EBADSLT", "n/a", "EBFONT", "ENOSTR", "ENODATA", "ETIME",
"ENOSR", "ENONET", "ENOPKG", "EREMOTE", "ENOLINK", "EADV", "ESRMNT", "ECOMM", "EPROTO", "EMULTIHOP", "EDOTDOT", "EBADMSG", "EOVERFLOW", "ENOTUNIQ", "EBADFD",
"EREMCHG", "ELIBACC", "ELIBBAD", "ELIBSCN", "ELIBMAX", "ELIBEXEC", "EILSEQ", "ERESTART", "ESTRPIPE", "EUSERS", "ENOTSOCK", "EDESTADDRREQ", "EMSGSIZE",
"EPROTOTYPE", "ENOPROTOOPT", "EPROTONOSUPPORT", "ESOCKTNOSUPPORT", "EOPNOTSUPP", "EPFNOSUPPORT", "EAFNOSUPPORT", "EADDRINUSE", "EADDRNOTAVAIL", "ENETDOWN",
"ENETUNREACH", "ENETRESET", "ECONNABORTED", "ECONNRESET", "ENOBUFS", "EISCONN", "ENOTCONN", "ESHUTDOWN", "ETOOMANYREFS", "ETIMEDOUT", "ECONNREFUSED",
"EHOSTDOWN", "EHOSTUNREACH", "EALREADY", "EINPROGRESS", "ESTALE", "EUCLEAN", "ENOTNAM", "ENAVAIL", "EISNAM", "EREMOTEIO", "EDQUOT", "ENOMEDIUM", "EMEDIUMTYPE",
"ECANCELED", "ENOKEY", "EKEYEXPIRED", "EKEYREVOKED", "EKEYREJECTED", "EOWNERDEAD", "ENOTRECOVERABLE"
];
// Primary database fields
static $fields = [
'i', 'p', 'g', "timestamp", "timestr", "pri", "prio", "source",
"errno", "app", "section", "file", "line", "version", "host",
"message", "doc", "code", "backtrace", "vars", "context",
];
/**
* Instance defaults
* ‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾
* · Defines default states ($app name, $section, $min_prio).
* · Summarizes values for new events in $template.
* · Hold :tokens in $iparams that always get applied.
* · Track parent and group event ids.
*
*/
// SQLite database storage path, should be absolute or docroot-based etc.
var $db = "config/log.db";
// Runtime defaults
static $app = "undef";
var $section = "main";
var $min_prio = 7;
// log event template values
public $template = [];
// handful of :tokens to apply on each log call
public $iparams = [];
// log event parent and group id
var /*&*/ $p = 0;
protected $g = NULL; // ROWID or :g
/**
* Prepare a logging group.
* ‾‾‾‾‾‾‾
*
* @param mixed* default :token or array list for log events
*/
function __construct(/*...$defaults*/) {
// prepare log event defaults
$this->template = array(
"p" => $this->p,
"g" => & $this->g,
"prio" => "info",
"host" => gethostname(),
"app" => self::$app,
"section" => & $this->section,
"timestamp" => 0,
"source" => "log",
"errno" => NULL,
"file" => NULL,
"line" => NULL,
"version" => NULL,
"message" => NULL,
"doc" => NULL,
"code" => NULL,
"backtrace" => [],
"vars" => [],
"context" => [],
);
// default __call() param list
$this->iparams = func_get_args();
}
/**
* The main logging function accepts an unordered list of parameters.
* ‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾
*
* "STRING"
* · First string will be used as message text.
* [ARRAYS]
* · Will be mapped into $data or cumulative $context blob.
* :TOKENS
* · Literal ':crit' or :warn will be assumed as prio levels.
* · Or substitute for :server or :backtrace dicts.
* · May categorize origin :sys, :lang, :assert, :exception
* · Can direct following array param to :vars or :context.
* · Otherwise refer to :section or :module ids.
* "KEY:VAL"
* · Strings of 'field: value' will be turned into arrays
* (more convenient and terse than literal array lists.)
* · For example "message: yada yada" is equivalent to message string.
* While "errno: 23" sets a core field, "doc: details..." another,
* but "xy_state: true" a context value.
*
* Expands resulting array into JSON blob, then sends it to database.
*
*
* @param array mixed arguments (string, array, key:val, :token)
* @return int log-event id
*/
public function __invoke($vars) {
// from defaults
$event = array_merge($this->template, [
"timestamp" => microtime(TRUE),
"p" => $this->p, // parent
"g" => $this->g, // group
]);
// all this just to turn token/array/string list into structurized blob
$this->map_params($event, array_merge($this->iparams, $vars));
// normalize params
$this->convert_string_params($event);
$this->move_context_params($event);
// check prio
if ($event["pri"] <= $this->min_prio) {
// store
$p = $this->store($event);
// keep log event id as group and parent references
$this->p or $this->p = $p;
$this->g or $this->g = $p;
}
// return log id, so next call may use Å‚("p: $pid") for relation
return $this->p;
}
/**
* Convert parameter list
* ‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾
*
* Builds the $event/data bag. Separates strings from arrays and key:value
* strings. Transforms :token names into priorities, section names or calls
* any injector functions.
*
*
* @param array log event data, gets populated
* @param array from parameter list (strings, array, key:val, :token)
* @param -
* @return void
*/
public function map_params(& $data, $param_list, $injectors = [], $a_target=NULL) {
foreach ($param_list as $value) {
// dicts get merged
if (is_array($value) || is_object($value)) {
if (strlen($a_target)) {
$data[$a_target] = array_merge($data[$a_target], (array)$value);
}
else {
$data = array_merge($data, (array)$value);
}
$a_target = NULL;
}
// ':token' only params
elseif (is_string($value) and strlen($value) and ($value[0] == ":")) {
// alias
$value = ltrim($value, ":");
$value = isset(self::$alias[$value]) ? self::$alias[$value] : $value;
// :token callback
if (method_exists($this, "inj_$value")) {
// Collect injectors, to sort and uniq and invoke them after assembling base fields.
$injectors[] = $value;
}
// :prio
elseif (in_array($value, self::$prio)) {
$data["prio"] = $value;
}
// :source
elseif (in_array($value, self::$source)) {
$data["source"] = $value;
}
// target :field for next array param
elseif (in_array($value, self::$fields)) {
$a_target = $value;
}
// otherwise assume :section
else {
$data["section"] = $value;
}
}
// field: value
elseif (is_string($value) and is_int(strpos($value, ":")) and preg_match("/^(\w+):\h?(.+)$/s", $value, $match)) {
list($match, $key, $value) = $match;
$data[isset(self::$alias[$key]) ? self::$alias[$key] : $key] = $value;
}
// plain message
elseif (is_string($value)) {
$data["message"] .= (strlen($data["message"]) ? "\n" : "") . $value;
// alternatively: turn $message into a list?
// or keep a detailed history in `context`?
}
// dunno, merge into context
else {
$data["context"][] = $value;
}
}
// order and run injectors
$injectors = array_merge(array_intersect(["server", "session", "backtrace", "file", "version", "code", "p"], $injectors), $injectors);
foreach (array_unique($injectors) as $value) {
$this->{"inj_$value"}($data);
}
}
/**
* Normalize some parameters. Converts between string and numeric
* representations of prio→pri flag, timestamp→timestr, and errno.
*
* @param array log event data
*/
public function convert_string_params(& $event) {
// prio string to integer
if (is_int($pri = array_search($event["prio"], self::$prio))) {
$event["pri"] = $pri;
}
else {
$event["prio"] = "info";
$event["pri"] = 7;
}
// timestr
$event["timestr"] = gmstrftime("%Y-%m-%dT%H:%M:%S", $event["timestamp"]);
// errno string to number
if (!is_numeric($event["errno"])) {
$event["errno"] = array_search(strtoupper(trim($event["errno"])), self::$errno);
}
}
/**
* Move anything with non-primary keys into `context` array.
*
* @param array log event data
*/
public function move_context_params(& $event) {
$extra = array_diff_key($event, array_flip(self::$fields));
$event["context"] = array_merge_recursive($event["context"], $extra);
$event = array_diff_key($event, $extra);
}
#ifdef LOGBE_SQLITE
/**
* Database pushing of event data.
* ‾‾‾‾‾‾‾‾
* This SQLite implementation is rather slow. It reopens and closes the handle
* to prevent lockups. Ideally this should be switched out for fluentd/rsyslog
* interfacing. → But this won't be made configurable. Instead brach versions
* of this script will implement different targets. (A plain JSON dump might be
* workable, but requires post-processing to reconstruct the event hierarchy.)
*
* @param array log event data
* @return int event id
*/
public function store($data) {
// JSONify arrays
$data = array_map("self::_json", $data);
$data = array_intersect_key($data, array_flip(array_diff(self::$fields, ["i"])));
// create handle, connect to SQLite file
static $db = new PDO("sqlite:{$this->db}", NULL, NULL, [PDO::ATTR_ERRMODE => PDO::ERRMODE_WARNING]);
$db->beginTransaction();
// bind values
$keys = array_keys($data);
$s = $db->prepare(
"INSERT OR ROLLBACK INTO log " .
"(`" . join("`, `", $keys) . "`) " . // :?
"VALUES (:" . join(", :", $keys) . ") " // ::
);
// store and commit
if ($s and $s->execute($data)) {
$db->commit();
$p = $db->lastInsertId();
}
else {
$p = $this->fallback_stderr($data);
}
// return new event id
return $p;
}
#elif defined(LOGBE_JSON)
#include <_store_json.inc>
#elif defined(LOGBE_STASH)
#include <_store_logstash.inc>
#elif defined(LOGBE_CEE)
#include <_store_rsyslog.inc>
#endif
/**
* Set $template values through `Å‚()->section = "xyz"`
*
* @param string Field name
* @param mixed Default value
*
*/
function __set($name, $value) {
$this->template[$name] = $value;
}
/**
* Logging handlers
* ‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾
* Alternative logger invocation functions, that basically wrap __invoke() via Å‚().
*
* · The hybrid ł::prio_section_tokens() scheme wraps token names in the method name.
*
* · An PHP error handler, exception fallback, and an assertion handler prepare all
* parameter transformations and some sensible logging defaults.
*
*/
/**
* Hybrid call wrapper, which allows compact prio+section invocations with.
*
* Å‚::err_module("Error in module", ':vars', $data);
*
* Mainly allows to combine priority and section name into call method name.
* But also permits listing injectors → ł::debug_backtrace_file_code("...");
*
*/
public static function __callStatic($name, $args) {
if (preg_match_all("/([a-z]+)/i", $name, $match)) {
foreach ($match[1] as $token) {
$args[] = strtolower(":$token"); // just map any word as :token
}
}
return call_user_func_array("Å‚", $args);
}
/**
* PHP error handler.
*
* Maps PHP :errno codes, retains :backtrace, and inserts :code excerpt.
*
*/
public static function error_handler($errno, $message, $file, $line, $varscope) {
// convert bitmask prio
foreach (self::$phpprio as $prio => $errmask){
if ($errmask & $errno) break;
}
// Prevent recursion on Å‚:: originating errors
if (isset($trace[0]["file"]) and $trace[0]["file"] == __FILE__) {
fwrite(STDERR, self::$phperr[$errno] . ": $errstr in $file line $line\n");
}
// Pass values on (- could be way more readable with "field:value" strings)
else {
Å‚(':lang', $prio, $message, ':code', ':version', ["errno" => $errno, "file" => $file, "line" => $line,
"vars" => $varscope, "error" => self::$phperr[$errno], "backtrace" => self::filter_backtrace()]
);
}
// populate $php_errormsg;
return false;
}
/**
* PHP exception handler.
*
* Of course only receives *unhandled* exceptions, therefore categorizes them :critical,
* retains :backtrace, message and exception type obviously.
*
*/
public static function exception_handler($e) {
// keep exception class, also use as message if empty
$class = get_class($e);
strlen($message = $e->getMessage()) or ($message = $class);
// pass on
Å‚(':exception', ':crit', $message, "exception: $class", ':code', ':version',
["backtrace" => $e->getTrace(), "file" => $e->getFile(), "line"=>$e->getLine(), "errno"=>$e->getCode()]
);
}
/**
* PHP assert() handler.
*
* Keeps the asserted inline $code, eventual comment as $message,
* and enables a :backtrace.
*
*/
public static function assert_handler($file, $line, $code, $message="Assertion failed", $prio=':warning') {
// extract comment
if (preg_match_all("~(?://|[/][*]|#)\h*(\V+?)\h*(?=[*][/]|$)~m", $code, $match)) {
$message = join("\n", $match[1]);
}
// pass on
Å‚(':assert', $prio, $message, ["file" => $file, "line" => $line, "code" => $code], ':backtrace');
// disable follow-up language warning
assert_options(ASSERT_WARNING, false);
}
/**
* Injectors
* ‾‾‾‾‾‾‾‾‾
* Some token names refer to the interpolation and lookup functions below.
*
* :backtrace Injects `backtrace` from debug_backtrace().
* :server Declares `_SERVER` variables in `context`.
* :file Finds referenced script and line number from trace.
* :code Inserts 3 lines of code context for log/error msgs.
* :version Looks up script @version and @category meta data.
* :p Derives log event parent id from last stacktraces
* and :section history.
*
* Notably the token parameter order is important, as :file depends on an
* existing :backtrace, and :version and :code depend on file/line infos.
*
* @param array log event data bag; gets updated per reference
*/
// inject backtrace list
public function inj_backtrace(& $data) {
$data["backtrace"] = self::filter_backtrace(debug_backtrace(0));
}
// $_SERVER environment variables
public function inj_server(& $data) {
$data["_SERVER"] = is_array($_SERVER) ? $_SERVER : $_SERVER->__vars;
}
// $_SESSION environment variables
public function inj_session(& $data) {
$data["_SESSION"] = is_array($_SESSION) ? $_SESSION : $_SESSION->__vars;
}
// 3 lines of code context
public function inj_code(& $data, $lines=3) {
if (!empty($data["file"]) && isset($data["line"])) {
if ($src = file($data["file"])) {
$data["code"] = join(array_slice($src, max(0, $data["line"] - $lines), $lines + 1));
}
}
}
// extract version: from comment meta data
public function inj_version(& $data) {
if (!empty($data["file"])) {
$src = file_get_contents($data["file"], false, NULL, 0, 1<<11); // read 2K max
// extract PMD version: / DocBlock @version field, alternatively revision:
if (preg_match("~ ^\h*[/*#]+ \h{,8} ( version:|@version:?|revision: )\h* (\S+)~smix", $src, $match)) {
$data["version"] = $match[2];
}
// while we're at it, also try to extract category: or @module descriptor as :section flag
if (preg_match("~ ^\h*[/*#]+ \h{,8} ( category:|@module:? )\h* (\S+) \h*$~smix", $src, $match)) {
$data["section"] = $match[2];
}
}
}
// deduce last file+line from :backtrace
public function inj_file(& $data) {
if (isset($data["backtrace"]) && empty($data["file"])) {
foreach (array_reverse($data["backtrace"]) as $row) {
if (isset($row["file"]) and ($row["file"] !== __FILE__)) {
$data["file"] = $row["file"];
$data["line"] = $row["line"];
}
}
}
}
// derive hierarchical parent id `p` from previous log events
public function inj_p(& $data) {
# needs a ->history[] of id/pid, section
# alternatively compare backtrace for prior file:line concordance
}
/**
* Utility calls
* ‾‾‾‾‾‾‾‾‾‾‾‾‾
*
*/
// Remove self-references to `Å‚.php` from backtrace.
public static function filter_backtrace($trace = NULL) {
$trace or $trace = debug_backtrace(0);
return array_values(array_filter($trace, function($row) {
return (empty($row["class"]) or ($row["class"] !== "Å‚"))
and (empty($row["file"]) or ($row["file"] !== __FILE__));
}));
}
// Turn arrays into JSON struct.
public static function _json($row) {
return is_null($row) ? NULL
: (is_scalar($row) ? $row : json_encode(unserialize(serialize((array)$row)), JSON_PRETTY_PRINT|JSON_UNESCAPED_SLASHES));
}
// When SQLite storage failed: resort to STDERR message.
protected function fallback_stderr($data) {
extract($data);
$message = json_encode($message);
fwrite(STDERR, strtr("$timestr\t$prio\t$source\t$errno\t$host:$app:$section\t$file:$line:$version\t$message\t$backtrace\t$vars\t$context", "\r\n", " ") . "\n");
}
}
?>