Log format experiments #26676

PVince81 · 2016-11-21T17:20:37Z

Make the log looks a bit better when containing exceptions.

To test, do a PROPFIND on any folder and look at the look.
Also tweak the boolean flags inside Log::processException().

The formatting was done by piping the row into jsonlint -p

Log exception on the same level as other fields with string stack trace

Uses getTraceAsString for the stack, $jsonStack=false; $jsonStringStack = false;;

Unformatted:

{"reqId":"+2KhWzBFYeuZNHxeLARN","remoteAddr":"127.0.0.1","app":"webdav","message":"Exception","level":3,"time":"2016-11-21T17:09:51+00:00","method":"PROPFIND","url":"/owncloud/remote.php/webdav","user":"admin","exception":{"Exception":"Exception","Message":"Test exception","Code":0,"File":"/srv/www/htdocs/owncloud/lib/private/Files/View.php","Line":1383,"Trace":"#0 /srv/www/htdocs/owncloud/apps/dav/lib/Connector/Sabre/Directory.php(252): OC\\Files\\View->getDirectoryContent('/')\n#1 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Tree.php(195): OCA\\DAV\\Connector\\Sabre\\Directory->getChildren()\n#2 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(893): Sabre\\DAV\\Tree->getChildren('')\n#3 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(947): Sabre\\DAV\\Server->addPathNodesRecursively(Array, Object(Sabre\\DAV\\PropFind))\n#4 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php(336): Sabre\\DAV\\Server->getPropertiesForPath('', Array, 1)\n#5 [internal function]: Sabre\\DAV\\CorePlugin->httpPropFind(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#6 /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#7 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(479): Sabre\\Event\\EventEmitter->emit('method:PROPFIND', Array)\n#8 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#9 /srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php(57): Sabre\\DAV\\Server->exec()\n#10 /srv/www/htdocs/owncloud/remote.php(164): require_once('/srv/www/htdocs...')\n#11 {main}"}}

Formatted:

{
  "reqId": "+2KhWzBFYeuZNHxeLARN",
  "remoteAddr": "127.0.0.1",
  "app": "webdav",
  "message": "Exception",
  "level": 3,
  "time": "2016-11-21T17:09:51+00:00",
  "method": "PROPFIND",
  "url": "/owncloud/remote.php/webdav",
  "user": "admin",
  "exception": {
    "Exception": "Exception",
    "Message": "Test exception",
    "Code": 0,
    "File": "/srv/www/htdocs/owncloud/lib/private/Files/View.php",
    "Line": 1383,
    "Trace": "#0 /srv/www/htdocs/owncloud/apps/dav/lib/Connector/Sabre/Directory.php(252): OC\\Files\\View->getDirectoryContent('/')\n#1 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Tree.php(195): OCA\\DAV\\Connector\\Sabre\\Directory->getChildren()\n#2 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(893): Sabre\\DAV\\Tree->getChildren('')\n#3 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(947): Sabre\\DAV\\Server->addPathNodesRecursively(Array, Object(Sabre\\DAV\\PropFind))\n#4 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php(336): Sabre\\DAV\\Server->getPropertiesForPath('', Array, 1)\n#5 [internal function]: Sabre\\DAV\\CorePlugin->httpPropFind(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#6 /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#7 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(479): Sabre\\Event\\EventEmitter->emit('method:PROPFIND', Array)\n#8 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#9 /srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php(57): Sabre\\DAV\\Server->exec()\n#10 /srv/www/htdocs/owncloud/remote.php(164): require_once('/srv/www/htdocs...')\n#11 {main}"
  }
}

This already looks nice but doesn't format the stack trace properly.

Log on same level as other fields but with JSON stack trace

Uses getTrace() for the stack and puts the items into a JSON sub-array.
$jsonStack=true;

As you can see there are LOTS of details in there, perhaps too much.

Unformatted:

