[tor-bugs] #13362 [Onionoo]: Make Onionoo's logs more useful

[Tor Bug Tracker & Wiki]

#13362: Make Onionoo's logs more useful
-------------------------+---------------------
 Reporter:  karsten      |          Owner:
     Type:  enhancement  |         Status:  new
 Priority:  normal       |      Milestone:
Component:  Onionoo      |        Version:
 Keywords:               |  Actual Points:
Parent ID:               |         Points:
-------------------------+---------------------
 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
 "[http://logback.qos.ch/manual/layouts.html#Parentheses 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.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/13362>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online