Optional structured logging to stdout

[alistairking]

If the KENTIK_LOG_FMT environment variable is set to json, then
output a more structured log message.

Like so:

{
  "time": "2022-08-31T13:30:00.954336665Z",
  "level": "info",
  "prefix": "[CHF]",
  "message": "Sending over http to [http://127.0.0.1:20012] -- Max conn Q: 1000",
  "caller": "/home/alistair/src/chf/pkg/client/packer.go:241"
}

More examples:

{"time":"2022-08-31T13:30:00.954413342Z","level":"info","prefix":"[CHF]","message":"HTTP SendHttpRequest 3: online for 1013:er4_ipfix:1546","caller":"/home/alistair/src/chf/pkg/common/tx/http/http.go:229"}
{"time":"2022-08-31T13:30:00.954605158Z","level":"info","prefix":"[CHF]","message":"CHF Client UDP listener polling","caller":"/home/alistair/src/chf/pkg/client/listen/udp-listen.go:63"}
{"time":"2022-08-31T13:30:00.954635045Z","level":"info","prefix":"[CHF]","message":"CHF Client HTTP listener polling","caller":"/home/alistair/src/chf/pkg/client/listen/http-listen.go:108"}
{"time":"2022-08-31T13:30:00.954663109Z","level":"info","prefix":"[CHF]","message":"spawning 6 decoders\n","caller":"/home/alistair/src/chf/pkg/client/client.go:1172"}
{"time":"2022-08-31T13:30:00.954672927Z","level":"info","prefix":"[CHF]","message":"Starting low traffic loop @ 20m0s. Exit if no traffic in this time","caller":"/home/alistair/src/chf/pkg/client/client.go:1571"}
{"time":"2022-08-31T13:30:04.461727007Z","level":"info","prefix":"[CHF] [BGP]","message":"Received EOR: \u0026{TimeFloat:0 Neigh:{IP:::1 Msg:{Update:{Attribute:{ASPath:[] ASSet:[] ConfedPath:[] ConfedSet:[] Origin: Community:[] ExtCommunity:[] PrefixSid:{LabelIndex:0}} Announce:{IPs:map[] IP6s:map[] IPL3VPN:map[] IP6L3VPN:map[] IPMPLS:map[] IP6MPLS:map[]} Withdraw:{IPs:[] IP6s:[] IPL3VPN:[] IP6L3VPN:[] IPMPLS:[] IP6MPLS:[]} EOR:{AFI:ipv6 SAFI:unicast}}}} Notification:}","caller":"/home/alistair/src/chf/pkg/common/bgp/bgp.go:180"}

[cleroux]

Can we change this to message to match zerolog?

Suggested change

	Message string `json:"msg"`
	Message string `json:"message"`

Example from zerolog:

{
"level":"warn",
"requestID":"insights_162c07ce-b6a6-41fd-a08b-1c3dc29db242",
"companyID":3041,
"userID":6643,
"error":"pq: column \"kt_aws_src_region\" does not exist",
"query":"/* service: insights , insightName: comparison.aws.region_to_region.internal */ SELECT    *,    (f_sum_both_bytes * 8) / (1661863801 - 1661259001) AS bps  FROM    (      SELECT        kt_aws_src_region,        kt_aws_dst_region,        sum(both_bytes) as f_sum_both_bytes,        rank() OVER (          ORDER BY            sum(both_bytes) DESC        ) AS rank      FROM        all_devices      WHERE        i_fast_dataset = TRUE        AND app_protocol IN (0, 1, 2, 3, 4)        AND i_sub_limit = 300        AND simple_trf_prof = 'internal'        AND kt_cloud_provider = $_kntq$AWS$_kntq$        AND ctimestamp > 1661259001        AND ctimestamp <= 1661863801        AND kt_aws_src_region != kt_aws_dst_region        AND i_device_type != 'router'      GROUP BY        kt_aws_src_region,        kt_aws_dst_region      ORDER BY        f_sum_both_bytes DESC      LIMIT 100    ) sq1",
"time":"2022-08-30T12:50:02Z",
"caller":"broker.go:391",
"message":"failed to run query"
}

