Reorder the fields in the json output for better readability; Support using File outputs when using threads

chronicles/log_output.nim

@@ -80,9 +80,9 @@ template bnd(s): NimNode =
   newIdentNode(s)
 
 template deref(so: StreamOutputRef): auto =
-  outputs(so.Stream)[so.outputId]
+  (outputs(so.Stream)[])[so.outputId]
 
-proc open*(o: var FileOutput, path: string, mode = fmAppend): bool =
+proc open*(o: ptr FileOutput, path: string, mode = fmAppend): bool =
   if o.outFile != nil:
     close(o.outFile)
     o.outFile = nil
@@ -94,7 +94,7 @@ proc open*(o: var FileOutput, path: string, mode = fmAppend): bool =
     o.outPath = path
     o.mode = mode
 
-proc open*(o: var FileOutput, file: File): bool =
+proc open*(o: ptr FileOutput, file: File): bool =
   if o.outFile != nil:
     close(o.outFile)
     o.outPath = ""
@@ -549,19 +549,19 @@ proc initLogRecord*(r: var JsonRecord,
 
   r.outStream = init OutputStream
   r.jsonWriter = JsonWriter.init(r.outStream, pretty = false)
-
   r.jsonWriter.beginRecord()
-  r.jsonWriter.writeField "msg", name
 
   if level != NONE:
-    r.jsonWriter.writeField "level", level.shortName
-
-  if topics.len > 0:
-    r.jsonWriter.writeField "topics", topics
+    r.jsonWriter.writeField "lvl", level.shortName
 
   when r.timestamps != NoTimestamps:
     r.jsonWriter.writeField "ts", r.timestamp()
 
+  r.jsonWriter.writeField "msg", name
+
+  if topics.len > 0:
+    r.jsonWriter.writeField "topics", topics
+
 proc setProperty*(r: var JsonRecord, key: string, val: auto) =
   r.jsonWriter.writeField key, val
 
@@ -631,8 +631,13 @@ macro createStreamSymbol(name: untyped, RecordType: typedesc,
     template tlsSlot*(S: type `name`): auto = `tlsSlot`
 
     var `outputs` = `outputsTuple`
-    template outputs*(S: type `name`): auto = `outputs`
-    template output* (S: type `name`): auto = `outputs`[0]
+
+    # The output objects are currently not GC-safe because they contain
+    # strings (the `outPath` field). Since these templates are not used
+    # in situations where these paths are modified, it's safe to provide
+    # a gcsafe override until we switch to Nim's --newruntime.
+    template outputs*(S: type `name`): auto = ({.gcsafe.}: addr `outputs`)
+    template output* (S: type `name`): auto = ({.gcsafe.}: addr `outputs`[0])
 
 # This is a placeholder that will be overriden in the user code.
 # XXX: replace that with a proper check that the user type requires

tests/customization/formatters.test

@@ -28,6 +28,6 @@ WRN Got attestation 2
 
 """
 
-json.txt="""{"msg":"Got attestation 1","level":"INF","tid":7011,"attestation":"some attestation","peer":"Peer 1","it":"not renamed","asig":"some signature","a":"renamed","complex_a_concatenation":"X"}
-{"msg":"Got attestation 2","level":"WRN","tid":7011,"attestation":"some attestation","peer":"Peer 1","it":"not renamed","attestationsig":"some signature","attestation":"renamed","complex_attestation_concatenation":"X"}
+json.txt="""{"lvl":"INF","msg":"Got attestation 1","tid":0,"attestation":"some attestation","peer":"Peer 1","it":"not renamed","asig":"some signature","a":"renamed","complex_a_concatenation":"X"}
+{"lvl":"WRN","msg":"Got attestation 2","tid":0,"attestation":"some attestation","peer":"Peer 1","it":"not renamed","attestationsig":"some signature","attestation":"renamed","complex_attestation_concatenation":"X"}
 """

tests/sinks/json_file_stdout.test

@@ -4,10 +4,10 @@ chronicles_colors=None
 chronicles_timestamps=None
 
 [Output]
-stdout="""{"msg":"main started","level":"INF","topics":"main","tid":0,"a":10,"arg":50,"b":"inner-b","c":10,"d":"some-d","x":16,"z":20}
-{"msg":"exiting","level":"INF","tid":0,"a":12,"b":"overriden-b","c":100,"msg":"bye bye","x":16}
+stdout="""{"lvl":"INF","msg":"main started","topics":"main","tid":13250,"a":10,"arg":50,"b":"inner-b","c":10,"d":"some-d","x":16,"z":20}
+{"lvl":"INF","msg":"exiting","tid":0,"a":12,"b":"overriden-b","c":100,"msg":"bye bye","x":16}
 """
 
-lexical_scopes.log="""{"msg":"main started","level":"INF","topics":"main","tid":0,"a":10,"arg":50,"b":"inner-b","c":10,"d":"some-d","x":16,"z":20}
-{"msg":"exiting","level":"INF","tid":0,"a":12,"b":"overriden-b","c":100,"msg":"bye bye","x":16}
+lexical_scopes.log="""{"lvl":"INF","msg":"main started","topics":"main","tid":13250,"a":10,"arg":50,"b":"inner-b","c":10,"d":"some-d","x":16,"z":20}
+{"lvl":"INF","msg":"exiting","tid":0,"a":12,"b":"overriden-b","c":100,"msg":"bye bye","x":16}
 """

tests/sinks/tripple_sink.test

@@ -28,6 +28,6 @@ INF exiting
 
 """
 
-log.json="""{"msg":"main started","level":"INF","topics":"main","tid":0,"a":10,"arg":50,"b":"inner-b","c":10,"d":"some-d","x":16,"z":20}
-{"msg":"exiting","level":"INF","tid":0,"a":12,"b":"overriden-b","c":100,"msg":"bye bye","x":16}
+log.json="""{"lvl":"INF","msg":"main started","topics":"main","tid":0,"a":10,"arg":50,"b":"inner-b","c":10,"d":"some-d","x":16,"z":20}
+{"lvl":"INF","msg":"exiting","tid":0,"a":12,"b":"overriden-b","c":100,"msg":"bye bye","x":16}
 """

tests/streams/streams_different_formats.test

@@ -8,7 +8,7 @@ stdout="""INF logging to foo                             tid=0
 INF logging to foo                             tid=0
 """
 
-default.log="""{"msg":"dynamic scope starts","level":"INF","tid":0,"reqId":10,"userId":20}
-{"msg":"dynamic scope ends","level":"INF","tid":0,"reqId":10,"userId":20}
-{"msg":"about to exit main","level":"WRN","tid":0}
+default.log="""{"lvl":"INF","msg":"dynamic scope starts","tid":0,"reqId":10,"userId":20}
+{"lvl":"INF","msg":"dynamic scope ends","tid":0,"reqId":10,"userId":20}
+{"lvl":"WRN","msg":"about to exit main","tid":0}
 """