Improvement: More mature logging approach

[freefd]

Is your feature request related to a problem? Please describe.
With the current logging approach it's not so easy to distinguish happened things from the logs:

2024/06/10 13:08:42 DBG Debug logging enabled
2024/06/10 13:08:42 INF Frigate Notify - v0.3.0
2024/06/10 13:08:42 INF Starting...
2024/06/10 13:08:42 DBG Loading config file: ./config.yml
2024/06/10 13:08:42 INF Config file loaded.
2024/06/10 13:08:42 DBG Validating config file...
2024/06/10 13:08:42 DBG Checking connection to Frigate server...
2024/06/10 13:08:42 INF Successfully connected to http://frigate:5000
2024/06/10 13:08:42 DBG Frigate server is running version 0.13.2-6476f8a
2024/06/10 13:08:42 DBG MQTT Enabled.
2024/06/10 13:08:42 DBG Events without a snapshot: allow
2024/06/10 13:08:42 DBG Events outside a zone: allow
2024/06/10 13:08:42 DBG All zones included in alerts
2024/06/10 13:08:42 DBG No zones excluded
2024/06/10 13:08:42 DBG All labels included in alerts
2024/06/10 13:08:42 DBG No labels excluded
2024/06/10 13:08:42 DBG Telegram alerting enabled.
2024/06/10 13:08:42 DBG Ntfy alerting enabled.
2024/06/10 13:08:42 INF Config file validated!
2024/06/10 13:08:42 DBG Connecting to MQTT Server...
2024/06/10 13:08:42 INF App running. Press Ctrl-C to quit.
2024/06/10 13:08:42 INF Connected to MQTT.
2024/06/10 13:08:42 INF Subscribed to MQTT topic: frigate/events
2024/06/10 13:10:35 INF New event received event_id=1718025034.99825-2n4h7l
2024/06/10 13:10:35 INF Event Detected camera=camera-name event_id=1718025034.99825-2n4h7l label=person zones=
2024/06/10 13:10:35 DBG Event start time: 2024-06-10 13:10:34 +0000 UTC event_id=1718025034.99825-2n4h7l
2024/06/10 13:10:36 DBG Custom message template used event_id=1718025034.99825-2n4h7l provider=Telegram rendered_template="Detection at 2024-06-10 13:10:34 +0000 UTC\nCamera: <b>camera-name</b>\nLabel: person (70%)\n\n\nLinks: <a href=\"https://domain.tld/cameras/camera-name\">Camera</a>  | <a href=\"https://domain.tld/api/events/1718025034.99825-2n4h7l/clip.mp4\">Event Clip</a> \n\n"
2024/06/10 13:10:36 INF Alert sent event_id=1718025034.99825-2n4h7l provider=Ntfy
2024/06/10 13:10:37 INF Alert sent event_id=1718025034.99825-2n4h7l provider=Telegram

The user cannot easily understand:

