Skip to content

gst/gstinfo: logging: structured JSON CEE output, initial implementation

Daniel Pocock requested to merge pocock/gstreamer:pocock/json_cee into master

I started looking at CEE-style JSON logs to help troubleshoot distributed applications in the WebRTC world

Has anybody already looked at this before?

Are there any other structured logging formats that people are interested in?

Some practical comments:

The initial implementation simply logs to stdout or file, just like the current logging. People still need some external tool to read the JSON events from logfiles into their preferred database, Elasticsearch, etc. People who want to move the events through Syslog can use rsyslog module "imfile" to read the JSON into proper Syslog events and add the "@cee:" prefix

I'm also implementing this in reSIProcate, it is now available for the SIP proxy, TURN server and reConServer (conferencing, SBC): https://github.com/resiprocate/resiprocate/commit/d1df9aeb956be79253560fe3628b3f37a4ef94f2

People can combine the JSON CEE events from all their applications into a single database for easier sharing and analysis.

Here is the official list of CEE fields for JSON: https://cee.mitre.org/language/1.0-beta1/core-profile.html

Three fields are mandatory: hostname, pname and time.

Some sites link to an extended list of CEE fields on the Fedora wiki but the Fedora page is gone. The list is available here in archive.org: https://web.archive.org/web/20161110090322/https://fedorahosted.org/lumberjack/wiki/FieldList

My initial attempt to do this in each application will put the plain text log string into the msg field and add the other fields that we already have, e.g. thread ID, timestamp, component. I won't attempt any deeper analysis of the message body right now. A more advanced attempt to do structured logging would provide some mechanism for the application to add extra fields to any log message, for example, webrtcbin might include the o= and s= lines from SDP as extra fields in every JSON event about a particular session.

Here is an example of a log event:

{"time":"2021-07-02T21:09:55.992418000Z","native!time!elapsed":3480327,"proc!id":26828,"proc!tid":4918210720,"pri":"DEBUG","subsys":"nettime","file!name":"gstnettimeprovider.c","file!line":183,"native!function":"gst_net_time_provider_thread","native!object":"<nettimeprovider0>","msg":"time provider thread is running","pname":"build/tests/examples/netclock/netclock-server","appname":"netclock-prod","hostname":"laptop1.example.org"}

Here is the same line pretty-printed:

{
    "appname": "netclock-prod",
    "file!line": 183,
    "file!name": "gstnettimeprovider.c",
    "hostname": "laptop1.example.org",
    "msg": "time provider thread is running",
    "native!function": "gst_net_time_provider_thread",
    "native!object": "<nettimeprovider0>",
    "native!time!elapsed": 3480327,
    "pname": "build/tests/examples/netclock/netclock-server",
    "pri": "DEBUG",
    "proc!id": 26828,
    "proc!tid": 4918210720,
    "subsys": "nettime",
    "time": "2021-07-02T21:09:55.992418000Z"
}

and this is the command line I used to run the example:

GST_DEBUG="5" \
GST_DEBUG_STRUCTURED=JSON_CEE \
GST_DEBUG_APPNAME="netclock-prod" \
build/tests/examples/netclock/netclock-server

Merge request reports