Merge pull request #2951 from sysadmind/console-logger

Add console logger option for pulp.server.

docs/user-guide/installation/extra_configuration.rst

@@ -141,3 +141,62 @@ following steps:
    For Upstart::
 
       $ for s in httpd pulp_workers pulp_resource_manager pulp_celerybeat; do sudo service $s restart; done;
+
+Logging Configuration
+---------------------
+
+.. _logging:
+
+Logging
+-------
+
+.. note::
+
+   Pulp reads the log configuration during startup. If the log level is changed while Pulp is
+   running, then you will need to restart it.
+
+
+Log Type
+^^^^^^^^
+
+Pulp's log type can be adjusted with the ``log_type`` setting in the ``[server]`` section of
+``/etc/pulp/server.conf``. This setting is optional and defaults to syslog. Valid choices are
+syslog and console.
+
+Log Level
+^^^^^^^^^
+
+Pulp's log level can be adjusted with the ``log_level`` setting in the ``[server]`` section of
+``/etc/pulp/server.conf``. This setting is optional and defaults to INFO. Valid choices are
+CRITICAL, ERROR, WARNING, INFO, DEBUG, and NOTSET.
+
+.. note::
+
+   This setting will only adjust the verbosity of the messages that Pulp emits. If you wish to see
+   all of these messages, you may also need to set the log level on your syslog handler. For example,
+   rsyslog typically only displays INFO and higher, so if you set Pulp to DEBUG it will still be
+   filtered by rsyslog. See the :ref:`rsyslogd` section for more information.
+
+Why Syslog?
+^^^^^^^^^^^
+
+Pulp's use of syslog is a departure from previous Pulp releases which used to write their own log
+files to /var/log/pulp/. This was problematic for Pulp's 2.4.0 release as Pulp evolved to use a
+multi-process distributed architecture. Python's file-based log handler cannot be used by multiple
+processes to write to the same file path, and so Pulp had to do something different. Syslog is a
+widely used logging protocol, and given the distributed nature of Pulp it was the most appropriate
+logging solution available.
+
+Task ID
+^^^^^^^
+
+Since Pulp is a multi-process application, Pulp will attempt to log a shortened 8 character version
+of the task id if the log entry is emitted from a task process. This can be used to look up the task
+in ``pulp-admin tasks`` commands.  An example of a log statement with a task id would be::
+
+    Jan 20 23:12:02 myhost pulp[30687]: pulp_rpm.plugins.importers.yum.sync:INFO: [338bdde4] Downloading 32 RPMs
+
+Here the shortened task id is ``338bdde4``. The full task id would be
+``338bdde4-608a-44ab-a79c-49c28b0fe037``. A statement without a task id would look like::
+
+    Jan 21 23:12:02 myhost pulp[30482]: pulp.server.async.worker_watcher:INFO: New worker 'resource_manager@myhost' discovered

docs/user-guide/troubleshooting.rst

@@ -1,38 +1,26 @@
 Troubleshooting
 ===============
 
-.. _logging:
+.. _troubleshoot_logging:
 
 Logging
 -------
 
-Starting with 2.4.0, Pulp uses syslog for its log messages. How to read Pulp's log messages
-therefore depends on which log handler your operating system uses. Two different log handlers that
-are commonly used will be documented here, journald and rsyslogd. If you happen to use a different
-syslog handler on your operating system, please refer to its documentation to learn how to access
-Pulp's log messages.
+Starting with 2.4.0, Pulp uses syslog by default for its log messages. Other options
+are available and you can find the setting for your system in ``/etc/pulp/server.conf``.
+How to read Pulp’s log messages therefore depends on which log handler your
+configuration specifies and how your operating system implements that configuration.
+Two different log handlers that are commonly used will be documented here: syslog and console.
 
-Log Level
-^^^^^^^^^
+Syslog
+^^^^^^
 
