Skip to content

Commit b577362

Browse files
mishamyteclaude
andcommitted
fix: trim trailing newline from formatted entry bodies
A custom ITextFormatter terminates the body the way a stream sink needs: the stock Console/File output templates render a trailing newline via {NewLine}, and {Exception} renders as Exception.ToString() + Environment.NewLine. That newline is record framing -- load-bearing for Console/File, where it separates entries in the output stream -- but a Loki entry is a JSON string value inside values, framed by the payload itself. Left in place it is stored as content and renders as a blank line in Grafana. Interior newlines are untouched. v8 trimmed here (LokiBatchFormatter.GenerateEntry did TrimEnd('\r', '\n')); the V9 rewrite dropped it. The built-in LokiJsonTextFormatter closes on '}', so default output is byte-identical. There is no template-side workaround: a template ending in {Exception} emits a trailing newline whenever an event carries an exception, whether or not {NewLine} is present. Fixes #347 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 59f4b79 commit b577362

4 files changed

Lines changed: 186 additions & 7 deletions

File tree

README.md

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -413,6 +413,13 @@ override `Format` or `SanitizePropertyName`, then pass it via `textFormatter`:
413413
}
414414
```
415415

416+
**Trailing newlines.** Any trailing `\r` / `\n` a formatter leaves is stripped before the body is written — always, and
417+
not configurable. A Loki entry is a JSON string value, so unlike Console or File — where that newline separates records
418+
in the stream — it would otherwise be stored as content and show up as a blank line in Grafana. This matters for output
419+
templates: both `{NewLine}` and `{Exception}` render one, so a template ending in `{Exception}` produces a trailing
420+
newline whenever an event carries an exception. Newlines *inside* a body are preserved; a body that deliberately ends in
421+
one loses it. This matches v8.
422+
416423
**Custom exception formatter.** Exception serialization is delegated to `ILokiExceptionFormatter`. The default
417424
(`LokiExceptionFormatter`) recursively writes `Type`, `Message`, `Source`, `StackTrace` and inner exceptions. Replace it
418425
to scrub PII, change the shape, or suppress stack traces:

src/Serilog.Sinks.Grafana.Loki/Infrastructure/Utf8TextWriter.fs

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -70,8 +70,10 @@ type internal Utf8TextWriter(bufferWriter: PooledByteBufferWriter) =
7070
let written = Encoding.UTF8.GetBytes(value, span)
7171
writer.Advance(written)
7272

73-
// Serilog formatters end log lines with WriteLine(); route through Write so
74-
// the newline is encoded into the same pooled buffer rather than flushed.
73+
// Some formatters terminate a line with WriteLine() (CompactJsonFormatter does; the
74+
// output-template formatters instead Write() Environment.NewLine themselves). Route it
75+
// through Write so the newline lands in the same pooled buffer rather than being flushed.
76+
// Whichever way it arrives, Serialization strips it from the tail of a Loki entry body.
7577
override self.WriteLine(value: string) =
7678
self.Write(value)
7779
self.Write('\n')

src/Serilog.Sinks.Grafana.Loki/Serialization.fs

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,10 @@ module internal Serialization =
6060
let private jStream = JsonEncodedText.Encode "stream"
6161
let private jValues = JsonEncodedText.Encode "values"
6262

63+
/// Trailing bytes stripped from a formatted body. Bound once: an inline "\r\n"B literal
64+
/// allocates a fresh array on every evaluation, which in the per-event loop is a regression.
65+
let private lineFraming = "\r\n"B
66+
6367
/// Serializes a complete batch of log events into mainBuffer as a Loki push payload:
6468
///
6569
/// { "streams": [ { "stream": { labels }, "values": [ [ "ts_ns", "body", { meta }? ], ... ] } ] }
@@ -133,7 +137,12 @@ module internal Serialization =
133137
use textWriter = new Utf8TextWriter(buffers.Body)
134138
textFormatter.Format(event, textWriter)
135139

136-
jsonWriter.WriteStringValue(buffers.Body.WrittenSpan)
140+
// A formatter terminates the body the way a stream sink needs — Serilog's stock
141+
// output templates render a trailing newline via {NewLine} or {Exception}. That is
142+
// record framing, load-bearing for Console/File but not here: a Loki entry is a JSON
143+
// string value framed by the payload itself, so a newline left in place is stored as
144+
// content and renders as a blank line in Grafana (#347). Interior newlines survive.
145+
jsonWriter.WriteStringValue(buffers.Body.WrittenSpan.TrimEnd(ReadOnlySpan<byte>(lineFraming)))
137146
buffers.Body.Clear()
138147

139148
// Optional 3rd element: per-line structured metadata, written straight to the

tests/Serilog.Sinks.Grafana.Loki.UnitTests/WireFormatTests.fs

Lines changed: 165 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ module Serilog.Sinks.Grafana.Loki.Tests.WireFormatTests
22

33
open System
44
open System.Diagnostics
5+
open System.Globalization
56
open System.Net
67
open System.Net.Http
78
open System.Text
@@ -12,6 +13,7 @@ open Swensen.Unquote
1213
open Xunit
1314
open Serilog.Events
1415
open Serilog.Formatting
16+
open Serilog.Formatting.Display
1517
open Serilog.Parsing
1618
open Serilog.Core
1719
open Serilog.Sinks.Grafana.Loki
@@ -147,6 +149,17 @@ let private bodyStringOf (stream: JsonElement) (i: int) =
147149
let entry = stream.GetProperty("values")[i]
148150
entry[1].GetString()
149151

152+
/// Serializes a single event through the given formatter and returns the entry body.
153+
let private bodyFrom (formatter: ITextFormatter) (event: LogEvent) =
154+
task {
155+
let handler, sink = makeSink (fun o -> { o with TextFormatter = formatter })
156+
157+
use _ = sink
158+
do! flush sink [ event ]
159+
use doc = handler.LastBodyJson
160+
return bodyStringOf (streamAt 0 doc) 0
161+
}
162+
150163
let private bodyProp (key: string) (stream: JsonElement) (i: int) =
151164
use body = JsonDocument.Parse(bodyStringOf stream i)
152165

@@ -990,22 +1003,170 @@ type private FixedBodyFormatter(text: string) =
9901003
interface ITextFormatter with
9911004
member _.Format(_, output) = output.Write(text)
9921005

1006+
/// Terminates each line with TextWriter.WriteLine rather than an embedded newline.
1007+
type private WriteLineFormatter() =
1008+
interface ITextFormatter with
1009+
member _.Format(_, output) =
1010+
output.WriteLine("first")
1011+
output.WriteLine("last")
1012+
1013+
/// Renders the event's `Body` property verbatim, so events in one batch can differ.
1014+
type private BodyPropertyFormatter() =
1015+
interface ITextFormatter with
1016+
member _.Format(logEvent, output) =
1017+
match logEvent.Properties.TryGetValue "Body" with
1018+
| true, (:? ScalarValue as v) -> output.Write(string v.Value)
1019+
| _ -> ()
1020+
9931021
[<Fact>]
9941022
let ``body: custom ITextFormatter goes through Utf8TextWriter path`` () : Task =
9951023
// When a non-LokiJsonTextFormatter is used, Serialization.fs routes through
9961024
// Utf8TextWriter. Verify the custom body survives unchanged in the Loki payload.
1025+
task {
1026+
let! body = bodyFrom (FixedBodyFormatter("CUSTOM_BODY")) (mkInfo [])
1027+
test <@ body = "CUSTOM_BODY" @>
1028+
}
1029+
1030+
// ── trailing newline trimming (#347) ──────────────────────────────────────────
1031+
1032+
// A fixed timestamp with an explicit offset makes MessageTemplateTextFormatter's rendering
1033+
// deterministic ({Timestamp} formats the DateTimeOffset as-is, without zone conversion), so
1034+
// these tests can assert on the exact body rather than a suffix.
1035+
let private fixedTs = DateTimeOffset(2026, 8, 8, 10, 30, 15, TimeSpan.Zero)
1036+
1037+
/// The stock Console/File output template, rendered under the invariant culture so the
1038+
/// exact-body assertions do not depend on the CI agent's locale. #347 reports the same shape
1039+
/// with plain `{Message}`; only the message rendering differs, not the trailing newline.
1040+
let private stockFormatter =
1041+
MessageTemplateTextFormatter(
1042+
"[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}",
1043+
CultureInfo.InvariantCulture
1044+
)
1045+
1046+
let private mkRendered (ex: exn) =
1047+
LogEvent(
1048+
fixedTs,
1049+
LogEventLevel.Information,
1050+
ex,
1051+
traceParser.Parse("Hello {Name}"),
1052+
[ LogEventProperty("Name", ScalarValue("world")) ]
1053+
)
1054+
1055+
[<Fact>]
1056+
let ``body: stock output template leaves no trailing newline`` () : Task =
1057+
// {NewLine} terminates the rendered line. That is record framing for Console/File,
1058+
// but a Loki entry is a JSON string value, so it must not survive into the payload.
1059+
task {
1060+
let! body = bodyFrom stockFormatter (mkRendered null)
1061+
test <@ body = "[10:30:15 INF] Hello world" @>
1062+
}
1063+
1064+
[<Fact>]
1065+
let ``body: rendered exception leaves no trailing newline`` () : Task =
1066+
// {Exception} renders as Exception.ToString() + Environment.NewLine, so a template ending
1067+
// in {Exception} still emits a trailing newline — dropping {NewLine} is not a workaround.
1068+
task {
1069+
let ex = InvalidOperationException("boom")
1070+
let! body = bodyFrom stockFormatter (mkRendered ex)
1071+
1072+
let expected =
1073+
$"[10:30:15 INF] Hello world{Environment.NewLine}System.InvalidOperationException: boom"
1074+
1075+
test <@ body = expected @>
1076+
}
1077+
1078+
[<Theory>]
1079+
[<InlineData("first\r\nsecond\nthird\r\n", "first\r\nsecond\nthird")>] // interior newlines survive
1080+
[<InlineData("line\n\r\n\n", "line")>] // a whole trailing run goes, not just the last byte
1081+
[<InlineData("line\r", "line")>] // lone CR, not preceded by an LF
1082+
[<InlineData("café 日本語\r\n", "café 日本語")>] // UTF-8 continuations (0x80-0xBF) never look like CR/LF
1083+
[<InlineData("padded \t", "padded \t")>] // spaces and tabs are content, not framing (matches v8)
1084+
[<InlineData("\r\n\r\n", "")>] // a body that is entirely framing trims to empty
1085+
let ``body: only trailing CR and LF are trimmed from a formatted body`` (rendered: string) (expected: string) : Task =
1086+
task {
1087+
let! body = bodyFrom (FixedBodyFormatter(rendered)) (mkInfo [])
1088+
test <@ body = expected @>
1089+
}
1090+
1091+
[<Fact>]
1092+
let ``body: a formatter terminating via WriteLine is trimmed`` () : Task =
1093+
// Utf8TextWriter.WriteLine is its own code path (it appends '\n' rather than
1094+
// Environment.NewLine), and it is how CompactJsonFormatter ends its output.
1095+
task {
1096+
let! body = bodyFrom (WriteLineFormatter()) (mkInfo [])
1097+
test <@ body = "first\nlast" @>
1098+
}
1099+
1100+
[<Fact>]
1101+
let ``body: trimming is per entry across a batch and leaves no stale bytes`` () : Task =
1102+
// The body buffer is reused for every event in a batch. Trimming must not shorten what
1103+
// gets cleared, or a long body's tail would bleed into the next, shorter entry.
9971104
task {
9981105
let handler, sink =
9991106
makeSink (fun o ->
10001107
{ o with
1001-
TextFormatter = FixedBodyFormatter("CUSTOM_BODY")
1108+
TextFormatter = BodyPropertyFormatter()
10021109
})
10031110

10041111
use _ = sink
1005-
do! flush sink [ mkInfo [] ]
1112+
1113+
// Rendered → expected, so the two sides can never drift apart.
1114+
let cases =
1115+
[
1116+
"a long first body that ends in a newline\r\n", "a long first body that ends in a newline"
1117+
"short", "short"
1118+
"third\n", "third"
1119+
"d", "d"
1120+
]
1121+
1122+
let events =
1123+
cases
1124+
|> List.mapi (fun i (rendered, _) ->
1125+
mkEventAt (fixedTs.AddSeconds(float i)) LogEventLevel.Information [ "Body", box rendered ])
1126+
1127+
do! flush sink events
10061128
use doc = handler.LastBodyJson
1007-
let body = bodyStringOf (streamAt 0 doc) 0
1008-
test <@ body = "CUSTOM_BODY" @>
1129+
let s = streamAt 0 doc
1130+
let actual = List.init cases.Length (bodyStringOf s)
1131+
1132+
test <@ actual = List.map snd cases @>
1133+
}
1134+
1135+
[<Fact>]
1136+
let ``body: a trimmed body still carries structured metadata`` () : Task =
1137+
// The trimmed WriteStringValue hands the writer straight to the metadata element;
1138+
// a shortened body must not disturb the optional 3rd entry element.
1139+
task {
1140+
let handler, sink =
1141+
makeSink (fun o ->
1142+
{ o with
1143+
TextFormatter = FixedBodyFormatter("meta body\r\n")
1144+
PropertiesAsStructuredMetadata = [| "RequestId" |]
1145+
})
1146+
1147+
use _ = sink
1148+
do! flush sink [ mkInfo [ "RequestId", box "req-42" ] ]
1149+
use doc = handler.LastBodyJson
1150+
let s = streamAt 0 doc
1151+
test <@ bodyStringOf s 0 = "meta body" @>
1152+
test <@ entryElementCount s 0 = 3 @>
1153+
test <@ metadataProp "RequestId" s 0 = Some "req-42" @>
1154+
}
1155+
1156+
[<Fact>]
1157+
let ``body: built-in formatter output is unaffected by trimming`` () : Task =
1158+
// The default path emits JSON closing on '}', so the trim finds nothing to strip and the
1159+
// payload stays byte-identical — properties included, not just the final character.
1160+
task {
1161+
let handler, sink = makeSink id
1162+
use _ = sink
1163+
do! flush sink [ mkInfo [ "Note", box "value" ] ]
1164+
use doc = handler.LastBodyJson
1165+
let s = streamAt 0 doc
1166+
let body = bodyStringOf s 0
1167+
// bodyProp parses the body, so it also asserts the payload is still valid JSON.
1168+
test <@ body.EndsWith("}") @>
1169+
test <@ bodyProp "Note" s 0 = Some "value" @>
10091170
}
10101171

10111172
// ── HTTP error response path ──────────────────────────────────────────────────

0 commit comments

Comments
 (0)