lib/connections: Consistent log levels & polish (fixes #4510) #4511
Conversation
lib/connections/relay_listen.go
Outdated
| continue | ||
| } | ||
|
|
||
| err = dialer.SetTCPOptions(conn) | ||
| if err != nil { | ||
| l.Infoln(err) | ||
| l.Debugln(err) |
There was a problem hiding this comment.
Actually I considered debug logging without context as ok, as the context can be established from file names and line numbers. I will add some (generic) context anyway.
lib/connections/tcp_listen.go
Outdated
| @@ -104,7 +104,7 @@ func (t *tcpListener) Serve() { | |||
|
|
|||
| err = dialer.SetTCPOptions(conn) | |||
| if err != nil { | |||
| l.Infoln(err) | |||
| l.Debugln(err) | |||
| } | |||
lib/connections/tcp_dial.go
Outdated
| @@ -39,7 +39,7 @@ func (d *tcpDialer) Dial(id protocol.DeviceID, uri *url.URL) (internalConn, erro | |||
|
|
|||
| err = dialer.SetTCPOptions(conn) | |||
| if err != nil { | |||
| l.Infoln(err) | |||
| l.Debugln(err) | |||
| } | |||
lib/upnp/upnp.go
Outdated
| @@ -159,7 +159,7 @@ USER-AGENT: syncthing/1.0 | |||
|
|
|||
| err = socket.SetDeadline(time.Now().Add(timeout)) | |||
| if err != nil { | |||
| l.Infoln(err) | |||
| l.Debugln(err) | |||
lib/upnp/upnp.go
Outdated
| @@ -168,7 +168,7 @@ USER-AGENT: syncthing/1.0 | |||
| _, err = socket.WriteTo(search, ssdp) | |||
| if err != nil { | |||
| if e, ok := err.(net.Error); !ok || !e.Timeout() { | |||
| l.Infoln(err) | |||
| l.Debugln(err) | |||
lib/upnp/upnp.go
Outdated
| @@ -168,7 +168,7 @@ USER-AGENT: syncthing/1.0 | |||
| _, err = socket.WriteTo(search, ssdp) | |||
| if err != nil { | |||
| if e, ok := err.(net.Error); !ok || !e.Timeout() { | |||
| l.Infoln(err) | |||
| l.Debugln(err) | |||
| } | |||
There was a problem hiding this comment.
You should also tweak SetTCPOptions to not fail on first failure.
There was a problem hiding this comment.
I don't really know what you want here.
lib/connections/relay_listen.go
Outdated
| @@ -71,18 +74,18 @@ func (t *relayListener) Serve() { | |||
|
|
|||
| conn, err := client.JoinSession(inv) | |||
| if err != nil { | |||
| l.Infoln("Joining relay session (BEP/relay):", err) | |||
| l.Debugln("Listen (BEP/relay): failed to join session:", err) | |||
There was a problem hiding this comment.
Should we really hide these? It's one of the only ways to debug the issues that are happening now.
There was a problem hiding this comment.
That was what I was asking originally. I was confused by what looked like randomly chosen info or debug levels with or without context (e.g. SetTCPOptions was info but without context, SetTrafficClass was debug but with context). I can't really judge their relevance, so pointers whether a log statement should be info or debug like this one are appreciated.
There was a problem hiding this comment.
Other errors that are returned by dial functions etc are logged a layer up, in the loop, so it's ok, yet this is the only place that reports relay issues, so it's not cool to hide it.
There was a problem hiding this comment.
The dial logging was only on debug, I changed that to info and removed some redundant debug log statements in the dial functions themselves.
lib/connections/relay_listen.go
Outdated
| @@ -95,7 +98,7 @@ func (t *relayListener) Serve() { | |||
| err = tlsTimedHandshake(tc) | |||
| if err != nil { | |||
| tc.Close() | |||
| l.Infoln("TLS handshake (BEP/relay):", err) | |||
| l.Debugln("Listen (BEP/relay): TLS handshake:", err) | |||
There was a problem hiding this comment.
Same here, only place that reports listen errors, so not cool to hide it.
There was a problem hiding this comment.
I will make everything log on info level that results in an early return/continue/break, does that sound sensible?
There was a problem hiding this comment.
Well I think I pointed out the relevant places in this change, but yeah, anything that doesn't return an error should probably be logged.
lib/connections/tcp_listen.go
Outdated
| } | ||
|
|
||
| tc := tls.Server(conn, t.tlsCfg) | ||
| err = tlsTimedHandshake(tc) | ||
| if err != nil { | ||
| l.Infoln("TLS handshake (BEP/tcp):", err) | ||
| l.Debugln("TLS handshake (BEP/tcp):", err) |
lib/connections/service.go
Outdated
| @@ -401,7 +401,7 @@ func (s *Service) connect() { | |||
|
|
|||
| conn, err := dialer.Dial(deviceID, uri) | |||
| if err != nil { | |||
| l.Debugln("dial failed", deviceCfg.DeviceID, uri, err) | |||
| l.Infof("%v for %v at %v: %v", dialerFactory, deviceCfg.DeviceID, uri, err) | |||
There was a problem hiding this comment.
This might flood, as we might have old addresses, so better this stays debug.
|
@st-review merge |
st-review
added
the
pr-merged
st-review
added
the
frozen-due-to-age
As Audrius mentioned in the linked issue, these functions would probably benefit from a general overhaul. Until that happens, this makes logging more consistent and less confusion to the user (info). It still logs to info level when the service fails at setup. During operation there was a mix of info and debug level logging, which now all happens on debug.