1. Which module produced the log entry.
2. Where the important part is located because the entries are only partially colored (and I'm not sure the global logger must always use ConsoleWriter, btw):
   
3. Parsing by automated tools, since the entries do not have a uniform structure.
4. What time is displayed, as no time zone and format is specified.

Describe the solution you'd like
More mature logging can be conceptualized as:

1. A single overlay function that handles logging.
2. Unified (form and text), enriched enough, log record format (see References section below).

References

1. https://datatracker.ietf.org/doc/html/rfc5424#section-6
2. https://betterstack.com/community/guides/logging/logging-best-practices/
3. https://betterstack.com/community/guides/logging/log-formatting/

[0x2142]

Thanks for the suggestions.

So there is structured logging available, but I specifically opted to use the colored format for console logging since it's a little easier to read. However, you can enable JSON logging with an environment variable if you would like. Here's a sample:

{"level":"debug","time":"2024/06/10 10:26:57","message":"Debug logging enabled"}
{"level":"info","time":"2024/06/10 10:26:57","message":"Frigate Notify - v0.3.1-dev"}
{"level":"info","time":"2024/06/10 10:26:57","message":"Starting..."}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Loading config file: ./config.yml"}
{"level":"info","time":"2024/06/10 10:26:57","message":"Config file loaded."}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Validating config file..."}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Checking connection to Frigate server..."}
{"level":"info","time":"2024/06/10 10:26:57","message":"Successfully connected to http://nvr"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Frigate server is running version 0.14.0-bccffe6"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Cameras to exclude from alerting:"}
{"level":"debug","time":"2024/06/10 10:26:57","message":" - test123"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"MQTT Enabled."}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Events without a snapshot: drop"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Events outside a zone: allow"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"All zones included in alerts"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"No zones excluded"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Labels to generate alerts for:"}
{"level":"debug","time":"2024/06/10 10:26:57","message":" - person"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Labels to exclude from alerting:"}
{"level":"debug","time":"2024/06/10 10:26:57","message":" - dog"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Discord alerting enabled."}
{"level":"info","time":"2024/06/10 10:26:57","message":"Config file validated!"}
{"level":"debug","time":"2024/06/10 10:26:57","message":"Connecting to MQTT Server..."}
{"level":"info","time":"2024/06/10 10:26:57","message":"App running. Press Ctrl-C to quit."}
{"level":"info","time":"2024/06/10 10:26:57","message":"Connected to MQTT."}
{"level":"info","time":"2024/06/10 10:26:57","message":"Subscribed to MQTT topic: fndev/events"}
{"level":"info","event_id":"1718029715.95222-743z1b","time":"2024/06/10 10:28:37","message":"New event received"}
{"level":"info","event_id":"1718029715.95222-743z1b","camera":"test_cam","label":"person","zones":"","time":"2024/06/10 10:28:37","message":"Event Detected"}
{"level":"debug","event_id":"1718029715.95222-743z1b","time":"2024/06/10 10:28:37","message":"Event start time: 2024-06-10 10:28:35 EDT"}
{"level":"info","event_id":"1718029715.95222-743z1b","time":"2024/06/10 10:28:37","message":"Event dropped - No snapshot available"}
{"level":"info","event_id":"1718029715.95222-743z1b","time":"2024/06/10 10:28:41","message":"Event update received"}
{"level":"info","event_id":"1718029715.95222-743z1b","camera":"test_cam","label":"person","zones":"test_zone","time":"2024/06/10 10:28:41","message":"Event Detected"}
{"level":"debug","event_id":"1718029715.95222-743z1b","time":"2024/06/10 10:28:41","message":"Event start time: 2024-06-10 10:28:35 EDT"}
{"level":"debug","event_id":"1718029715.95222-743z1b","camera":"test_cam","label":"person","zones":"test_zone","time":"2024/06/10 10:28:41","message":"Object entered new zone"}
{"level":"info","event_id":"1718029715.95222-743z1b","provider":"Discord","time":"2024/06/10 10:28:41","message":"Alert sent"}

I'm good with adding the time zone & calling module to the logs 👍

[freefd]

Hi @0x2142, having the colored text/plain logs in modern container orchestration systems (e.g., Kubernetes) can lead to the following side effect:

• https://discuss.kubernetes.io/t/kubectl-logs-shows-color-codes-instead-of-colors/9854
• https://community.graylog.org/t/colour-escape-characters-receive-from-a-k8s-input-are-not-decoded/29609

I'm good with adding the time zone

Maybe the Zulu time is more appropriate instead of exposing TZ.

[0x2142]

Ah, so the JSON logs have no color applied. The example above only shows colors because of the syntax highlighting for JSON. Sorry if that was confusing.

It does look like zerolog also supports disabling colors on ConsoleWriter - so I can add something to optionally disable that too.

[freefd]

Dear Matt,

The example above only shows colors because of the syntax highlighting for JSON.

Itm, I understand how the code highlighting works in modern CVS, trust me :)

But the story is not about JSON at all :)
Instead, I tried to explain, the coloring for text/plain logs could lead to unexpected results by exposing ANSI/VT100 escape sequences into raw mode.

For example, the message with following content

\033[31m This is red text!\033[0m \033[32m This is green text!\033[0m \033[33m This is yellow text!\033[0m

in the modern terminal emulator will be rendered as

But in a log collector system all those escape sequences from this message will be written as is. And previously mentioned links are exactly about this trouble.

It does look like zerolog also supports disabling colors on ConsoleWriter - so I can add something to optionally disable that too.

As per zerolog documentation, the ConsoleWriter was invented exactly for coloring logs support in the console.
I'd even say, from the business case POV (for Ops guys), the default logging behavior must be without logs coloring.
And, if the operator really wants, the coloring could be enabled (one more runtime env variable, I guess).

[freefd]

• FN_NOCOLOR env variable to disable coloring: https://github.com/0x2142/frigate-notify/pull/83/files#diff-09f3acd23c50eda2b887ad8f055de8bc957f060215522eb018bcb9084954b0cdR10
• The log line now includes the name of the module, i.e.:
  2024/08/15 19:07:56 +0000 INF ../tmp/src/notifier/nfty.go:92 > Alert sent event_id=1723738075.791779-78ooel provider=Ntfy