-Pulp's log level can be adjusted with the ``log_level`` setting in the ``[server]`` section of
-``/etc/pulp/server.conf``. This setting is optional and defaults to INFO. Valid choices are
-CRITICAL, ERROR, WARNING, INFO, DEBUG, and NOTSET.
-
-.. note::
-
-   This setting will only adjust the verbosity of the messages that Pulp emits. If you wish to see
-   all of these messages, you may also need to set the log level on your syslog handler. For example,
-   rsyslog typically only displays INFO and higher, so if you set Pulp to DEBUG it will still be
-   filtered by rsyslog. See the :ref:`rsyslogd` section for more information.
-
-.. note::
-
-   Pulp reads the log level configuration during startup. If the log level is changed while Pulp is
-   running, then you will need to restart it.
+The two common syslog utilities covered in this guide are journald and rsyslog.
+If you happen to use a different syslog handler on your operating system, please
+refer to its documentation to learn how to access Pulp’s log messages.
 
 journald
-^^^^^^^^
+~~~~~~~~
 
 journald is the logging daemon that is distributed as part of systemd. If you are using Fedora
 this is your primary logging daemon, though it's possible that you also have rsyslogd installed.
@@ -48,18 +36,15 @@ will display most of Pulp's log messages::
 We'll leave it to the systemd team to thoroughly document ``journalctl``, but it's worth mentioning
 that it can be used to aggregate the logs from Pulp's various processes together into one handy
 view using it's ``+`` operator. Pulp server runs in a variety of units, and if there are problems
-starting Pulp, you may wish to see log messages from httpd or celery. If you wanted to see the
-log messages from all server processes together you could use this command::
-
-    $ sudo journalctl SYSLOG_IDENTIFIER=pulp + SYSLOG_IDENTIFIER=celery + SYSLOG_IDENTIFIER=httpd
+startinudo journalctl SYSLOG_IDENTIFIER=pulp + SYSLOG_IDENTIFIER=celery + SYSLOG_IDENTIFIER=httpd
 
 A ``journalctl`` flag to know about is ``-f``, which performs a similar function
 as ``tail``'s ``-f`` flag.
 
 .. _rsyslogd:
 
 rsyslogd
-^^^^^^^^
+~~~~~~~~
 
 rsyslogd is another popular logging daemon. If you are using RHEL 6, this is your logging daemon.
 On many distributions, it is configured to log most messages to ``/var/log/messages``. If this is
@@ -75,30 +60,6 @@ If you wish to match Pulp messages and have them logged to a different file than
 details. An alternative could be to use ``tail`` and ``grep`` to view Pulp messages logged to
 ``/var/log/messages``.
 
-Why Syslog?
-^^^^^^^^^^^
-
-Pulp's use of syslog is a departure from previous Pulp releases which used to write their own log
-files to /var/log/pulp/. This was problematic for Pulp's 2.4.0 release as Pulp evolved to use a
-multi-process distributed architecture. Python's file-based log handler cannot be used by multiple
-processes to write to the same file path, and so Pulp had to do something different. Syslog is a
-widely used logging protocol, and given the distributed nature of Pulp it was the most appropriate
-logging solution available.
-
-Task ID
-^^^^^^^
-
-Since Pulp is a multi-process application, Pulp will attempt to log a shortened 8 character version
-of the task id if the log entry is emitted from a task process. This can be used to look up the task
-in ``pulp-admin tasks`` commands.  An example of a log statement with a task id would be::
-
-    Jan 20 23:12:02 myhost pulp[30687]: pulp_rpm.plugins.importers.yum.sync:INFO: [338bdde4] Downloading 32 RPMs
-
-Here the shortened task id is ``338bdde4``. The full task id would be
-``338bdde4-608a-44ab-a79c-49c28b0fe037``. A statement without a task id would look like::
-
-    Jan 21 23:12:02 myhost pulp[30482]: pulp.server.async.worker_watcher:INFO: New worker 'resource_manager@myhost' discovered
-
 Other logs
 ^^^^^^^^^^
 

server/etc/pulp/server.conf

@@ -74,6 +74,7 @@
 # debugging_mode:   boolean; toggles Pulp's debugging capabilities
 # log_level:        The desired logging level. Options are: CRITICAL, ERROR, WARNING, INFO, DEBUG,
 #                   and NOTSET. Pulp will default to INFO.
+# log_type:         how logs should be logged on the system. Options are: syslog, console
 # working_directory:path to where pulp workers can create working directories needed to complete tasks
 [server]
 # server_name: server_hostname
