JSON CEE structured logging for WebRTC, SIP and XMPP
I've recently added JSON CEE structured logging to reSIProcate and submitted pull requests for identical functionality in some related projects.
The use case for structured logging is quite compelling in the RTC world, which includes WebRTC, SIP and XMPP software. In the early days, we would do everything with a single process like Asterisk and we would only have to deal with a single log file. Today, especially with WebRTC, we often have multiple processes involved in a single phone call or video meeting. When something goes wrong, we need to be able to look at the logs from all of these processes. Structured logging provides a convenient way to combine and analyze the log files.
For structured logging to be useful in a distributed system, every process needs to use the same structure. The syntax of the logs and the semantics of individual values from different processes need to be identical.
JSON CEE is a specific standard for structured logging. It solves this problem. The JSON CEE standard was never fully completed. Nonetheless, it has been documented widely and it appears to be more than good enough for the ecosystem of free, open source RTC applications. Using JSON CEE is far better than every individual SIP and XMPP project reinventing the wheel with their own JSON schema.
Free-form text-based logs can become particularly awkward in the RTC world. For example, we often log multi-line SIP or SDP message bodies as they undergo various transformations in the stack. Text-based log files have no standard way to cope with multi-line log messages. JSON solves this problem.
With free-form log entries, tools have to be adapted to look for certain patterns. Structured logging may eliminate the need for any customization in log analysis tools.
The latest JSON CEE standard 1.0-beta1 is documented here.
Here is an example of a JSON CEE structured log message. Notice it includes a multi-line message body.
{
"hostname": "host1.example.org",
"pri": "DEBUG",
"syslog": {
"level": 7
},
"time": "2023-05-26T23:59:42.616853697Z",
"pname": "testSdp",
"subsys": "RESIP",
"proc": {
"id": "4003132",
"tid": 70366700277776
},
"file": {
"name": "rutil/ParseBuffer.cxx",
"line": 986
},
"native": {
"function": "fail"
},
"msg": "resip/stack/SdpContents.cxx:1648, Parse failed Too many connection addresses in context: Contents\nv=0\no=Evil 3559 3228 IN IP4 192.168.2.122\ns=SIP Call\nt=0 0\nm=audio 17124 RTP/AVP 18\nc=IN IP4 192.168.2.122/127/2000000000[CRLF]\n ^[CRLF]\na=rtpmap:18 G729/8000\n"
}
Adding custom fields to JSON log messages
Applications can add extra fields to the JSON message if they really want to. For example, a SIP application could add the dialog ID to all log entries that relate to a specific dialog. A TURN server, rtpproxy or signalling server such as a SIP proxy could add UDP port numbers in a special field of their log messages. These values would allow reporting tools to quickly filter all log messages from different applications that relate to a specific session.
Progress adding JSON CEE support to popular RTC applications
| reSIProcate | Done: when calling Log::initialize, add Log::JSON_CEE |
|---|---|
| Kamailio | Done: see pull request 2826 and 2848 |
| OpenSIPS | Done: Syslog config and the stderr config |
| Gstreamer | Pull request submitted #847, please follow-up with Gstreamer developers |
| Kurento | Pull request submitted #1, please follow-up with Kurento developers |
| Asterisk | Bug report submitted, see ASTERISK-29517 |
Best practices for implementing JSON CEE support
Applications can output JSON CEE log messages as strings.
To maximize performance and minimize the risk of bugs, it is a good idea to avoid using a JSON library and simply write the JSON CEE log messages using basic string manipulation techniques. For example, in reSIProcate, we write JSON log entries as strings using the C++ stream operator (the code is here). In regular C, such as Gstreamer, the printf function can be used to write JSON log strings.
When using the Syslog API functions, the JSON strings need to be prefixed with the string @cee: like this:
#includesyslog(LOG_CRIT, "@cee: { \"msg\" : \"feed me\" }");
That's all there is too it. Many application developers can simply copy-and-paste from the pull requests mentioned above.
Adding JSON CEE support to dependency libraries and pre-compiled binaries
In some cases, dependency libraries are calling the syslog API and sending log messages directly to syslog.
If the library provides logging callbacks, they may be able to override the syslog calls.
If not, the LD_PRELOAD mechanism can be used to intercept calls to the Syslog API. This is a bit of a hack and may not be able to fill all the fields in the JSON CEE schema.
There is an example in my logredir code.
Build it and they will come
A standard like JSON CEE, even if it was never finished, helps to unify the developers who write the log messages and the developers who create tools to interpret them.
At the most basic level, the log messages from all applications have the same syntax and field names.
More significantly, the standard unifies the semantics of the values in log messages. For exmaple, severity values from one application should be comparable to severity values from another application. This should make life a lot easier for everybody in both development and support teams.
Reporting on JSON CEE data
ElasticSearch/Kibana and the equivalent OpenSearch Dashboard stacks provide a convenient way to store and analyze JSON data sets such as CEE.
There are already many online examples for integrating rsyslog with ElasicSearch or OpenSearch. I was able to make this work by cutting-and-pasting from the examples.
The fact that many people already wrote documents and blogs about doing this with JSON CEE is another good reason for RTC applications to use the CEE schema.
Here are some screenshots:
