Disable automatic log rotation

With this commit we disable automatic log rotation in Rally's
out-of-the-box logging configuration because it can lead to race
conditions (multiple processes attempting to rollover the log file).

We also migrate existing configurations if possible (i.e. the user did
not modify it) and provide an example configuration for `logrotate`.

Closes elastic#539
Relates elastic#560

docs/configuration.rst

@@ -119,7 +119,19 @@ Logging in Rally is configured in ``~/.rally/logging.json``. For more informatio
 * The Python reference documentation on the `logging configuration schema <https://docs.python.org/3/library/logging.config.html#logging-config-dictschema>`_ explains the file format.
 * The `logging handler documentation <https://docs.python.org/3/library/logging.handlers.html>`_ describes how to customize where log output is written to.
 
-By default, Rally will log all output to ``~/.rally/logs/rally.log`` and rotate this file daily.
+By default, Rally will log all output to ``~/.rally/logs/rally.log``.
+
+The log file will not be rotated automatically as this is problematic due to Rally's multi-process architecture. Setup an external tool like `logrotate <https://linux.die.net/man/8/logrotate>`_ to achieve that. See the following example as a starting point for your own ``logrotate`` configuration and ensure to replace the path ``/home/user/.rally/logs/rally.log`` with the proper one::
+
+    /home/user/.rally/logs/rally.log {
+            daily                   # rotate daily
+            rotate 7                # keep the last seven log files
+            maxage 14               # remove logs older than 14 days
+            compress                # compress old logs ...
+            delaycompress           # ... after moving them
+            missingok               # ignore missing log files
+            notifempty              # don't attempt to rotate empty ones
+    }
 
 Example
 ~~~~~~~

docs/migrate.rst

@@ -1,6 +1,26 @@
 Migration Guide
 ===============
 
+Migrating to Rally 1.0.1
+------------------------
+
+Logs are not rotated
+^^^^^^^^^^^^^^^^^^^^
+
+With Rally 1.0.1 we have disabled automatic rotation of logs by default because it can lead to race conditions due to Rally's multi-process architecture. If you did not change the default out-of-the-box logging configuration, Rally will automatically fix your configuration. Otherwise, you need to replace all instances of ``logging.handlers.TimedRotatingFileHandler`` with ``logging.handlers.WatchedFileHandler`` to disable log rotation.
+
+To rotate logs we recommend to use external tools like `logrotate <https://linux.die.net/man/8/logrotate>`_. See the following example as a starting point for your own ``logrotate`` configuration and ensure to replace the path ``/home/user/.rally/logs/rally.log`` with the proper one::
+
+    /home/user/.rally/logs/rally.log {
+            daily                   # rotate daily
+            rotate 7                # keep the last seven log files
+            maxage 14               # remove logs older than 14 days
+            compress                # compress old logs ...
+            delaycompress           # ... after moving them
+            missingok               # ignore missing log files
+            notifempty              # don't attempt to rotate empty ones
+    }
+
 Migrating to Rally 1.0.0
 ------------------------
 

esrally/log.py

@@ -3,6 +3,7 @@
 import json
 import time
 import os
+import hashlib
 
 from esrally.utils import io
 
@@ -31,6 +32,26 @@ def default_log_path():
     return os.path.join(os.path.expanduser("~"), ".rally", "logs")
 
 
+def remove_obsolete_default_log_config():
+    """
+    Log rotation is problematic because Rally uses multiple processes and there is a lurking race condition when
+    rolling log files. Hence, we do not rotate logs from within Rally and leverage established tools like logrotate for that.
+
+    Checks whether the user has a problematic out-of-the-box logging configuration delivered with Rally 1.0.0 which
+    used log rotation and removes it so it can be replaced by a new one in a later step.
+    """
+    log_config = log_config_path()
+    if io.exists(log_config):
+        source_path = io.normalize_path(os.path.join(os.path.dirname(__file__), "resources", "logging_1_0_0.json"))
+        with open(source_path, "r", encoding="UTF-8") as src:
+            contents = src.read().replace("${LOG_PATH}", default_log_path())
+            source_hash = hashlib.sha512(contents.encode()).hexdigest()
+        with open(log_config, "r", encoding="UTF-8") as target:
+            target_hash = hashlib.sha512(target.read().encode()).hexdigest()
+        if source_hash == target_hash:
+            os.rename(log_config, "{}.bak".format(log_config))
+
+
 def install_default_log_config():
     """
     Ensures a log configuration file is present on this machine. The default

esrally/rally.py

@@ -483,6 +483,7 @@ def dispatch_sub_command(cfg, sub_command):
 
 def main():
     check_python_version()
+    log.remove_obsolete_default_log_config()
     log.install_default_log_config()
     log.configure_logging()
     logger = logging.getLogger(__name__)

esrally/rallyd.py

@@ -52,6 +52,7 @@ def status():
 
 def main():
     check_python_version()
+    log.remove_obsolete_default_log_config()
     log.install_default_log_config()
     log.configure_logging()
     console.init()

esrally/resources/logging.json

@@ -19,11 +19,8 @@
   },
   "handlers": {
     "rally_log_handler": {
-      "class": "logging.handlers.TimedRotatingFileHandler",
+      "class": "logging.handlers.WatchedFileHandler",
       "filename": "${LOG_PATH}/rally.log",
-      "utc": true,
-      "when": "midnight",
-      "backupCount": 14,
       "encoding": "UTF-8",
       "formatter": "normal",
       "filters": ["isActorLog"]

esrally/resources/logging_1_0_0.json

@@ -0,0 +1,55 @@
+{
+  "version": 1,
+  "formatters": {
+    "normal": {
+      "format": "%(asctime)s,%(msecs)d %(actorAddress)s/PID:%(process)d %(name)s %(levelname)s %(message)s",
+      "datefmt": "%Y-%m-%d %H:%M:%S",
+      "()": "esrally.log.configure_utc_formatter"
+    },
+    "profile": {
+      "format": "%(asctime)s,%(msecs)d PID:%(process)d %(name)s %(levelname)s %(message)s",
+      "datefmt": "%Y-%m-%d %H:%M:%S",
+      "()": "esrally.log.configure_utc_formatter"
+    }
+  },
+  "filters": {
+    "isActorLog": {
+      "()": "thespian.director.ActorAddressLogFilter"
+    }
+  },
+  "handlers": {
+    "rally_log_handler": {
+      "class": "logging.handlers.TimedRotatingFileHandler",
+      "filename": "${LOG_PATH}/rally.log",
+      "utc": true,
+      "when": "midnight",
+      "backupCount": 14,
+      "encoding": "UTF-8",
+      "formatter": "normal",
+      "filters": ["isActorLog"]
+    },
+    "rally_profile_handler": {
+      "class": "logging.FileHandler",
+      "filename": "${LOG_PATH}/profile.log",
+      "delay": true,
+      "encoding": "UTF-8",
+      "formatter": "profile"
+    }
+  },
+  "root": {
+    "handlers": ["rally_log_handler"],
+    "level": "INFO"
+  },
+  "loggers": {
+    "elasticsearch": {
+      "handlers": ["rally_log_handler"],
+      "level": "WARNING",
+      "propagate": false
+    },
+    "rally.profile": {
+      "handlers": ["rally_profile_handler"],
+      "level": "INFO",
+      "propagate": false
+    }
+  }
+}