Opened 5 years ago

Closed 5 years ago

#12882 closed enhancement (implemented)

Logging Framework

Reported by: iwakeh Owned by: iwakeh
Priority: Medium Milestone:
Component: Metrics/Onionoo Version:
Severity: Keywords:
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Logging should be provided by a standard logging framework that can handle both tomcat mode and standalone app.

(originated in #12869)

Child Tickets

Attachments (14)

onionoo-logging.2.patch (9 bytes) - added by iwakeh 5 years ago.
obsolete
logback.2.xml (2.0 KB) - added by iwakeh 5 years ago.
web-app logbaxk config, to be placed in etc/
logback.xml (2.2 KB) - added by iwakeh 5 years ago.
logback.xml in the base directory
onionoo-logging.patch (170.7 KB) - added by iwakeh 5 years ago.
java sources diff
0001-Logging-vagrant-etc.-suggestions-combined.patch (189.1 KB) - added by iwakeh 5 years ago.
Here is a more convenient all in one patch. It also supplies util.FormattingUtils
0001-whitespace-changes.patch (479.1 KB) - added by iwakeh 5 years ago.
0002-logging-added-to-java-sources.patch (76.2 KB) - added by iwakeh 5 years ago.
0003-logging-configuration-and-vagrant.patch (15.2 KB) - added by iwakeh 5 years ago.
0004-removed-print-stack-trace.patch (6.3 KB) - added by iwakeh 5 years ago.
final addition, removes some obsolete stack trace prints
0001-logging-changes-for-build.xml-added-logback-config.patch (12.6 KB) - added by iwakeh 5 years ago.
configuration changes
0002-logging-java-source-changes.patch (77.0 KB) - added by iwakeh 5 years ago.
logging: java sources
onionoo-logging.build-and-config-files.patch (2 bytes) - added by iwakeh 5 years ago.
obsolete
onionoo-logging.patch​ (2 bytes) - added by iwakeh 5 years ago.
obsolete
FormattingUtils.java (864 bytes) - added by iwakeh 5 years ago.
Now it should be complete.

Download all attachments as: .zip

Change History (30)

comment:1 Changed 5 years ago by iwakeh

Owner: set to iwakeh
Status: newassigned

I could look into it.

comment:2 Changed 5 years ago by iwakeh

Choices on wheezy main stable are

  • log4j1.2
  • logback
  • commons-logging and more.

And, java.logging should be looked at, too.


comment:3 Changed 5 years ago 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.

comment:4 Changed 5 years ago by iwakeh

Thanks, for this info!

I suggest the following:

  • two different "sinks" (i.e. log files or 'appenders') for logging:
    • the metrics part and
    • the "real" logging info (i.e. errors, warnings and the like)

This is feasible with all three solutions above (even the older versions in debian, afaik).
The actual log location and level should be configurable at runtime (in tomcat) or
start time (for standalone). Of course, piping the log entries into just one file should
also be a configuration matter.

I assume, you don't process the current logs automatically?
Thus, the formatting is important only insofar that the metric performance log entries
should be as 'human readable' as they are know, but minor format changes do not matter?

For the application logging part I suggest to start with identifying errors and warnings
and very few if at all informational log entries. This keeps the initial work for adding
log entries small.

Last edited 5 years ago by iwakeh (previous) (diff)

comment:5 Changed 5 years ago by karsten

Agreed about the suggested two sinks for metrics and logging. That reminds me of another important requirement: the logging part should be split up into informational messages and warnings or errors. The former can be written to files in a "logrotate" style, the latter must be included in emails sent out by cron.

Let me explain how this works right now: the cron part of Onionoo uses System.out for informational messages and System.err for errors and warnings. The Ant target "run" has error="errors" set, so that errors and warnings are written (not appended) to the local errors file. Cron calls Ant with the following command: ant run >> log && cat errors. That means that informational messages are appended to log and everything in the errors file gets mailed to me once the cronjob finishes.

For completeness, here's how logging in Tomcat is currently used: there are a few calls to System.err (which could also be System.out calls) in the server package. Those lines are appended to Tomcat's catalina.out file. Any other file would be fine, too, this is just where it happens to log right now.

As for identifying errors, warnings, and informational log entries, I think the current System.out and System.err statements might be a fine start. All these can be turned into calls to the logging framework.

And to answer your question: no, I don't process logs automatically.

Want to apply one of the mentioned logging frameworks and try it in the Vagrant environment?

comment:6 Changed 5 years ago by iwakeh

Status: assignedneeds_review

I used slf4j and logback. The latter is a really clean and well documented re-implementation
of log4j1.2, but logback 'speaks' slf4j natively.
With slf4j the framework can be switched easier.
And, there are sufficient versions available in wheezy stable.
Tomcat does not need to be tweeked, i.e. the onionoo.war contains everything necessary for logging this way.

build.xml

I switched to java 7, but I also introduced a property for the java version. So it'll be easy to change.
I also included a clean task.

Vagranfile, INSTALL …

I added changes necessary to the Vagrantfile.
And, I kept all the changes from #12934 .

logging configuration

  • standalone: logback.xml needs to reside in the classpath (there is a copy statement in the run task now.)
  • war: The onionoo.war contains its own logback.xml

The to logback.xml configurations differ mostly in their logging paths.

Well, I surely forgot something ;-)

