GitLab

I noticed a few problems with Onionoo's logs since we switched to logback.

First, error logs are strangely truncated, as in this older example:

2014-09-24 22:23:43 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:43 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:43 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:43 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:43 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:43 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:44 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:23:44 ERROR o.t.o.u.DescriptorDownloader(1132014-09-24 22:25:08 ERROR o.t.o.u.NodeDetailsStatusUpdater(464

My guess is that this can be explained by "parentheses being special". We could use [] instead, or simply use the same pattern as for the main log.

Second, the statistics logs are missing the most relevant parts. Here's an example:

2014-09-04 10:15:06 [runtime: 843] Initializing.
2014-09-04 10:15:06 [runtime: 845] Acquired lock
2014-09-04 10:15:06 [runtime: 847] Initialized descriptor source
2014-09-04 10:15:06 [runtime: 852] Initialized document store
2014-09-04 10:15:06 [runtime: 877] Initialized status update runner
2014-09-04 10:15:06 [runtime: 890] Initialized document writer runner
2014-09-04 10:15:06 [runtime: 891] Downloading descriptors.
2014-09-04 10:15:44 [runtime: 38516] Reading descriptors.
2014-09-04 10:24:51 [runtime: 585920] Updating internal status files.
2014-09-04 10:30:58 [runtime: 952445] Updating document files.
2014-09-04 10:35:14 [runtime: 1208036] Shutting down.
2014-09-04 10:35:14 [runtime: 1208039] Wrote parse histories
2014-09-04 10:35:44 [runtime: 1238709] Flushed document cache
2014-09-04 10:35:44 [runtime: 1238709] Gathering statistics.
2014-09-04 10:35:44 [runtime: 1238711] NodeDetailsStatusUpdater
2014-09-04 10:35:44 [runtime: 1238713] ClientsStatusUpdater
2014-09-04 10:35:44 [runtime: 1238715] UptimeStatusUpdater
2014-09-04 10:35:44 [runtime: 1238715] GeoIP lookup service
2014-09-04 10:35:44 [runtime: 1238719] Reverse domain name resolver
2014-09-04 10:35:44 [runtime: 1238720] Descriptor source
2014-09-04 10:35:44 [runtime: 1238721] Document store
2014-09-04 10:35:44 [runtime: 1238721] Releasing lock.
2014-09-04 10:35:44 [runtime: 1238721] Released lock
2014-09-04 10:35:44 [runtime: 1238721] Terminating.

I think the problem is that we're not including {} placeholders in log calls with additional arguments, so logback is simply dropping those arguments on the floor. But maybe we shouldn't mix log calls with placeholders and log calls that concatenate strings themselves. Taking out calls with multiple arguments (except for logging exceptions) seems like the simplest fix for now, though I could see us switching to placeholders in the future.

Third, and this is not really an issue but a minor inconvenience, the [runtime: 123456] part of both main and error logs is not as easy to read as it would seem. I wonder if we should simply switch timestamps to %date{ISO8601, UTC} for millisecond precision. That would make logs somewhat easier to read.