commit 1a2ba3577321ebfbfbb2e75e1d9719d0e3728af6 Author: Arturo Filastò arturo@filasto.net Date: Sat Nov 12 13:06:16 2016 +0100

Improvements to log handling

* Add rotate setting to configure daily or length based rotation

* Make MsecLogObserver inherit the log_level properties from LogLevelObserver

* Add option to disable log rotation This can be used if you would rather handle log rotation via logrotate.d and similar system tools.

* Support max_rotate_files option

* Add some basic unittests for log related functions

* Improve comments to rotation options

* Disable duckduckgo geoip lookup service --- data/ooniprobe.conf.sample | 14 ++++++++++++-- ooni/geoip.py | 7 +++++-- ooni/settings.py | 10 ++++++++++ ooni/tests/test_utils.py | 47 ++++++++++++++++++++++++++++++++++++++++++++++ ooni/utils/log.py | 19 ++++++++++++++----- 5 files changed, 88 insertions(+), 9 deletions(-)

diff --git a/data/ooniprobe.conf.sample b/data/ooniprobe.conf.sample index ee9a2c9..5880aee 100644 --- a/data/ooniprobe.conf.sample +++ b/data/ooniprobe.conf.sample @@ -4,8 +4,18 @@

basic: # Where OONIProbe should be writing its log file - logfile: /var/log/ooniprobe.log - loglevel: WARNING + # logfile: ooniprobe.log + # loglevel: WARNING + # Will rotate logs daily when "daily" or based on rotate_length + # when "length" is set. null to disable rotation. + # rotate: daily + # rotate_length: 1M + # Sets an upper bound on the number of rotated files, only works when + # "length" is the rotation mode + # max_rotated_files: null + # The maximum amount of data to store on disk. Once the quota is reached, + # we will start deleting older reports. + # measurement_quota: 1G privacy: # Should we include the IP address of the probe in the report? includeip: false diff --git a/ooni/geoip.py b/ooni/geoip.py index 9148e34..c765015 100644 --- a/ooni/geoip.py +++ b/ooni/geoip.py @@ -164,8 +164,11 @@ class ProbeIP(object):

def __init__(self): self.geoIPServices = { - 'ubuntu': UbuntuGeoIP, - 'duckduckgo': DuckDuckGoGeoIP + 'ubuntu': UbuntuGeoIP + # We are disabling this because it sometimes creates parsing + # errors. + # See: https://github.com/TheTorProject/ooni-probe/issues/670 + # 'duckduckgo': DuckDuckGoGeoIP } self.geodata = { 'asn': 'AS0', diff --git a/ooni/settings.py b/ooni/settings.py index ed2d1e1..eb4f052 100644 --- a/ooni/settings.py +++ b/ooni/settings.py @@ -22,6 +22,13 @@ basic: # Where OONIProbe should be writing its log file # logfile: {logfile} # loglevel: WARNING + # Will rotate logs daily when "daily" or based on rotate_length + # when "length" is set. null to disable rotation. + # rotate: daily + # rotate_length: 1M + # Sets an upper bound on the number of rotated files, only works when + # "length" is the rotation mode + # max_rotated_files: null # The maximum amount of data to store on disk. Once the quota is reached, # we will start deleting older reports. # measurement_quota: 1G @@ -105,6 +112,9 @@ defaults = { "basic": { "loglevel": "WARNING", "logfile": "ooniprobe.log", + "rotate": "daily", + "rotate_length": "1M", + "max_rotated_files": None, "measurement_quota": "1G" }, "privacy": { diff --git a/ooni/tests/test_utils.py b/ooni/tests/test_utils.py index 4ef2926..f0f4ce0 100644 --- a/ooni/tests/test_utils.py +++ b/ooni/tests/test_utils.py @@ -1,5 +1,6 @@ import os import tempfile +from mock import patch

from twisted.trial import unittest

@@ -77,3 +78,49 @@ class TestUtils(unittest.TestCase): with open(os.path.join(tmp_dir, "subdir", "something.txt"), "w") as out_file: out_file.write("A"*1000) self.assertEqual(directory_usage(tmp_dir), 1000*2) + +class LoggingTests(unittest.TestCase): + def setUp(self): + self.dir = self.mktemp() + os.makedirs(self.dir) + self.name = "test.log" + self.path = os.path.join(self.dir, self.name) + + @patch('ooni.settings.config') + def test_length_rotate(self, mock_config): + mock_config.basic.loglevel = 'DEBUG' + mock_config.advanced.debug = False + mock_config.basic.rotate = 'length' + mock_config.basic.rotate_length = '1M' + + ooni_logger = log.OONILogger() + ooni_logger.start(logfile=self.path) + + ooni_logger.debug("1"*(1024**2)) + + # This will trigger the rotation + ooni_logger.debug("2") + + ooni_logger.stop() + self.assertTrue(os.path.exists("{0}.1".format(self.path))) + self.assertFalse(os.path.exists("{0}.2".format(self.path))) + + + @patch('ooni.settings.config') + def test_log_levels(self, mock_config): + mock_config.basic.loglevel = 'WARN' + mock_config.advanced.debug = False + mock_config.basic.rotate = None + + ooni_logger = log.OONILogger() + ooni_logger.start(logfile=self.path) + ooni_logger.msg("Should not print") + ooni_logger.warn("Will print") + ooni_logger.err("Will print") + ooni_logger.debug("Should not print") + ooni_logger.stop() + with open(self.path) as in_file: + self.assertEqual( + len(in_file.readlines()), + 2 + ) diff --git a/ooni/utils/log.py b/ooni/utils/log.py index b4136be..353b8b2 100644 --- a/ooni/utils/log.py +++ b/ooni/utils/log.py @@ -6,9 +6,10 @@ import logging from datetime import datetime

from twisted.python import log as tw_log -from twisted.python.logfile import DailyLogFile +from twisted.python.logfile import DailyLogFile, LogFile

from ooni.utils import mkdir_p +from ooni.utils.files import human_size_to_bytes from ooni import otime

# Get rid of the annoying "No route found for @@ -101,7 +102,7 @@ class StdoutStderrObserver(LogLevelObserver): self.write(text + "\n") self.flush()

-class MsecLogObserver(tw_log.FileLogObserver): +class MsecLogObserver(LogLevelObserver): def formatTime(self, when): """ Code from Twisted==16.4.1 modified to log microseconds. Although this @@ -172,10 +173,18 @@ class OONILogger(object): if config.advanced.debug: stdout_log_level = levels['DEBUG']

- daily_logfile = DailyLogFile(log_filename, log_folder) + if config.basic.rotate is 'daily': + logfile = DailyLogFile(log_filename, log_folder) + elif config.basic.rotate is 'length': + logfile = LogFile(log_filename, log_folder, + rotateLength=int(human_size_to_bytes( + config.basic.rotate_length + )), + maxRotatedFiles=config.basic.max_rotated_files) + else: + logfile = open(os.path.join(log_folder, log_filename), 'a')

- self.fileObserver = MsecLogObserver(LogLevelObserver(daily_logfile, - log_level=file_log_level)) + self.fileObserver = MsecLogObserver(logfile, log_level=file_log_level) self.stdoutObserver = StdoutStderrObserver(sys.stdout, log_level=stdout_log_level)