Patch attached, please review.

PS:
I added the public final static long NO_TIME_AVAILABLE = -1L; constant
in DateTimeHelper (cf. #12935).

And some more immediate logging in PerformanceMetrics.

Important:

  • a line ln -s /vagrant/logback.xml has to be added to vagrant/botstrap.sh
  • tomcat needs to be told about the jdk1.7 java home. this is not reflected in the current bootstrap.sh either, i.e. apt-get purge -y openjdk-6-jdk openjdk-6-jre has to be added after the apt-get install lines.
  • paths and file names for logging can be changed in the two logback.xmls; Currently there are three log files onionoo-{err,all,statistics}.log
  • I would advice to add the error message to all the logging messages from catch-statements.
Last edited 5 years ago by iwakeh (previous) (diff)

Changed 5 years ago by iwakeh

Attachment: onionoo-logging.2.patch added

obsolete

Changed 5 years ago by iwakeh

Attachment: logback.2.xml added

web-app logbaxk config, to be placed in etc/

Changed 5 years ago by iwakeh

Attachment: logback.xml added

logback.xml in the base directory

Changed 5 years ago by iwakeh

Attachment: onionoo-logging.patch added

java sources diff

Changed 5 years ago by iwakeh

Here is a more convenient all in one patch. It also supplies util.FormattingUtils

comment:7 Changed 5 years ago by karsten

Oh wow, that's quite a patch. Lots of good stuff in it, but we'll need to tweak it before we can apply it. Let me take this opportunity to start a "Contributor Guide" (this is written in Markdown, because I want to commit this text to a Markdown file later). Want to tweak this patch and push changes to a public Git repository somewhere? Also feel free to comment on the Contributor Guide.

# Contributor Guide

This guide is meant for people who want to contribute patches to Onionoo.

## Patch format

Format your patches using git format-patch if you want to submit just a single, small commit.
If you want to submit more than one commit, push your changes to a public Git repository somewhere that can be pulled from.

## Whitespace conventions

Whitespace conventions are important, because whitespace changes bloat patches and make them harder to review.
If we all agree on the same whitespace conventions, the only changes to review are actually meaningful changes.
If you need to make whitespace changes, because files did not conform to whitespace conventions before, do these changes in one or more separate commits that contain nothing else than whitespace changes.

The following whitespace conventions apply:

  • Maximum line width is 74 characters. Why 74? Because it looks pretty in vim in a 80-character terminal with line numbers turned on.
  • Full sentences are followed by a period and two spaces. An exception to this rule are sentences in markup files like Markdown; in this case, each sentence should start with a newline, so that a change in one sentence doesn't cause changes to all subsequent sentences. An exception to this exception are multiple sentences in a single bullet point.
  • Indentations use two spaces, no tabs. Continuations use four spaces.
  • Attributes and methods are typically separated by two newlines. An exception are attributes with getters and setters which can be written without separating newlines.
  • All source files end with two newlines.

comment:8 Changed 5 years ago by iwakeh

I agree, that patch patchwork is a bit chaotic.

For the next big patch I'll set-up a repo somewhere, that'll include the logging.

For the moment:
the attached, three patches take up the suggestions from your comment.
0001 for whitespace and formatting
0002 for java sources
0003 for config files

Hope this makes the changes more readable.

Changed 5 years ago by iwakeh

Changed 5 years ago by iwakeh

Changed 5 years ago by iwakeh

Changed 5 years ago by iwakeh

final addition, removes some obsolete stack trace prints

comment:9 Changed 5 years ago by karsten

Hmm, I looked through the first few hundred lines of 0001-whitespace-changes.patch​, and those changes don't confirm to what I intended to write above. Here are some examples:

diff --git a/src/main/java/org/torproject/onionoo/cron/Main.java b/src/main/java/org/torproject/onionoo/cron/Main.java
index bd4b95a..3fb355f 100644
--- a/src/main/java/org/torproject/onionoo/cron/Main.java
+++ b/src/main/java/org/torproject/onionoo/cron/Main.java
@@ -26,7 +26,7 @@ public class Main {
       Logger.printStatusTime("Acquired lock");
     } else {
       Logger.printErrorTime("Could not acquire lock.  Is Onionoo "
-          + "already running?  Terminating");
+        + "already running?  Terminating");
       return;
     }

@@ -68,10 +68,9 @@ public class Main {
       Logger.printStatusTime("Released lock");
     } else {
       Logger.printErrorTime("Could not release lock.  The next "
-          + "execution may not start as expected");
+        + "execution may not start as expected");
     }

     Logger.printStatus("Terminating.");
   }
 }
