[syslog-ng] syslog-ng, json and handle escaping properly

[Arthur Lambert]

> log {
>   source { example-msg-generator(num(1)
template("{\"category\":\"BOOT\",\"level\":\"INFO\",\"message\":\"Check
pstore partition..\"}")); };
>   parser { json-parser(); };
>   destination { file(/dev/stdout template("$(format-json --key
category,level,message timestamp=${ISODATE})\n")); };
>};

Ok so first I update the syslog-ng config file with your modification

diff --git a/board/xxx/xxx/rootfs/etc/syslog-ng.conf
b/board/xxx/xxx/rootfs/etc/syslog-ng.conf
index c28ea5e59d..6b93ce24b8 100644
--- a/board/xxx/xxx/rootfs/etc/syslog-ng.conf
+++ b/board/xxxx/xxx/rootfs/etc/syslog-ng.conf
@@ -4,10 +4,6 @@ filter f_middleware {
     facility("local1");
 };
-template t_json_filetemplate {
-    template("{\"timestamp\":\"${ISODATE}\",${MESSAGE}\n");
-};
 source s_kernel {
        file("/proc/kmsg" program_override("kernel"));
 };
@@ -21,7 +17,8 @@ destination d_kernel {
 };
 destination d_middleware {
-       file("/data/logs/middleware.log", template(t_json_filetemplate));
+       file(/data/logs/middleware.log template("$(format-json --key
category,level,message timestamp=${ISODATE})\n"));;
+
 };
 log {
@@ -31,6 +28,7 @@ log {

 log {
        source(s_middleware);
+       parser { json-parser(); };
        filter(f_middleware);
        destination(d_middleware);
 };

I also add the '{' in my macro log

diff --git a/log/log_private.h b/log/log_private.h
index b1e2dd31..09e875e1 100644
--- a/log/log_private.h
+++ b/log/log_private.h
@@ -18,7 +18,7 @@
 #define _PRINT_DEBUG(M, ...)
    \
        do {
     \
-               syslog(LOG_DEBUG,
"\"category\":\"%s\",\"level\":\"DEBUG\",\"message\":\"" M "%s\"}\n",
__DIR__, __VA_ARGS__); \
+               syslog(LOG_DEBUG,
"{\"category\":\"%s\",\"level\":\"DEBUG\",\"message\":\"" M "%s\"}\n",
__DIR__, __VA_ARGS__); \
        } while (0)
 #else
@@ -28,32 +28,32 @@
 #define _PRINT_INF_GOTO(M, ...)
                     \
        do {
                     \
-               syslog(LOG_DEBUG,
"\"category\":\"%s\",\"level\":\"INFO\",\"message\":\"" M "%s\"}\n",
__DIR__, __VA_ARGS__); \
+               syslog(LOG_DEBUG,
"{\"category\":\"%s\",\"level\":\"INFO\",\"message\":\"" M "%s\"}\n",
__DIR__, __VA_ARGS__); \
                errno = 0;
                     \
                goto error;
                    \
(...)
 #endif /* !LOG_PRIVATE_H_ */

So basically I suppose that your modification allows to syslog-ng  to
understand by itself that there is an extra pair key/value
in my format and that I am using JSON format.  So let's do some test now...

int main (void)
{
  PRINT_DEBUG ("Test simple.");
  PRINT_DEBUG ("\nTest with return line\n.");
  PRINT_DEBUG ("Test with json inside message : {\"key\" : \"%d\", \"key2\"
: \"%d\"} ", 42, 21);
  PRINT_DEBUG ("Test simple2.");
  PRINT_DEBUG ("Begin. Program name : %s", argv[0]);
 (...)
}

Result :

# cat /data/logs/middleware.log
{"timestamp":"2020-04-24T15:36:28+02:00","message":"Test
simple.","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:36:28+02:00","message":"Test
simple2.","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:36:28+02:00","message":"Begin. Program name :
nano_core","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:36:28+02:00","message":"Board config :
nano_proto1","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:36:28+02:00","message":"Initialize
GPIO..","level":"INFO","category":"GPIO_MANAGER"}
{"timestamp":"2020-04-24T15:36:28+02:00","message":"Synchronize dictionnary
with current rootfs content","level":"INFO","category":"AUDIO_MANAGER"}

As you can see, the line with \n and the JSON debug output is not in the
final log. It was not in a good format for the JSON syslog-ng parser.
How can I fix that? Now that syslog-ng is able to understand that there is
a category, a level, a message in my JSON. I cannot just ask for
syslog-ng to use the escape template only on the column with message key
before sending the message to the parser?

I am able to fix the \n issue by using unix-dgram instead of unix-stream
but without really understand why. New result after using unix-dgram :

{"timestamp":"2020-04-24T15:58:09+02:00","message":"Test
simple.","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:58:09+02:00","message":"\nTest with return
line\n.","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:58:09+02:00","message":"Test
simple2.","level":"DEBUG","category":"MPU_CORE"}
{"timestamp":"2020-04-24T15:58:09+02:00","message":"Begin. Program name :
nano_core","level":"DEBUG","category":"MPU_CORE"}
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.balabit.hu/pipermail/syslog-ng/attachments/20200424/ccc88d27/attachment-0001.html>