Structured logging #275

uablrek · 2022-08-31T13:21:23Z

Description

Structured logging a'la K8s, go-logr/logr

Issue link

#253

Checklist

Purpose
- Bug fix
- New functionality
- Documentation
- Refactoring
- CI
Test
- Unit test
- E2E Test
- Tested manually
Introduce a breaking change
- Yes (description required)
- No
Introduce changes in the Operator
- Yes (description required)
- No

uablrek · 2022-08-31T15:15:07Z

To test structured logs, switch to this branch and build ipam, then start KinD and do;

kubectl logs -n red ipam-trench-a-0 | jq

Snip;

{
  "severity": "info",
  "timestamp": "2022-08-31T15:11:25.294+00:00",
  "service_id": "Meridio-ipam",
  "message": "Configuration read",
  "version": "1.1.0",
  "extra_data": {
    "config": {
      "Port": 7777,
      "Datasource": "/run/ipam/data/registry.db",
      "TrenchName": "trench-a",
      "NSPService": "nsp-service-trench-a:7778",
      "PrefixIPv4": "172.16.0.0/16",
      "ConduitPrefixLengthIPv4": 20,
      "NodePrefixLengthIPv4": 24,
      "PrefixIPv6": "fd00::/48",
      "ConduitPrefixLengthIPv6": 56,
      "NodePrefixLengthIPv6": 64,
      "IPFamily": "dualstack",
      "LogLevel": "DEBUG"
    }
  }
}
{
  "severity": "debug",
  "timestamp": "2022-08-31T15:11:25.295+00:00",
  "service_id": "Meridio-ipam",
  "message": "Health server: Register subservices",
  "version": "1.1.0",
  "extra_data": {
    "probeSvc": "Readiness",
    "services": [
      "NSPCli",
      "IPAM"
    ]
  }
}

uablrek · 2022-09-03T05:17:23Z

Shall we make the ADP format the only one?

My approach was that Meridio is an open-source project first and Ericsson second. But let's be realistic, Meridio will be used only by Ericsson for a long time. As such we can make the Ericsson format the only format and add different formats later if needed. The current implementation can be seen as a PoC that different formats can be supported.

uablrek · 2022-09-03T05:39:28Z

Shall we have a global logger?

I have kind of gone all-in on the go-logr/logr concepts (except for Fatal()). E.g. the WithValues() function can be used to pass adapted loggers down the food-chain. But the individual parts of Meridio are fairly small (at least compared to K8s) so a more pragmatic approach may be acceptable. For instance;

// New() is supposed to be called once and will also set the global Logger
// (multiple calls to New() are allowed but will over-write the global Logger)
logger := log.New("Meridio-ipam", config.LogLevel)
// The global logger can be used anywhere
log.Logger.Info("Printed by the global logger")

N.B. the intended way of using go-logr/logr is still possible, but it is not enforced.

uablrek · 2022-09-03T17:06:59Z

The latest commit implements an NSM logger, used as (see load-balancer/main.go);

	// Work-around for hard-codes logrus dependency in NSM
	if config.LogLevel == "TRACE" {
		nsmlog.EnableTracing(true)
		logrus.SetLevel(logrus.TraceLevel)
	}
	logger.Info("NSM trace", "enabled", nsmlog.IsTracingEnabled())
	ctx = nsmlog.WithLog(ctx, log.NSMLogger(logger)) // allow NSM logs

but trace logs are not formatted because of a NSM log issue.

uablrek · 2022-09-05T06:46:26Z

Some thoughts about "subsystems"

These should be used with care (if used at all). It does not help any one (developers or users) to just make them up. IMO the only two real subsytems that make sense are bird and nfqlb. If we catch log printouts from those and use a "logger" to re-emit them in our choosen format (as we should IMO), then a "subsystem" entry shall be used.

Update

NSM is also a subsystem of course! When the NSM log issue is solved NSM logs may look something like this;

{
  "severity": "info",
  "timestamp": "2022-09-06T12:47:19.258+02:00",
  "service_id": "NSMLogger-info",
  "message": "Object",
  "version": "1.0.0",
  "extra_data": {
    "subsystem": "NSM",
    "44": "Key is an int"
  }
}

uablrek · 2022-09-06T16:06:14Z

An example structured log from a load-balancer-a on KinD setup for Meridio e2e; load-balancer-json.log

Formatted with jq.

uablrek · 2022-09-07T06:21:38Z

I have removed all conversion to structured logging in Meridio code and made this PR a pure add-on.

I would like a fast review/approval to allow independent and parallel conversion to structured logging of Meridio code.

uablrek · 2022-09-07T07:53:46Z

The usage of the log package is removed from this PR but an example output can be found in #275 (comment).

LionelJouin · 2022-09-07T08:27:18Z

pkg/log/logger_test.go