-

The first two changes should go away, because those lines are continuations of the previous line, and therefore should use 4 spaces, not 2. The last change should go away, because files should end with two newlines.

diff --git a/src/main/java/org/torproject/onionoo/docs/BandwidthDocument.java b/src/main/java/org/torproject/onionoo/docs/BandwidthDocument.java
index ea20a5e..021c2f7 100644
--- a/src/main/java/org/torproject/onionoo/docs/BandwidthDocument.java
+++ b/src/main/java/org/torproject/onionoo/docs/BandwidthDocument.java
@@ -8,20 +8,22 @@ public class BandwidthDocument extends Document {

   @SuppressWarnings("unused")
   private String fingerprint;
+
   public void setFingerprint(String fingerprint) {
     this.fingerprint = fingerprint;
   }

This additional newline shouldn't be there, because the setter is "grouped" together with its attribute by omitting the newline. Does that make sense, or do you prefer if we change that?

   public void clearDirty() {
     this.isDirty = false;
   }

-  private SortedMap<Long, long[]> writeHistory =
-      new TreeMap<Long, long[]>();
+  private SortedMap<Long, long[]> writeHistory
+    = new TreeMap<Long, long[]>();
+
   public void setWriteHistory(SortedMap<Long, long[]> writeHistory) {
     this.writeHistory = writeHistory;
   }

Apart from the 2 spaces which should be 4, I don't have a clear preference whether the = should be on the first or second line. We can change that if you want.

-          ? endMillis : history.tailMap(startMillis).firstKey();
-      if (previousEndMillis <= startMillis &&
-          nextStartMillis >= endMillis) {
-        history.put(startMillis, new long[] { startMillis, endMillis,
-            bandwidth });
+        ? endMillis : history.tailMap(startMillis).firstKey();
+      if (previousEndMillis <= startMillis
+        && nextStartMillis >= endMillis) {
+        history.put(startMillis, new long[]{startMillis, endMillis,
+          bandwidth});

Similarly, I don't feel strongly about the && being at the line end or beginning. Happy to change that if you prefer.

What I don't like as much is the long[]{startMillis, part which I find kinda hard to read.

Anyway, how about we separate the whitespace discussion from the logging part? I can't apply your patches 0002 to 0004 without 0001. Would you be able to rebase those patches to current master without your 0001 patch, and then we move the reformatting discussion to a separate ticket?

Sorry this is so difficult. Thanks for your contribution!

comment:10 Changed 5 years ago by karsten

Oh, and please configure your Git correctly before sending the next patches:

From 00e9ff415a4f53d95b6a88b489f279c9a1254af4 Mon Sep 17 00:00:00 2001
From: iwakeh <no-mail@unknown.org>
Date: Thu, 1 Jan 1970 00:00:00 +0000

comment:11 Changed 5 years ago by iwakeh

Yeah, combining code from different development setups usually creates
some difficulties. Only patience can help :-)

So, I compiled another two patchfiles without the whitespace changes.
I omitted the changes to the Vagrantfile and INSTALL, as these look allright in #12934

Let's move the discussion about formatting to a new issue,
I will comment there.

Hope the patches work this time!

These are the current patches:
https://trac.torproject.org/projects/tor/raw-attachment/ticket/12882/0001-logging-changes-for-build.xml-added-logback-config.patch
and
https://trac.torproject.org/projects/tor/raw-attachment/ticket/12882/0002-logging-java-source-changes.patch

Last edited 5 years ago by iwakeh (previous) (diff)

Changed 5 years ago by iwakeh

configuration changes

Changed 5 years ago by iwakeh

logging: java sources

Changed 5 years ago by iwakeh

obsolete

Changed 5 years ago by iwakeh

Attachment: onionoo-logging.patch​ added

obsolete

comment:12 Changed 5 years ago by karsten

Can you provide the missing org.torproject.onionoo.util.FormattingUtils class and any other missing classes? (I assume you didn't run git add before running git format-patch.) Thanks!

Changed 5 years ago by iwakeh

Attachment: FormattingUtils.java added

Now it should be complete.

comment:13 Changed 5 years ago by iwakeh

Yes you're right, I forgot the git add.
The file is attached.

comment:14 Changed 5 years ago by karsten

Here we go. Please see my task-12882 branch with your two patches plus a couple more that I'd like to squash into yours. Note that I switched back from Java 7 to 6 because of some difficulties with 7; we should discuss Java 7 on a separate ticket. Are you fine with me squashing these changes into yours and pushing to master?

comment:15 in reply to:  14 Changed 5 years ago by iwakeh

Things look fine to me. Go ahead.

What's the problem with java7?
(I didn't see anything new in #12881)

comment:16 Changed 5 years ago by karsten

Resolution: implemented
Status: needs_reviewclosed

Commented on Java 7 issue on #12881, rebased branch, merged to master, and deployed on the production system. Closing. Thanks a lot for your efforts here!

Note: See TracTickets for help on using tickets.