@@ -83,6 +84,7 @@
 # default_password: admin
 # debugging_mode: false
 # log_level: INFO
+# log_type: syslog
 # working_directory: /var/cache/pulp
 
 

server/pulp/server/config.py

@@ -118,6 +118,7 @@ def _load_config(self):
         'debugging_mode': 'false',
         'storage_dir': '/var/lib/pulp/',
         'log_level': 'INFO',
+        'log_type': 'syslog',
         'key_url': '/pulp/gpg',
         'ks_url': '/pulp/ks',
         'working_directory': '/var/cache/pulp'

server/pulp/server/logs.py

@@ -21,6 +21,7 @@
 LOG_FORMAT_STRING = 'pulp: %(name)s:%(levelname)s: %(message)s'
 TASK_LOG_FORMAT_STRING = 'pulp: %(name)s:%(levelname)s: [%(task_id)-8s] %(message)s'
 LOG_PATH = os.path.join('/', 'dev', 'log')
+VALID_LOGGERS = ['syslog', 'console']
 
 
 def _blacklist_loggers():
@@ -53,13 +54,29 @@ def start_logging(*args, **kwargs):
         log_level = DEFAULT_LOG_LEVEL
     root_logger = logging.getLogger()
     root_logger.setLevel(log_level)
+    try:
+        log_type = config.config.get('server', 'log_type')
+    except (ConfigParser.NoOptionError, AttributeError):
+        log_type = 'syslog'
+
+    if log_type not in VALID_LOGGERS:
+        print >> sys.stderr, "log_type not properly set. Defaulting to syslog."
+        log_type = 'syslog'
 
     # Set up our handler and add it to the root logger
-    if not os.path.exists(LOG_PATH):
-        print >> sys.stderr, "Unable to access to log, {log_path}.".format(log_path=LOG_PATH)
-        sys.exit(os.EX_UNAVAILABLE)
+    if log_type == 'syslog':
+        if not os.path.exists(LOG_PATH):
+            print >> sys.stderr, "Unable to access to log, {log_path}.".format(log_path=LOG_PATH)
+            sys.exit(os.EX_UNAVAILABLE)
+
+        handler = CompliantSysLogHandler(
+            address=LOG_PATH,
+            facility=CompliantSysLogHandler.LOG_DAEMON
+        )
+
+    elif log_type == 'console':
+        handler = logging.StreamHandler()
 
-    handler = CompliantSysLogHandler(address=LOG_PATH, facility=CompliantSysLogHandler.LOG_DAEMON)
     task_filter = TaskIDFilter()
     handler.addFilter(task_filter)
     formatter = TaskLogFormatter()

server/test/unit/server/test_logs.py

@@ -672,6 +672,15 @@ def log_message(q, num):
         self.assertTrue(check_same == 10)
 
 
