New API: avoid message formatting when possible to be able to take advantage of zero alloc libraries

[hugoArregui]

Description

The idea is to deprecate the usage of string formatting and always use typed fields instead, so:

	a.log.Debugf("Started agent: isControlling? %t, remoteUfrag: %q, remotePwd: %q", isControlling, remoteUfrag, remotePwd)

becomes:

	a.log.DebugLvl().
		Bool("isControlling", isControlling).
		Str("remoteUfrag", remoteUfrag).
		Str("remotePwd", remotePwd).
		Msg("Started agent")

This change is totally backwards compatible.

I also added a thirdparty directory with a zerolog implementation so people don't have to roll out their own implementation

This is how the integration will look like from a pion user perspective: https://github.com/decentraland/webrtc-broker/blob/5df08906d7547b5edbae3add274286a17f663f37/internal/logging/logging.go#L37

Reference issue

Related #10

[codecov-io]

Codecov Report

Merging #11 into master will decrease coverage by 36.28%.
The diff coverage is 18.61%.

@@             Coverage Diff             @@
##           master      #11       +/-   ##
===========================================
- Coverage   55.46%   19.17%   -36.29%     
===========================================
  Files           2        2               
  Lines         119      219      +100     
===========================================
- Hits           66       42       -24     
- Misses         51      169      +118     
- Partials        2        8        +6

Impacted Files	Coverage Δ
logger.go	17.82% <16.32%> (-44.8%)	⬇️
formatters.go	21.11% <21.11%> (ø)

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 0387f8a...7661bb5. Read the comment docs.

[Sean-Der]

@hugoArregui

I might be doing things wrong but pion/webrtc@master isn't able to compile.

What do you think of including info from runtime? Getting the calling function could be really helpful for debugging. Right now people just grep for the error message.

seaduboi@38f9d359441f:~/go/src/github.com/pion/webrtc$ golangci-lint run --build-tags quic ./...
peerconnection_test.go:117:9: cannot use testCatchAllLeveledLogger(t) (value of type testCatchAllLeveledLogger) as *logging.Logger value in return statement (typecheck)
	return testCatchAllLeveledLogger(t)
	       ^
seaduboi@38f9d359441f:~/go/src/github.com/pion/webrtc$ cd examples
seaduboi@38f9d359441f:~/go/src/github.com/pion/webrtc/examples$ golangci-lint run --build-tags quic ./...
custom-logger/main.go:47:9: cannot use (customLogger literal) (value of type customLogger) as *logging.Logger value in return statement (typecheck)
	return customLogger{}

[hugoArregui]

@Sean-Der sorry for the delay! I've been very busy with other things.

I might be doing things wrong but pion/webrtc@master isn't able to compile.

Sorry about that, yes, that's true, I should have clarified that, this change is backwards compatible with the usage of the logger, but not with a given logger implementation, so in this case the webrtc test is defining a custom a logger in a way this PR doesn't support anymore. Before this PR, you provide your own logger, but with this PR you provide a formatter. Let me know if you think this is a problem.

What do you think of including info from runtime? Getting the calling function could be really helpful for debugging. Right now people just grep for the error message.

This is certainly doable, let me try something. I don't want to provide an API to do that because some log libraries support this functionality in their own way (zerolog and logrus for example), but I can add it to our default formatters.

[hugoArregui]

@Sean-Der there you go:

$ PION_LOG_TRACE=ice  go run pion-to-pion-trickle/offer/main.go
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:477] Started agent: isControlling? true, remoteUfrag: "EWrKFRseuWyothki", remotePwd: "AhgwpKAinQUfayfGoPgvLtlGThydrrjU"
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:506] Setting new connection state: Checking
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:91] pinging all candidates
ICE Connection State has changed: checking
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:91] pinging all candidates
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 192.168.1.70:50353 to host 192.168.1.70:50714

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 172.27.249.157:63881 to host 192.168.1.70:50714

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/candidatepair.go:92] failed to send STUN message: failed to send packet: write udp 172.27.249.157:63881->192.168.1.70:50714: sendto: no route to host
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:91] pinging all candidates
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 192.168.1.70:50353 to host 192.168.1.70:50714

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 172.27.249.157:63881 to host 192.168.1.70:50714

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/candidatepair.go:92] failed to send STUN message: failed to send packet: write udp 172.27.249.157:63881->192.168.1.70:50714: sendto: no route to host
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 192.168.1.70:50353 to host 172.27.249.157:51059

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 172.27.249.157:63881 to host 172.27.249.157:51059

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:159] inbound STUN (SuccessResponse) from host 192.168.1.70:50714 to host 192.168.1.70:50353
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:169] Found valid candidate pair: prio 9151314440652587007 (local, prio 2130706431) host 192.168.1.70:50353 <-> host 192.168.1.70:50714 (remote, prio 2130706431)
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:1006] inbound STUN (Request) from 192.168.1.70:50714 to host 192.168.1.70:50353
[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:135] The candidate (host 192.168.1.70:50353, host 192.168.1.70:50714) is the best candidate available, marking it as nominated

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/selection.go:115] ping STUN (nominate candidate pair) from host 192.168.1.70:50353 to host 192.168.1.70:50714

