PHP utility collection with hybrid and fluent APIs.

⌈⌋ branch:  hybrid7 libraries


Artifact [224edcb117]

Artifact 224edcb1176be43f4d27c7695f473225c364aa66:

  • File logstruck.php — part of check-in [5ee688036b] at 2015-01-05 07:48:22 on branch trunk — Highly experimental logging API and SQLite backend. Provides parameterized and hybrid function signature, allows storing array structures with grouped events. State: pretty basic prototype. (user: mario size: 24603)

<?php
/**
 * title: logStruck
 * description: SQlite group/structured logging backend
 * version: 0.0.9
 * type: handler
 * depends: php:sqlite >= 3.7, php >= 5.4
 * autoexec: true
 * config:
 *   <var name="ł::$db" description="SQLite storage location">
 *   <var name="ł::$app" description="default application name">
 *   <var name="ł::$section" description="current application module/section">
 * category: logging
 * license: Public Domain
 * state: experimental
 * 
 * 
 * Implements a terse but parametric logging API for structured journaling.
 * Basically meant for userland and direct GELF/Journald-style logging.
 * 
 *  · Storage in SQLite
 *  · Retain PHP process/runtime grouping, for tree-style event relationship
 *  · Application and sectioning names
 *  · Priority (err, crit, warn, info) and origin (app, lang, assert, sys)
 *  · Common fields as primary keys
 *  · Dictionary JSON blobs for arbitrary data
 *  · Auto-registering error and assertion handler
 *  · Zero configurability or alternative backend dispatching.
 * 
 * Function signatures:
 * 
 *  · Main logging function is  ł("..")
 *  · Use Ruby-style ':token' names
 *  · And HTTP-style 'field: value' parameters
 *  · Passed arrays stored as JSON blobs
 *  · Logger defaults may encompass :server and :backtrace or :code
 *  · Calling ł::$PRIO_$MODULE("..") readily sets :prio and :module
 * 
 * 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", $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`.
 * 
 * 
 * Rationale:
 * 
 *  · Most logging libraries in PHP are inherently text-store trussed.
 *    Reformatting/parsing into struct-backends is often an afterthought.
 * 
 *  · ”Complexity seldomly abets security“. Long-winded logger instantiation,
 *    message formatters, and backend filters don't encourage diligent use.
 * 
 *  · Entirely intended as userland runtime; only suitable for wee projects.
 * 
 *  · Inspired by structlog, cabin, journald, graylog, PEAR log¹, fluentd;
 *    albeit with a weird ':token' signature in place of named params in PHP.
 * 
 *  · Currently just inserts one-dimensional events. The API mapping is
 *    too crude still for spatial message/section/prio collections.
 * 
 *  · Log events are only associated to a primary group event. Not enough
 *    stack context analyzation retained to build proper trees. Might require
 *    reference objects; but that could also harm the API simplicity.
 * 
 * 
 */


#ł(':info', ':test', "Just testing if anything works", ':backtrace', ':server');
#ł(':debug', ':test', "Second entry", "errno: 5", ':vars', "random: 2", "file: t.php", "line: 20");
#ł(':crit', ':logging', "Debug :vars = _ENV", ':vars', $_ENV);


/**
 * Automatically declare PHP handlers for Errors, Assertions, Exceptions.
 *
 */
set_error_handler("ł::error_handler");
set_exception_handler("ł::exception_handler");
assert_options(ASSERT_CALLBACK, "ł::assert_handler");

#test
function run() {
    assert(" 1 == 2;  // never true");
    UNDEFINED_THINGY;
    throw new Exception("Yikes", 0x200);
}
run(1,2,3);


/**
 * Hybrid invocation as plain function.
 *
 *
 */
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;
    }
}



/**
 * @static Class which implements message struct assembly and storage.
 * Name is UTF-8 to deter cargo culters, and simplify source discoverabiliy.
 * SQLite gets reopened/closed mercilessly to prevent locking.
 *
 */
class ł {


    /**
     * Built-in defaults and database field mapping.
     *
     */

    // SQLite database storage path, should be absolute or docroot-based etc.
    var $db = "config/log.db";

    // Runtime defaults
    static $app = "undef";
    static $section = "main";
    static $min_prio = 7;
    