{"reqId":"gaAGh5V1bfwaRzSbh1Qu","remoteAddr":"127.0.0.1","app":"webdav","message":"Exception","level":3,"time":"2016-11-21T17:11:08+00:00","method":"PROPFIND","url":"/owncloud/remote.php/webdav","user":"admin","exception":{"Exception":"Exception","Message":"Test exception","Code":0,"File":"/srv/www/htdocs/owncloud/lib/private/Files/View.php","Line":1383,"Trace":[{"file":"/srv/www/htdocs/owncloud/apps/dav/lib/Connector/Sabre/Directory.php","line":252,"function":"getDirectoryContent","class":"OC\\Files\\View","type":"->","args":["/"]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Tree.php","line":195,"function":"getChildren","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->","args":[]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php","line":893,"function":"getChildren","class":"Sabre\\DAV\\Tree","type":"->","args":[""]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php","line":947,"function":"addPathNodesRecursively","class":"Sabre\\DAV\\Server","type":"->","args":[[[{},{}]],{}]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php","line":336,"function":"getPropertiesForPath","class":"Sabre\\DAV\\Server","type":"->","args":["",["{DAV:}resourcetype","{DAV:}getlastmodified","{DAV:}getcontentlength","{DAV:}getetag","{http://owncloud.org/ns}id","{http://owncloud.org/ns}downloadURL","{http://owncloud.org/ns}dDC","{http://owncloud.org/ns}permissions","{http://owncloud.org/ns}size","{DAV:}quota-used-bytes","{DAV:}quota-available-bytes","{http://owncloud.org/ns}share-types"],1]},{"function":"httpPropFind","class":"Sabre\\DAV\\CorePlugin","type":"->","args":[{"absoluteUrl":"http://localhost/owncloud/remote.php/webdav"},{}]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[[{},"httpPropFind"],[{"absoluteUrl":"http://localhost/owncloud/remote.php/webdav"},{}]]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php","line":479,"function":"emit","class":"Sabre\\Event\\EventEmitter","type":"->","args":["method:PROPFIND",[{"absoluteUrl":"http://localhost/owncloud/remote.php/webdav"},{}]]},{"file":"/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->","args":[{"absoluteUrl":"http://localhost/owncloud/remote.php/webdav"},{}]},{"file":"/srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php","line":57,"function":"exec","class":"Sabre\\DAV\\Server","type":"->","args":[]},{"file":"/srv/www/htdocs/owncloud/remote.php","line":164,"args":["/srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php"],"function":"require_once"}]}}

Formatted:

{
  "reqId": "gaAGh5V1bfwaRzSbh1Qu",
  "remoteAddr": "127.0.0.1",
  "app": "webdav",
  "message": "Exception",
  "level": 3,
  "time": "2016-11-21T17:11:08+00:00",
  "method": "PROPFIND",
  "url": "/owncloud/remote.php/webdav",
  "user": "admin",
  "exception": {
    "Exception": "Exception",
    "Message": "Test exception",
    "Code": 0,
    "File": "/srv/www/htdocs/owncloud/lib/private/Files/View.php",
    "Line": 1383,
    "Trace": [
      {
        "file": "/srv/www/htdocs/owncloud/apps/dav/lib/Connector/Sabre/Directory.php",
        "line": 252,
        "function": "getDirectoryContent",
        "class": "OC\\Files\\View",
        "type": "->",
        "args": [
          "/"
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Tree.php",
        "line": 195,
        "function": "getChildren",
        "class": "OCA\\DAV\\Connector\\Sabre\\Directory",
        "type": "->",
        "args": []
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php",
        "line": 893,
        "function": "getChildren",
        "class": "Sabre\\DAV\\Tree",
        "type": "->",
        "args": [
          ""
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php",
        "line": 947,
        "function": "addPathNodesRecursively",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": [
          [
            [
              {},
              {}
            ]
          ],
          {}
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php",
        "line": 336,
        "function": "getPropertiesForPath",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": [
          "",
          [
            "{DAV:}resourcetype",
            "{DAV:}getlastmodified",
            "{DAV:}getcontentlength",
            "{DAV:}getetag",
            "{http://owncloud.org/ns}id",
            "{http://owncloud.org/ns}downloadURL",
            "{http://owncloud.org/ns}dDC",
            "{http://owncloud.org/ns}permissions",
            "{http://owncloud.org/ns}size",
            "{DAV:}quota-used-bytes",
            "{DAV:}quota-available-bytes",
            "{http://owncloud.org/ns}share-types"
          ],
          1
        ]
      },
      {
        "function": "httpPropFind",
        "class": "Sabre\\DAV\\CorePlugin",
        "type": "->",
        "args": [
          {
            "absoluteUrl": "http://localhost/owncloud/remote.php/webdav"
          },
          {}
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php",
        "line": 105,
        "function": "call_user_func_array",
        "args": [
          [
            {},
            "httpPropFind"
          ],
          [
            {
              "absoluteUrl": "http://localhost/owncloud/remote.php/webdav"
            },
            {}
          ]
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php",
        "line": 479,
        "function": "emit",
        "class": "Sabre\\Event\\EventEmitter",
        "type": "->",
        "args": [
          "method:PROPFIND",
          [
            {
              "absoluteUrl": "http://localhost/owncloud/remote.php/webdav"
            },
            {}
          ]
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php",
        "line": 254,
        "function": "invokeMethod",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": [
          {
            "absoluteUrl": "http://localhost/owncloud/remote.php/webdav"
          },
          {}
        ]
      },
      {
        "file": "/srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php",
        "line": 57,
        "function": "exec",
        "class": "Sabre\\DAV\\Server",
        "type": "->",
        "args": []
      },
      {
        "file": "/srv/www/htdocs/owncloud/remote.php",
        "line": 164,
        "args": [
          "/srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php"
        ],
        "function": "require_once"
      }
    ]
  }
}

Log on same level as other fields but take the string trace rows and put these into a JSON array

$jsonStack=false; $jsonStringStack = true;

Unformatted:

{"reqId":"ZZuX2T/Fubz5+TbHOG7p","remoteAddr":"127.0.0.1","app":"webdav","message":"Exception","level":3,"time":"2016-11-21T17:15:50+00:00","method":"PROPFIND","url":"/owncloud/remote.php/webdav","user":"admin","exception":{"Exception":"Exception","Message":"Test exception","Code":0,"File":"/srv/www/htdocs/owncloud/lib/private/Files/View.php","Line":1383,"Trace":["#0 /srv/www/htdocs/owncloud/apps/dav/lib/Connector/Sabre/Directory.php(252): OC\\Files\\View->getDirectoryContent('/')","#1 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Tree.php(195): OCA\\DAV\\Connector\\Sabre\\Directory->getChildren()","#2 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(893): Sabre\\DAV\\Tree->getChildren('')","#3 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(947): Sabre\\DAV\\Server->addPathNodesRecursively(Array, Object(Sabre\\DAV\\PropFind))","#4 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php(336): Sabre\\DAV\\Server->getPropertiesForPath('', Array, 1)","#5 [internal function]: Sabre\\DAV\\CorePlugin->httpPropFind(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))","#6 /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)","#7 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(479): Sabre\\Event\\EventEmitter->emit('method:PROPFIND', Array)","#8 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))","#9 /srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php(57): Sabre\\DAV\\Server->exec()","#10 /srv/www/htdocs/owncloud/remote.php(164): require_once('/srv/www/htdocs...')","#11 {main}"]}}

Formatted:

{
  "reqId": "ZZuX2T/Fubz5+TbHOG7p",
  "remoteAddr": "127.0.0.1",
  "app": "webdav",
  "message": "Exception",
  "level": 3,
  "time": "2016-11-21T17:15:50+00:00",
  "method": "PROPFIND",
  "url": "/owncloud/remote.php/webdav",
  "user": "admin",
  "exception": {
    "Exception": "Exception",
    "Message": "Test exception",
    "Code": 0,
    "File": "/srv/www/htdocs/owncloud/lib/private/Files/View.php",
    "Line": 1383,
    "Trace": [
      "#0 /srv/www/htdocs/owncloud/apps/dav/lib/Connector/Sabre/Directory.php(252): OC\\Files\\View->getDirectoryContent('/')",
      "#1 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Tree.php(195): OCA\\DAV\\Connector\\Sabre\\Directory->getChildren()",
      "#2 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(893): Sabre\\DAV\\Tree->getChildren('')",
      "#3 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(947): Sabre\\DAV\\Server->addPathNodesRecursively(Array, Object(Sabre\\DAV\\PropFind))",
      "#4 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/CorePlugin.php(336): Sabre\\DAV\\Server->getPropertiesForPath('', Array, 1)",
      "#5 [internal function]: Sabre\\DAV\\CorePlugin->httpPropFind(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))",
      "#6 /srv/www/htdocs/owncloud/lib/composer/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)",
      "#7 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(479): Sabre\\Event\\EventEmitter->emit('method:PROPFIND', Array)",
      "#8 /srv/www/htdocs/owncloud/lib/composer/sabre/dav/lib/DAV/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))",
      "#9 /srv/www/htdocs/owncloud/apps/dav/appinfo/v1/webdav.php(57): Sabre\\DAV\\Server->exec()",
      "#10 /srv/www/htdocs/owncloud/remote.php(164): require_once('/srv/www/htdocs...')",
      "#11 {main}"
    ]
  }
}

Perhaps the last one is the nicest.

Also note that I added JSON_UNESCAPED_SLASHES to avoid the annoying \/...

PVince81 · 2016-11-21T17:22:29Z

@DeepDiver1975 @butonic @cdamken do we agree on the general idea that we want to bring "exception" on the same level as the other attributes in the log ?

I had to do some code magic to pass the exception as $context and $extras.

If not then it will be impossible to make it look nice when json-formatted because the exception will always be inside an escaped string.

mention-bot · 2016-11-21T17:24:58Z

@PVince81, thanks for your PR! By analyzing the history of the files in this pull request, we identified @DeepDiver1975, @pierrejochem and @MorrisJobke to be potential reviewers.

cdamken · 2016-11-21T18:22:10Z

Perhaps the last one is the nicest.

Also note that I added JSON_UNESCAPED_SLASHES to avoid the annoying /...

@PVince81 I'm agree, the last one is the nicest and the easiest to have quick overview.

IMO we could also have it that way or with the option to have in all in one line with an "\n" or other character that can be easy identified and that way it can be separated if required or per line.

PVince81 · 2016-11-22T09:09:13Z

@cdamken the original format already had \n in the lines. But JSON formatters do not replace these to real newlines since they are part of the string. Unless you want to develop a custom formatter ?

I find it neat if all one needs is jsonlint -p

butonic · 2016-11-24T12:13:57Z

this is awesome. Definitely pull the exception up to a top level member. I'd go with the last version. The stacktrace analyzer of PHP seems to accept only the native log format or a full thread dump ... so we need to make this as humanly readable as possible.

PVince81 · 2016-11-24T13:50:42Z

Ok, will do:

keep only third variant
add back the "sanitize members" logic to that variant
some unit testing, hopefully

PVince81 · 2016-11-24T14:52:30Z

check if the additional params need to be carried over to other log implementations (syslog...)

PVince81 · 2018-04-13T13:37:37Z

Slightly related for extra fields: #31121

Might be reusable for this PR about exceptions by passing it as extra field.

PVince81 · 2018-06-06T13:33:48Z

will be obsoleted by #31623

PVince81 added the 2 - Developing label Nov 21, 2016

PVince81 added this to the 9.2 milestone Nov 21, 2016

PVince81 self-assigned this Nov 24, 2016

PVince81 force-pushed the log-experiments branch from 0fd9261 to 423ec4b Compare November 24, 2016 14:53

Vincent Petry added 2 commits April 3, 2017 11:37

Move exception to first JSON level in log

519992b

Trigger dummy exception

cf4f12c

PVince81 force-pushed the log-experiments branch from 423ec4b to cf4f12c Compare April 3, 2017 09:37

PVince81 modified the milestones: triage, 10.0 May 4, 2017

ownclouders added the status/STALE label Dec 7, 2017

PVince81 mentioned this pull request Dec 18, 2017

directly log exception attributes as json members #24736

Closed

ownclouders removed the status/STALE label Apr 13, 2018

ownclouders added the status/STALE label Apr 21, 2018

PVince81 modified the milestones: triage, maybe some day May 22, 2018

PVince81 removed their assignment Jun 5, 2018

PVince81 mentioned this pull request Jun 6, 2018

[stable10][feature] provide original exception via logging events #31623

Merged

9 tasks

PVince81 closed this Jun 6, 2018

ownclouders removed the status/STALE label Jun 6, 2018

PVince81 deleted the log-experiments branch September 27, 2018 13:31

lock bot locked as resolved and limited conversation to collaborators Sep 27, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log format experiments #26676

Log format experiments #26676

PVince81 commented Nov 21, 2016

PVince81 commented Nov 21, 2016

mention-bot commented Nov 21, 2016

cdamken commented Nov 21, 2016

PVince81 commented Nov 22, 2016

butonic commented Nov 24, 2016

PVince81 commented Nov 24, 2016 •

edited

Loading

PVince81 commented Nov 24, 2016

PVince81 commented Apr 13, 2018

PVince81 commented Jun 6, 2018

Log format experiments #26676

Log format experiments #26676

Conversation

PVince81 commented Nov 21, 2016

Log exception on the same level as other fields with string stack trace

Log on same level as other fields but with JSON stack trace

Log on same level as other fields but take the string trace rows and put these into a JSON array

PVince81 commented Nov 21, 2016

mention-bot commented Nov 21, 2016

cdamken commented Nov 21, 2016

PVince81 commented Nov 22, 2016

butonic commented Nov 24, 2016

PVince81 commented Nov 24, 2016 • edited Loading

PVince81 commented Nov 24, 2016

PVince81 commented Apr 13, 2018

PVince81 commented Jun 6, 2018

PVince81 commented Nov 24, 2016 •

edited

Loading