[/Users/hugoarregui/go/pkg/mod/github.com/pion/ice@v0.5.14/agent.go:880] ping STUN from host 192.168.1.70:50353 to host 192.168.1.70:50714

[Sean-Der]

Oh I love that, nice work @hugoArregui

This is a merge from me! We will need to communicate/update things a little more on this. Let me handle a few outstanding issues (that are actively biting people) and lets get this in right after!

[hugoArregui]

awesome! no hurry, this is a breaking change for people defining their own logger, so we can wait until the next major if that makes more sense

[bshi]

I found this by way of #10 which I found when I encountered some evidence of logging introducing unnecessary mutex contention. It seems there are two orthogonal issues here and it's probably worth addressing them separately.

(1) Suboptimal usage/invocation of logging libraries (log(foo.String())).
(2) The underlying logging mechanism.

Issue (1) already has a solution in the stdlib and can be fixed fairly easily by auditing the codebase and using %q interpolation everywhere we log a https://golang.org/pkg/fmt/#Stringer types: logf("blah %s", x.String()) -> logf("blah %q", x). In fact, I'd go even further and say that %s in logs should be banned in favor of %q unless explicitly rationalized because it's more readable and less prone to misinterpretation: i can't find in file (double space) vs i can't find "" in file

https://play.golang.org/p/Ius_-3qHErF

type N struct{ n int }

func (n *N) String() string { return "my thing " + strconv.Itoa(n.n) }

func main() {
	fmt.Printf("foo: %q\n", &N{12})
	fmt.Printf("NOTE! this only works as intended if the interface is satisfied: %q", N{12})
}

Yields

foo: "my thing 12"
NOTE! this only works as intended if the interface is satisfied: {'\f'}

Issue (2) is a broader problem. Given that pion's goals are oriented around being embeddable, IMO this logging library should simply be a set of interfaces (https://dave.cheney.net/2017/01/23/the-package-level-logger-anti-pattern is a concise writeup on why) and a no-op default implementation leaving the concrete implementation up to users to inject.

In addition, and tangentially related, I agree pion/webrtc and its transitive dependencies would benefit from structured logging and in particular something capable of supporting contextual fields so defining the interfaces as a subset of the zerolog API has my vote. That way injecting a logging implementation would only involve instantiating a zerolog Logger instead of the wrapper approach in this PR.

[Sean-Der]

@bshi I am 100% in support of this!

It is also much easier to break these things now then in August 2019 (pre-Modules) back then I had some apprehension because breaking APIs caused so much frustration.

[hugoArregui]

Hey guys, it has been a while since I worked on this (and in go), so maybe I'm missing something, but the proposed logging package is a set of interfaces, there is also a zerolog package in the thirdparty directory, but is not all together.

[bshi]

@hugoArregui sorry if I missed something but I don't see any interface types in this change? I was also mostly chiming in on what the interface should be. And I realized after the fact that the zerolog API surface is not amenable to hiding behind an interface without any changes. Should we consider a community standard interface? https://github.com/go-logr/logr supports contextual logging.

[hugoArregui]

Formatter is the interface:

logging/logger.go

Line 67 in 7661bb5

type Formatter interface {

and it's implemented in the zerolog package:

logging/thirdparty/zerolog/logger.go

Line 10 in 7661bb5

type ZerologFormatter struct {

[bshi]

The interface as defined is still opinionated about the underlying logging mechanism (stdlib log). My initial point (as rationalized by https://dave.cheney.net/2017/01/23/the-package-level-logger-anti-pattern) was that pions should be entirely decoupled from any concrete logging implementation (aside from a nop-logger) and that logging should be injected by client code.