[tor-bugs] #12882 [Onionoo]: Logging Framework

Tue Aug 19 19:02:34 UTC 2014

#12882: Logging Framework
-----------------------------+----------------------
     Reporter:  iwakeh       |      Owner:  iwakeh
         Type:  enhancement  |     Status:  assigned
     Priority:  normal       |  Milestone:
    Component:  Onionoo      |    Version:
   Resolution:               |   Keywords:
Actual Points:               |  Parent ID:
       Points:               |
-----------------------------+----------------------

Comment (by karsten):

 Here's some recent output from the "System.out" logging that the hourly
 cronjob does:

 {{{
 Tue Aug 19 18:15:05 UTC 2014: Initializing.
   Acquired lock (00:00.001 minutes).
   Initialized descriptor source (00:00.013 minutes).
   Initialized document store (00:00.043 minutes).
   Initialized status update runner (00:00.022 minutes).
   Initialized document writer runner (00:00.015 minutes).
 Tue Aug 19 18:15:05 UTC 2014: Downloading descriptors.
 Tue Aug 19 18:15:25 UTC 2014: Reading descriptors.
   Read relay server descriptors (00:46.781 minutes).
   Read relay extra-info descriptors (00:37.159 minutes).
   Read exit lists (00:00.198 minutes).
   Read relay network consensuses (03:54.649 minutes).
   Read bridge server descriptors (00:04.426 minutes).
   Read bridge extra-info descriptors (03:07.221 minutes).
   Read bridge-pool assignments (00:01.605 minutes).
   Read bridge network statuses (00:00.943 minutes).
 Tue Aug 19 18:23:58 UTC 2014: Updating internal status files.
   Read status summary (00:17.928 minutes).
   Set current node fingerprints (00:00.094 minutes).
   Started reverse domain name lookups (00:00.069 minutes).
   Looked up cities and ASes (00:35.442 minutes).
   Set descriptor parts of node statuses. (01:05.976 minutes).
   Calculated path selection probabilities (00:01.258 minutes).
   Finished reverse domain name lookups (03:17.728 minutes).
   Wrote status summary (00:00.420 minutes).
   Updated exit addresses in details statuses (00:01.116 minutes).
   NodeDetailsStatusUpdater updated status files (00:00.000 minutes).
   BandwidthStatusUpdater updated status files (00:00.001 minutes).
   WeightsStatusUpdater updated status files (00:00.000 minutes).
   ClientsStatusUpdater updated status files (00:05.763 minutes).
   UptimeStatusUpdater updated status files (00:12.398 minutes).
 Tue Aug 19 18:29:37 UTC 2014: Updating document files.
   Wrote summary document files (00:01.611 minutes).
   Wrote details document files (00:23.959 minutes).
   Wrote bandwidth document files (01:47.902 minutes).
   Wrote weights document files (01:40.339 minutes).
   Wrote weights document files (00:00.000 minutes).
   Wrote clients document files (00:12.951 minutes).
   Wrote uptime document files (00:19.518 minutes).
 Tue Aug 19 18:34:03 UTC 2014: Shutting down.
   Wrote parse histories (00:00.058 minutes).
   Flushed document cache (00:18.492 minutes).
 Tue Aug 19 18:34:21 UTC 2014: Gathering statistics.
   NodeDetailsStatusUpdater statistics:
     1 relay consensuses processed
     2 bridge statuses processed
   ClientsStatusUpdater statistics:
     1,711 client statistics processed from extra-info descriptors
     1,665 client status files updated
   UptimeStatusUpdater statistics:
     1 hours of relay uptimes processed
     1 hours of bridge uptimes processed
     9,840 uptime status files updated
   GeoIP lookup service statistics:
     319,693 addresses looked up
     319,478 addresses resolved
   Reverse domain name resolver statistics:
     1,867 lookups performed
     00:00.000 minutes minimum lookup time
     00:00.410 minutes median lookup time
     00:03.917 minutes maximum lookup time
   SummaryDocumentWriter statistics:
     17,703 summary document files written
     23 summary document files deleted
   ClientsDocumentWriter statistics:
     2,554 clients document files updated
   UptimeDocumentWriter statistics:
     11,419 uptime document files written
   Descriptor source statistics:
     700 descriptor files found locally
     703 descriptor files found remotely
     10 descriptor files downloaded from remote
     7 descriptor files deleted locally
     8 descriptor queues created
     700 descriptors excluded from this execution
     18,015 descriptors provided
     24.5 MiB provided
     703 descriptors excluded from next execution
   Document store statistics:
     2 list operations performed
     586,821 files listed
     68,646 files stored
     1.3 GiB stored
     182,011 files retrieved
     2.3 GiB retrieved
     0 files removed
 Tue Aug 19 18:34:21 UTC 2014: Releasing lock.
   Released lock (00:00.000 minutes).
 Tue Aug 19 18:34:21 UTC 2014: Terminating.
 }}}

 Yes, that's all.  So, this isn't really "logging" in the sense that we
 could debug any problems using these logs.  Well, maybe.  But it's mostly
 keeping "metrics" like how long certain substeps of the processing take,
 or how many files have been processed.  This information is very
 interesting to me, because I can locate bottlenecks more easily.  And with
 a runtime of almost 20 minutes for an hourly cronjob you see how important
 that is.

 So, if we use a logging framework, we'll also have to decide what stuff
 will be logged.

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