+def console_logging_side_effect(section, key):
+    if section == 'server':
+        if key == 'log_level':
+            return 'INFO'
+        elif key == 'log_type':
+            return 'console'
+    return DEFAULT
+
+
 class TestStartLogging(unittest.TestCase):
     """
     Test the configure_pulp_logging() function.
@@ -728,7 +737,7 @@ def fake_getLogger(name=None):
         logs.start_logging()
 
         # The config should have been queried for log level
-        get.assert_called_once_with('server', 'log_level')
+        get.assert_has_calls(mock.call('server', 'log_level'))
         # We should have defaulted
         root_logger.setLevel.assert_called_once_with(logging.INFO)
 
@@ -752,7 +761,7 @@ def fake_getLogger(name=None):
         logs.start_logging()
 
         # The config should have been queried for log level
-        get.assert_called_once_with('server', 'log_level')
+        get.assert_has_calls(mock.call('server', 'log_level'))
         # We should have used the user's setting
         root_logger.setLevel.assert_called_once_with(logging.ERROR)
 
@@ -778,13 +787,13 @@ def fake_getLogger(name=None):
         logs.start_logging()
 
         # The config should have been queried for log level
-        get.assert_called_once_with('server', 'log_level')
+        get.assert_has_calls(mock.call('server', 'log_level'))
         # We should have defaulted
         root_logger.setLevel.assert_called_once_with(logs.DEFAULT_LOG_LEVEL)
 
     @mock.patch('pulp.server.logs.config.config.get', return_value='Debug')
     @mock.patch('pulp.server.logs.logging.getLogger')
-    def test_root_logger_configured(self, getLogger, get):
+    def test_root_logger_configured_default(self, getLogger, get):
         """
         This test ensures that the root logger is configured appropriately.
         """
@@ -812,6 +821,87 @@ def fake_getLogger(name=None):
         # And the handler should have the formatter with our format string
         self.assertTrue(isinstance(root_handler.formatter, logs.TaskLogFormatter))
 
+    @mock.patch('pulp.server.logs.config.config.get', return_value='something wrong')
+    @mock.patch('pulp.server.logs.logging.getLogger')
+    def test_log_type_invalid(self, getLogger, get):
+        """
+        Test that we still default to syslog if the user sets some non-existing log type.
+        """
+        root_logger = mock.MagicMock(spec=logging.Logger)
+        root_logger.manager = mock.MagicMock()
+        root_logger.manager.loggerDict = {}
+
+        def fake_getLogger(name=None):
+            if name is None:
+                return root_logger
+            root_logger.manager.loggerDict[name] = mock.MagicMock()
+            return root_logger.manager.loggerDict[name]
+        getLogger.side_effect = fake_getLogger
+
+        logs.start_logging()
+
+        # The config should have been queried for log type
+        get.assert_has_calls(mock.call('server', 'log_type'))
+        # We should have defaulted
+        root_logger.addHandler.assert_called_once()
+        root_handler = root_logger.addHandler.mock_calls[0][1][0]
+        self.assertTrue(isinstance(root_handler, logs.CompliantSysLogHandler))
+
+    @mock.patch('pulp.server.logs.config.config.get', return_value='console')
+    @mock.patch('pulp.server.logs.logging.getLogger')
+    def test_log_type_set(self, getLogger, get):
+        """
+        Test that we correctly allow users to set their log type.
+        """
+        root_logger = mock.MagicMock(spec=logging.Logger)
+        root_logger.manager = mock.MagicMock()
+        root_logger.manager.loggerDict = {}
+
+        def fake_getLogger(name=None):
+            if name is None:
+                return root_logger
+            root_logger.manager.loggerDict[name] = mock.MagicMock()
+            return root_logger.manager.loggerDict[name]
+        getLogger.side_effect = fake_getLogger
+
+        logs.start_logging()
+
+        # The config should have been queried for log level
+        get.assert_has_calls(mock.call('server', 'log_type'))
+        # We should have used the user's setting
+        root_logger.addHandler.assert_called_once()
+        root_handler = root_logger.addHandler.mock_calls[0][1][0]
+        self.assertTrue(isinstance(root_handler, logging.StreamHandler))
+
+    @mock.patch('pulp.server.logs.config.config.get', side_effect=console_logging_side_effect)
+    @mock.patch('pulp.server.logs.logging.getLogger')
+    def test_root_logger_configured_console(self, getLogger, get):
+        """
+        This test ensures that the root logger is configured appropriately when
+        console logging set.
+        """
+        root_logger = mock.MagicMock(spec=logging.Logger)
+        root_logger.manager = mock.MagicMock()
+        root_logger.manager.loggerDict = {}
+
+        def fake_getLogger(name=None):
+            if name is None:
+                return root_logger
+            if name not in root_logger.manager.loggerDict:
+                root_logger.manager.loggerDict[name] = mock.MagicMock()
+            return root_logger.manager.loggerDict[name]
+        getLogger.side_effect = fake_getLogger
+
+        logs.start_logging()
+
+        # Let's make sure the handler is setup right
+        self.assertEqual(root_logger.addHandler.call_count, 1)
+        root_handler = root_logger.addHandler.mock_calls[0][1][0]
+        self.assertTrue(isinstance(root_handler, logging.StreamHandler))
+
+        # And the handler should have the formatter with our format string
+        self.assertTrue(isinstance(root_handler.formatter, logs.TaskLogFormatter))
+
 
 class TestStopLogging(unittest.TestCase):
     """