nats-server
nats-server copied to clipboard
nats-io
Support structured logging
Feature Requests
Hi, we would like to switch the logging format to structured (json). For easier analysis of logs.
If you would welcome this feature, we could do it and create a pull request.
Use Case:
Projects with automated log analysis.
Proposed Change:
Add a new configuration to create a structured logger.
Which log statements in particular? Of course there is a large ecosystem around NATS and tooling that is built around the old format.
However, as we move more towards black box operations (debugging things without access to the server or logs themselves) we are adding new things that can take advantage of JSON structuring and delivery.
It Will be great if can be added a flag to turn the logging into JSON, otherwise, platforms like Google Logging, can't set the severity of the messages properly.
I am working on this problem right now, in GKE if you don't use the custom format of Stackdrive/Google Logging you need to deploy a custom configuration, ending in another component to maintain beside that you need to do a regexp to parse logs.
Obviously NATS is not going to implement the custom format of every single provider, but a --json-log with a structured log will help a lot.
I will be happy to contribute with this if this functionality is considered desirable.
I'm a big fan of structured logging, the problem is this is a deep pit as every platform wants their own crazy formats
But at least if it is structured, you don't need to create a regexp. Also, you can use logrus, where almost every single format it's already implemented, and you can implement the format for the bigger clouds, with a small effort.
Doing something like:
switch f.Format {
case TextFormat:
f := new(prefixed.TextFormatter)
f.ForceColors = runtime.GOOS != "windows"
f.FullTimestamp = true
f.TimestampFormat = time.RFC3339Nano
l.Formatter = f
case JSONFormat:
f := new(logrus.JSONFormatter)
f.TimestampFormat = time.RFC3339Nano
l.Formatter = f
case FluentdFormat:
f := new(logrus.JSONFormatter)
f.FieldMap = logrus.FieldMap{
logrus.FieldKeyTime: "timestamp",
logrus.FieldKeyLevel: "severity",
logrus.FieldKeyMsg: "message",
}
l.Formatter = f
case StackdriverFormat:
var opts []stackdriver.Option
if service := os.Getenv("LOG_SERVICE_NAME"); service != "" {
opts = append(opts, stackdriver.WithService(service))
}
if service := os.Getenv("LOG_SERVICE_VERSION"); service != "" {
opts = append(opts, stackdriver.WithVersion(service))
}
opts = append(opts, stackdriver.WithStackSkip("github.com/gitsight/go-log"))
l.Formatter = stackdriver.NewFormatter(opts...)
}
Yeah, in my own projects I use logrus and it's been a life saver for this reason. Pretty weary of new dependencies here though is the problem :)
Hay @ripienaar any news on this? Perhaps a better alternative would be zap to make the logs more performant.
Several people have offered to implement it. Perhaps one of them can? (I can speak highly of zap as a solution.)
My use case is that NATS is included as a helm dependency in something else I'm using, and now it's polluting my otherwise nicely structured logs in datadog. And while yes, I can write a custom parse rule, it's significantly easier to just ingest a structured object so that everything isn't ingested as an error.
I would like to be able to use logfmt instead of JSON, but regardless this is really the job of the logger implementation (with formatting and transport configured by the user).
example logfmt
[1] 2022/11/23 13:00:56.048398 [INF] Version: 2.9.6
[1] 2022/11/23 13:00:56.048473 [INF] Git: [289a9e1]
[1] 2022/11/23 13:00:56.048638 [INF] Cluster: my_cluster
[1] 2022/11/23 13:00:56.048677 [INF] Name: NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
[1] 2022/11/23 13:00:56.048725 [INF] ID: NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
[1] 2022/11/23 13:00:56.048799 [INF] Using configuration file: nats-server.conf
[1] 2022/11/23 13:00:56.049314 [INF] Starting http monitor on 0.0.0.0:8222
[1] 2022/11/23 13:00:56.049401 [INF] Listening for client connections on 0.0.0.0:4222
[1] 2022/11/23 13:00:56.055752 [INF] Server is ready
[1] 2022/11/23 13:00:56.058258 [INF] Cluster name is my_cluster
[1] 2022/11/23 13:00:56.060059 [INF] Listening for route connections on 0.0.0.0:6222
..
[1] 2022/11/23 13:31:50.917381 [DBG] 10.220.47.190:56194 - rid:134 - Router Ping Timer
[1] 2022/11/23 13:31:50.917410 [DBG] 10.220.47.190:56194 - rid:134 - Delaying PING due to client activity 1s ago
Logfmt is nice to read, while easy simple to parse Notice logs are on a single line
time="2022/11/23T13:00:56.048398Z" level=info msg="Starting nats-server" cluster=my_cluster version=2.9.6 git=289a9e1 id=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS name=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
time="2022/11/23T13:00:56.048799Z" level=info msg="Using configuration file" file=nats-server.conf cluster=my_cluster version=2.9.6 git=289a9e1 id=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS name=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
time="2022/11/23T13:00:56.049314Z" level=info msg="Starting http monitor" host=0.0.0.0 port=8222 cluster=my_cluster version=2.9.6 git=289a9e1 id=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS name=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
time="2022/11/23T13:00:56.049401Z" level=info msg="Listening for client connections" host=0.0.0.0 port=4222 cluster=my_cluster version=2.9.6 git=289a9e1 id=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS name=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
time="2022/11/23T13:00:56.055752Z" level=info msg="Server is ready" host=0.0.0.0 port=8222 cluster=my_cluster version=2.9.6 git=289a9e1 id=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS name=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
time="2022/11/23T13:00:56.060059Z" level=info msg="Listening for route connections" host=0.0.0.0 port=6222 cluster=my_cluster version=2.9.6 git=289a9e1 id=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS name=NA75ER54M7QDNVTRDB4UTHGUKPO3YVJ4K5T66WBDHRAMZHHKSOYMHGWS
...
time="2022/11/23T13:31:50.917381Z" level=debug msg="Delaying PING due to client activity" router_id=134 router_ip=10.220.47.190 router_port=56194 activity_age_seconds=0 # showing without the global attributes in case it is too much noise
time="2022/11/23T13:31:50.917410Z" level=debug msg="Router Ping Timer" router_id=134 router_ip=10.220.47.190 router_port=56194 # showing without the global attributes in case it is too much noise
And similar for JSON (just a little harder to read IMO, but the formatting should be up to the user, the message and attributes should be up to the lib/app developers, and as @smartinov pointed out, Zap is quite nice uncomplicated model).
I'm a big fan of structured logging, the problem is this is a deep pit as every platform wants their own crazy formats
@ripienaar, I agree, no longer try to satisfy any particular convention and instead focussed on a message field along with whatever attributes should go with it. Then leave it up to log viewer app to parse it.
It might be worth considering OpenTelemetry (not only for logging, but also traces and metrics).
It looks like logs aren't supported yet for Go, but that's the same case for Rust (I've found it helpful using the tracing crate for logging with attributes in libs, while then using a tracing subscriber to deal with how logs are exposed along with attributes in the resulting app - I imagine it to be relatively similar for the Go SDK).
+1 OpenTelemetry https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/semantic_conventions/messaging.md
About the topic, and keeping OTEL in mind,
Could most things be traces rather than logs? You can compose a log out of a trace, but it is tricky to do the other way around!
So maybe what most people want is tracing.