[alistairking]

Yep, sure. See 05c2e69

[808codist]

Two questions re: "prefix"

• Are the reasons for adding a prefix in logs still valid?
• Assuming we can't remove prefix, can we omit the square brackets in the JSON version?

[alistairking]

Two questions re: "prefix"

* Are the reasons for adding a prefix in logs still valid?

* Assuming we can't remove prefix, can we omit the square brackets in the JSON version?

The prefix is just a string that callers provide, there's been a convention to put brackets around the prefix, and in some cases there are multiple "prefixes" in the string:

{
  "time": "2022-08-31T13:30:04.461727007Z",
  "level": "info",
  "prefix": "[CHF] [BGP]",
  "message": "Received EOR: &{TimeFloat:0 Neigh:{IP:::1 Msg:{Update:{Attribute:{ASPath:[] ASSet:[] ConfedPath:[] ConfedSet:[] Origin: Community:[] ExtCommunity:[] PrefixSid:{LabelIndex:0}} Announce:{IPs:map[] IP6s:map[] IPL3VPN:map[] IP6L3VPN:map[] IPMPLS:map[] IP6MPLS:map[]} Withdraw:{IPs:[] IP6s:[] IPL3VPN:[] IP6L3VPN:[] IPMPLS:[] IP6MPLS:[]} EOR:{AFI:ipv6 SAFI:unicast}}}} Notification:}",
  "caller": "/home/alistair/src/chf/pkg/common/bgp/bgp.go:180"
}

In 05c2e69 I at least trimmed the trailing whitespace, but I'm not sure that removing the brackets makes sense. Happy to be convinced otherwise though.

[cleroux]

Nice. Good idea to make caller match too.
I worry this will prolong golog's existence but the short term benefits are worth it.
In case it needs to be said, there are still reasons to prefer zerolog. Off the top of my head:

• More efficient memory usage
• Context-based logging lets us attach values to the logger that persist through the call stack.

[alistairking]

Yeah, I agree completely. For me the biggest benefit of zerolog is that it's actually structured logging so arbitrary K/Vs can be attached to the log rather than crafted into the message sentence.

[cleroux]

IIRC, the default string serialization format of time.Time is not suitable for logging. I'm curious what the output JSON actually looks like here.
You may want to have this struct implement the json.Marshaler interface so you can format the time explicitly.
Looking at the tests, I don't see any that actually verify the JSON output format. If you wish to do that and need an example, I have some tests that do that here.

[808codist]

Default serialization:

{"time":"2022-09-07T19:32:55.049633946Z","name":"./kproxy [2189:versa_br1_our1:404050] [3044075]","level":"info","prefix":"[CHF]","caller":"/home/debian/src/chf/pkg/common/tx/http/http.go:84","message":"HTTP sendTarget 3: online for https://flow.OUR1.kentik.com/chf, UA: Kentik: dirty-babf062ea69594d98297c1de532b1bcf7939c016 Built on Linux 5.10.16.3-microsoft-standard-WSL2 x86_64 [go version go1.18.5 linux/amd64] Debian GNU/Linux 9.13 (stretch) (Tue, 6 Sep 2022 21:31:54 -1000): 2189:versa_br1_our1:404050"}
{"time":"2022-09-07T19:32:56.603166385Z","name":"./kproxy [2189:versa_br2_our1:404055] [3044066]","level":"info","prefix":"[CHF]","caller":"/home/debian/src/chf/pkg/common/tx/http/http.go:84","message":"HTTP sendTarget 3: online for https://flow.OUR1.kentik.com/chf, UA: Kentik: dirty-babf062ea69594d98297c1de532b1bcf7939c016 Built on Linux 5.10.16.3-microsoft-standard-WSL2 x86_64 [go version go1.18.5 linux/amd64] Debian GNU/Linux 9.13 (stretch) (Tue, 6 Sep 2022 21:31:54 -1000): 2189:versa_br2_our1:404055"}

Good enough?

[cleroux]

Yeah actually I think that should be fine. Thanks.