    // 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",
    ];
    
    // Log level and sources
    static $prio = ["emergency", "alert", "critical", "error", "warning", "notice", "info", "debug"];
    static $source = ["sys", "log", "lang", "assert", "exception"];

    // 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.
     *
     */

    // 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" => "-",
            "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
        $data = array_merge($this->template, [
            "timestamp" => microtime(TRUE),
            "app" => self::$app,
            "section" => self::$section,
            "p" => $this->p, // parent
            "g" => $this->g, // group
        ]);

        // all this just to turn token/array/string list into structurized blob
        $this->map_params($data, array_merge($this->iparams, $vars));

        // normalize params
        $this->inj_string_params($data);
        $this->move_context_params($data);

        // check prio
        if ($data["pri"] > self::$min_prio) {
            return;
        }

        // store
        $p = $this->store($data);
        
        // keep log event id as group and parent references
        $this->p or $this->p = $p;
        $this->g or $this->g = $p;
        return $p;
    }


    /**
     * Convert parameter list / tokens / arrays into $data blob.
     *
     * @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, $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, $value)) {
                    // Should rather collect them, and invoke afterwards, and ordered perhaps
                    $this->{$value}($data);
                }
                // :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;
            }
        }
    }


    /**
     * Normalize some parameters. Converts between string and numeric
     * representations of prio→pri flag, timestamp→timestr, and errno.
     *
     * @param  array   log event data
     */
    public function inj_string_params(& $data) {

        // prio string to integer
        if (is_int($pri = array_search($data["prio"], self::$prio))) {
            $data["pri"] = $pri;
        }
        else {
            $data["prio"] = "info";
            $data["pri"] = 7;
        }
        
        // timestr
        $data["timestr"] = gmstrftime("%Y-%m-%dT%H:%M:%S", $data["timestamp"]);
        
        // errno string to number
        if (!is_numeric($data["errno"])) {
            $data["errno"] = array_search(strtoupper(trim($data["errno"])), self::$errno);
        }
    }


    /**
     * Move anything with non-primary keys into `context` array.
     *
     * @param  array   log event data
     */
    public function move_context_params(& $data) {
        $extra = array_diff_key($data, array_flip(self::$fields));
        $data["context"] = array_merge_recursive($data["context"], $extra);
        $data = array_diff_key($data, $extra);
    }
    

    /**
     * Insert event data into log database.
     *
     * @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
        $db = new PDO("sqlite::memory:", NULL, NULL, [PDO::ATTR_ERRMODE => PDO::ERRMODE_WARNING]);
        $db->query("ATTACH '{$this->db}' AS `logdb`");
        $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);
        }

        // close store
        $db->query("DETACH `logdb`");
        $db = NULL;
        return $p;
    }





    /**
     * Hybrid call wrapper, which allows compact prio+section invocations with:
     *
     *   ł::err_module("Error in module");
     *   ł::crit_db("No space left on device", "errno: ENOSPC");
     *   ł::warn_auth("Constraint failure", $userObj);
     *
     */
    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, $trace) {

        // 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, ["errno" => $errno, "file" => $file, "line" => $line, "backtrace" => $trace, "error" => self::$phperr[$errno]], ':code', ':version');
        }
        
        // 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",
          ["backtrace" => $e->getTrace(), "file" => $e->getFile(), "line"=>$e->getLine(), "errno"=>$e->getCode()],
          ':code', ':version'
        );
    }


    /**
     * 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.
     *
     * Logging tokens of :backtrace, :server, :file, :code, :version
     * get substituted with arrays by following injector functions.
     *
     * @param  array   log event data bag; gets updated per reference
     */    


    // inject backtrace list
    public function backtrace(& $data) {
        $data["backtrace"] = ł::filter_backtrace(debug_backtrace(0));
    }
    
    // $_SERVER environment variables
    public function server(& $data) {
        $data["_SERVER"] = is_array($_SERVER) ? $_SERVER : $_SERVER->__vars;
    }

    // 3 lines of code context
    public function 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 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*( 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*(?: category:|@module:? )\h* (\S+) \h*$~smix", $src, $match)) {
                $data["section"] = $match[2];
            }
        }
    }

    // deduce last file+line from :backtrace
    public function 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"];
                }
            }
        }
    }



    /**
     * Utility calls.
     *
     */


    // Remove self-references to `ł.php` from backtrace.
    public static function filter_backtrace($trace) {
        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");
    }

}


?>