@@ -0,0 +1,102 @@
+/*


Add Copyright

LionelJouin · 2022-09-07T08:39:22Z

pkg/log/logger.go

+		panic(fmt.Sprintf("Can't create a zap logger (%v)?", err))
+	}
+	return zapr.NewLogger(z.With(
+		zap.String("version", "1.0.0"), zap.Namespace("extra_data")))


Is this supposed to be the Meridio Version?

No, it's the version of the ADP format. It is required according to the ADP format spec.

"required": [ "version", "timestamp", "severity", "service_id", "message" ]

LionelJouin · 2022-09-07T08:46:24Z

go.mod

@@ -5,6 +5,8 @@ go 1.19
 require (
 	github.com/antonfisher/nested-logrus-formatter v1.3.1
 	github.com/edwarnicke/grpcfd v1.1.2
+	github.com/go-logr/logr v1.2.3
+	github.com/go-logr/zapr v1.2.0


There is a new release 1.2.3 https://github.com/go-logr/zapr/releases

LionelJouin · 2022-09-07T08:46:41Z

go.mod

@@ -21,6 +23,7 @@ require (
 	github.com/stretchr/testify v1.8.0
 	github.com/vishvananda/netlink v1.2.1-beta.2.0.20220630165224-c591ada0fb2b
 	go.uber.org/goleak v1.1.12
+	go.uber.org/zap v1.19.1


There is a new release 1.23.0 https://github.com/uber-go/zap/releases

I have just done go mod tidy. How goes go select the versions?

you can use go mod edit -require go.uber.org/[email protected] (or change manually in the go.mod) then go mod tidy, but otherwise I have no idea how go selects the versions (Maybe it depends on the go version you have installed locally?).

I edited go.mod

LionelJouin · 2022-09-07T08:48:21Z

docs/logging.md

+```
+
+There is no defined "trace" level in output so both trace and debug
+messages will be have severity "debug". The level filtering is still valid


Suggested change

messages will be have severity "debug". The level filtering is still valid

messages will have severity "debug". The level filtering is still valid

LionelJouin · 2022-09-07T08:49:08Z

docs/logging.md

+
+There is no defined "trace" level in output so both trace and debug
+messages will be have severity "debug". The level filtering is still valid
+though, trace messages are suspressed unless TRACE level is set.


Suggested change

though, trace messages are suspressed unless TRACE level is set.

though, trace messages are suppressed unless TRACE level is set.

uablrek mentioned this pull request Aug 31, 2022

Log pkg with context support #259

Closed

12 tasks

uablrek requested review from zolug and LionelJouin August 31, 2022 16:39

uablrek self-assigned this Aug 31, 2022

uablrek added the kind/enhancement label Aug 31, 2022

uablrek force-pushed the loggingV2 branch from a8a5067 to 610abc5 Compare September 2, 2022 10:34

uablrek force-pushed the loggingV2 branch from 6697148 to a829993 Compare September 6, 2022 11:16

uablrek mentioned this pull request Sep 7, 2022

Added documentation with examples to check NSM main events in logs #254

Draft

12 tasks

uablrek force-pushed the loggingV2 branch from e4be91a to 485da98 Compare September 7, 2022 06:17

LionelJouin approved these changes Sep 7, 2022

View reviewed changes

Add structured logging

ccc7358

uablrek force-pushed the loggingV2 branch from 2cbbf1b to ccc7358 Compare September 7, 2022 10:24

uablrek merged commit e15c490 into master Sep 7, 2022

uablrek deleted the loggingV2 branch September 7, 2022 10:45

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Structured logging #275

Structured logging #275

uablrek commented Aug 31, 2022 •

edited

Loading

uablrek commented Aug 31, 2022

uablrek commented Sep 3, 2022

uablrek commented Sep 3, 2022

uablrek commented Sep 3, 2022 •

edited

Loading

uablrek commented Sep 5, 2022 •

edited

Loading

uablrek commented Sep 6, 2022 •

edited

Loading

uablrek commented Sep 7, 2022

uablrek commented Sep 7, 2022

LionelJouin Sep 7, 2022

LionelJouin Sep 7, 2022

uablrek Sep 7, 2022

uablrek Sep 7, 2022

LionelJouin Sep 7, 2022

LionelJouin Sep 7, 2022

uablrek Sep 7, 2022

LionelJouin Sep 7, 2022 •

edited

Loading

uablrek Sep 7, 2022

LionelJouin Sep 7, 2022

LionelJouin Sep 7, 2022

	messages will be have severity "debug". The level filtering is still valid
	messages will have severity "debug". The level filtering is still valid

	though, trace messages are suspressed unless TRACE level is set.
	though, trace messages are suppressed unless TRACE level is set.

Structured logging #275

Structured logging #275

Conversation

uablrek commented Aug 31, 2022 • edited Loading

Description

Issue link

Checklist

uablrek commented Aug 31, 2022

uablrek commented Sep 3, 2022

Shall we make the ADP format the only one?

uablrek commented Sep 3, 2022

Shall we have a global logger?

uablrek commented Sep 3, 2022 • edited Loading

uablrek commented Sep 5, 2022 • edited Loading

Some thoughts about "subsystems"

Update

uablrek commented Sep 6, 2022 • edited Loading

uablrek commented Sep 7, 2022

uablrek commented Sep 7, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

LionelJouin Sep 7, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

uablrek commented Aug 31, 2022 •

edited

Loading

uablrek commented Sep 3, 2022 •

edited

Loading

uablrek commented Sep 5, 2022 •

edited

Loading

uablrek commented Sep 6, 2022 •

edited

Loading

LionelJouin Sep 7, 2022 •

edited

Loading