logdefer.serializer.json source code

1 module logdefer.serializer.json;
2 
3 
4 import logdefer.common : DelegateWriter, EventContext, LogEntry;
5 
6 import std.array : Appender;
7 import std.string : format;
8 import std.traits : isSafe;
9 import std.utf : stride, UTFException;
10 
11 import logdefer.time.duration : Seconds;
12 
13 /**
14   Basic JSON serializer that outputs in the standard Log::Defer format.
15   See https://metacpan.org/pod/Log::Defer for more details on the format
16   and tools to render it.
17   Since output format is fixed this uses an optimized algorithm.
18   This is about 2x faster than using std.json
19   */
20 @safe
21 struct JSONSerializer(Writer = DelegateWriter) if (isSafe!Writer)
22 {
23     public:
24 
25         @disable this();
26 
27         this(Writer writer)
28         {
29             writer_ = writer;
30         }
31 
32         void opCall(const ref EventContext eventContext)
33         {
34             write("{");
35 
36             serializeEventTimers(eventContext);
37             serializeLogs(eventContext);
38             serializeMetadata(eventContext);
39             serializeUserTimers(eventContext);
40 
41             write("}");
42 
43             writer_(buffer_[0..length_].idup);
44 
45             length_ = 0;
46         }
47 
48     private:
49 
50         Writer writer_ = void;
51 
52         // Maximum JSON size
53         immutable enum BUFFER_SIZE = 32 * 1024;
54 
55         char[BUFFER_SIZE] buffer_;
56         uint length_;
57 
58         void serializeEventTimers(const ref EventContext eventContext)
59         {
60             writeAll([
61                 `"start":`,
62                 "%s".format(eventContext.realStartTime),
63                 `,"end":`,
64                 "%.6f".format(eventContext.endOffset.toUnits!Seconds),
65             ]);
66         }
67 
68         void serializeMetadata(const ref EventContext eventContext)
69         {
70             if (eventContext.metadata)
71             {
72                 write(`,"data":{`);
73                 foreach(const ref entry; eventContext.metadata.byKeyValue())
74                 {
75                     writeAll([
76                         `"`,
77                         encode(entry.key),
78                         `":"`,
79                         encode(entry.value),
80                         `",`
81                     ]);
82                 }
83                 buffer_[length_ - 1] = '}';
84             }
85         }
86 
87         void serializeLogs(const ref EventContext eventContext)
88         {
89             if (eventContext.logs.data)
90             {
91                 write(`,"logs":[`);
92 
93                 foreach(ref entry; eventContext.logs.data)
94                 {
95                     writeAll([
96                         "[",
97                         "%.6f".format(entry.endOffset.toUnits!Seconds),
98                         ",",
99                         "%d".format(entry.verbosity),
100                         `,"`,
101                         encode(entry.msg),
102                         `"],`
103                     ]);
104                 }
105                 buffer_[length_ - 1] = ']'; 
106             }
107         }
108 
109         void serializeUserTimers(const ref EventContext eventContext)
110         {
111             if (eventContext.timers.data)
112             {
113                 write(`,"timers":[`);
114 
115                 foreach(ref timer; eventContext.timers.data)
116                 {
117                     writeAll([
118                         `["`,
119                         timer.name,
120                         `",`,
121                         "%.6f".format(timer.start.toUnits!Seconds),
122                         `,`,
123                         "%.6f".format(timer.end.toUnits!Seconds),
124                         `],`
125                     ]);
126                 }
127                 buffer_[length_ - 1] = ']';
128             }
129         }
130 
131         void writeAll(string[] strings)
132         {
133             foreach(ref str; strings)
134             {
135                 write(str);
136             }
137         }
138 
139         void write(string output)
140         {
141             foreach(ref c; output)
142             {
143                 buffer_[length_++] = c;
144             }
145         }
146 
147 
148         // Fast lookup for escapes
149         static immutable string[256] mapping;
150         shared static this()
151         {
152             foreach (i; 0..32)
153             {
154                 mapping[i] = `\u` ~ format("%04x", i);
155             }
156 
157             mapping[8] = `\b`;
158             mapping[9] = `\t`;
159             mapping[10] = `\n`;
160             mapping[12] = `\f`;
161             mapping[13] = `\r`;
162             mapping[34] = `\"`;
163             mapping[47] = `\/`;
164             mapping[92] = `\\`;
165         }
166 
167         /*
168            Encodes string literals.  Input is assumed to be valid UTF8 string
169            and will throw a UTFException if this is not the case
170 
171            - Control characters 0x0-0x1F plus 34, 47, 92 are escaped
172            - Multibyte characters are written as is (not encoded using \uXXXX)
173            */
174         string encode(string input)
175         {
176             auto buffer = Appender!string();
177             // Should be enough to handle most cases (except where most
178             // characters are control characters
179             buffer.reserve(input.length * 2);
180 
181             uint index;
182             while (index < input.length)
183             {   
184                 auto size = input.stride(index);
185                 // Single byte character
186                 if (size == 1)
187                 {
188                     const char c = input[index++];
189                     const string mapped = mapping[c];
190 
191                     // char is mapped to escape
192                     if (mapped != string.init)
193                     {
194                         buffer.put(mapped);
195                     }
196                     // normal char
197                     else
198                     {
199                         buffer.put(c);
200                     }
201                 }
202                 // Multibyte
203                 else
204                 {
205                     buffer.put(input[index..index+size]);
206                     index += size;
207                 }
208             }
209 
210             return buffer.data;
211         }
212 }
213 
214 version (unittest)
215 {
216     import core.exception : RangeError;
217     import std.conv : hexString;
218     import std.exception : assertThrown;
219     import std.json : JSONValue, parseJSON;
220     import std.stdio : writeln;
221 
222     import logdefer.time.duration : Millis, Nanos;
223     import unixtime : UnixTimeHiRes;
224 
225     auto now = UnixTimeHiRes(1434608500);
226     Nanos duration = Millis(250);
227 }
228 
229 unittest
230 {
231     writeln("[UnitTest JSONSerializer] - basic start and end timer");
232 
233     auto ec = EventContext();
234     ec.realStartTime = now;
235     ec.endOffset = duration;
236     
237     JSONValue json;
238     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
239     serializer(ec);
240 
241     assert(json["start"].floating == 1434608500.0);
242     assert(json["end"].floating == 0.250000);
243     assert("logs" !in json);
244     assert("data" !in json);
245 
246 }
247 
248 unittest
249 {
250     writeln("[UnitTest JSONSerializer] - data section");
251 
252     auto ec = EventContext();
253     ec.realStartTime = now;
254     ec.endOffset = duration;
255     ec.metadata["7"] = "2.1";
256     ec.metadata["foo"] = "bar";
257 
258     JSONValue json;
259     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
260     serializer(ec);
261 
262     assert("start" in json);
263     assert("end" in json);
264     assert("logs" !in json);
265     assert("data" in json);
266     assert(json["data"].object().length == 2);
267     assert(json["data"]["7"].str == "2.1");
268     assert(json["data"]["foo"].str == "bar");
269 }
270 
271 unittest
272 {
273     writeln("[UnitTest JSONSerializer] - log entries");
274 
275     auto ec = EventContext();
276     ec.realStartTime = now;
277     ec.endOffset = duration;
278     ec.logs.put(LogEntry(duration, 10, "line 1"));
279     ec.logs.put(LogEntry((duration * 2), 15, "line 2"));
280     ec.logs.put(LogEntry((duration * 3), 15, ""));
281 
282     JSONValue json;
283     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
284     serializer(ec);
285 
286     assert("start" in json);
287     assert("end" in json);
288     assert("logs" in json);
289     assert("data" !in json);
290     assert(json["logs"].array.length == 3);
291 
292     assert(json["logs"][0][0].floating == 0.25);
293     assert(json["logs"][0][1].integer == 10);
294     assert(json["logs"][0][2].str == "line 1");
295 
296     assert(json["logs"][1][0].floating == 0.5);
297     assert(json["logs"][1][1].integer == 15);
298     assert(json["logs"][1][2].str == "line 2");
299 
300     assert(json["logs"][2][0].floating == 0.75);
301     assert(json["logs"][2][1].integer == 15);
302     assert(json["logs"][2][2].str == "");
303 }
304 
305 unittest
306 {
307     writeln("[UnitTest JSONSerializer] - UTF-8");
308 
309     auto ec = EventContext();
310     ec.realStartTime = now;
311     ec.endOffset = duration;
312     ec.metadata[hexString!("e8af b7e6 b182 4944 0a00")] = hexString!("3731 202d 20e9 98bf e5b0 94e6 b395 0a00");
313     ec.logs.put(LogEntry(duration, 1, hexString!("e994 99e8 afaf 0a00")));
314 
315     JSONValue json;
316     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
317     serializer(ec);
318 
319     assert("start" in json);
320     assert("end" in json);
321     assert("logs" in json);
322     assert("data" in json);
323 
324     assert(json["logs"].array.length == 1);
325     assert(json["logs"][0][2].str == hexString!("e994 99e8 afaf 0a00"));
326 
327     assert(json["data"][hexString!("e8af b7e6 b182 4944 0a00")].str == hexString!("3731 202d 20e9 98bf e5b0 94e6 b395 0a00"));
328 }
329 
330 unittest
331 {
332     writeln("[UnitTest JSONSerializer] - invalid UTF-8");
333 
334     auto ec = EventContext();
335     ec.realStartTime = now;
336     ec.endOffset = duration;
337     // Invalid sequence
338     ec.logs.put(LogEntry(duration, 1, hexString!("ff01")));
339 
340     JSONValue json;
341     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
342     assertThrown!UTFException(serializer(ec));
343 }
344 
345 unittest
346 {
347     writeln("[UnitTest JSONSerializer] - control characters");
348 
349     auto ec = EventContext();
350     ec.realStartTime = now;
351     ec.endOffset = duration;
352     ec.logs.put(LogEntry(
353         duration, 10, "\t\tconh\btrol\nchar//a\\cters\0")
354     );
355 
356     JSONValue json;
357     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
358     serializer(ec);
359 
360     assert("start" in json);
361     assert("end" in json);
362     assert("logs" in json);
363 
364     assert(json["logs"][0][2].str == "\t\tconh\btrol\nchar//a\\cters\0");
365 }
366 
367 unittest
368 {
369     writeln("[UnitTest JSONSerializer] - message too long");
370 
371     auto ec = EventContext();
372     ec.realStartTime = now;
373     ec.endOffset = duration;
374 
375     foreach(i; 0..10000)
376     {
377         ec.logs.put(LogEntry(
378             duration, 10, "too long")
379         );
380     }
381 
382     JSONValue json;
383     auto serializer = JSONSerializer!(DelegateWriter)((string msg) { json = parseJSON(msg); });
384     assertThrown!RangeError(serializer(ec));
385 }