diff --git a/notebook/log.py b/notebook/log.py index af87528fe3..eb246bc400 100644 --- a/notebook/log.py +++ b/notebook/log.py @@ -10,7 +10,7 @@ from .prometheus.log_functions import prometheus_log_method -def log_request(handler): +def log_request(handler, log=access_log, log_json=False): """log a bit more information about each request than tornado's default - move static file get success to debug-level (reduces noise) @@ -22,29 +22,35 @@ def log_request(handler): request = handler.request if status < 300 or status == 304: # Successes (or 304 FOUND) are debug-level - log_method = access_log.debug + log_method = log.debug elif status < 400: - log_method = access_log.info + log_method = log.info elif status < 500: - log_method = access_log.warning + log_method = log.warning else: - log_method = access_log.error + log_method = log.error - request_time = 1000.0 * handler.request.request_time() + request_time = 1000.0 * request.request_time() ns = dict( status=status, method=request.method, ip=request.remote_ip, uri=request.uri, - request_time=request_time, + request_time=float('%.2f' % request_time), ) - msg = "{status} {method} {uri} ({ip}) {request_time:.2f}ms" + msg = "{status} {method} {uri} ({ip}) {request_time:f}ms" if status >= 400: # log bad referers ns['referer'] = request.headers.get('Referer', 'None') msg = msg + ' referer={referer}' if status >= 500 and status != 502: # log all headers if it caused an error - log_method(json.dumps(dict(request.headers), indent=2)) - log_method(msg.format(**ns)) + if log_json: + log_method("", extra=dict(props=dict(request.headers))) + else: + log_method(json.dumps(dict(request.headers), indent=2)) + if log_json: + log_method("", extra=dict(props=ns)) + else: + log_method(msg.format(**ns)) prometheus_log_method(handler) diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py index 66bb6ee84d..47ee952e33 100755 --- a/notebook/notebookapp.py +++ b/notebook/notebookapp.py @@ -8,6 +8,7 @@ import binascii import datetime import errno +import functools import gettext import hashlib import hmac @@ -247,9 +248,12 @@ def init_settings(self, jupyter_app, kernel_manager, contents_manager, # collapse $HOME to ~ root_dir = '~' + root_dir[len(home):] + # Use the NotebookApp logger and its formatting for tornado request logging. + log_function = functools.partial( + log_request, log=log, log_json=jupyter_app.log_json) settings = dict( # basics - log_function=log_request, + log_function=log_function, base_url=base_url, default_url=default_url, template_path=template_path, @@ -701,6 +705,43 @@ class NotebookApp(JupyterApp): _log_formatter_cls = LogFormatter + _json_logging_import_error_logged = False + + log_json = Bool(False, config=True, + help=_('Set to True to enable JSON formatted logs. ' + 'Run "pip install notebook[json-logging]" to install the ' + 'required dependent packages. Can also be set using the ' + 'environment variable JUPYTER_ENABLE_JSON_LOGGING=true.') + ) + + @default('log_json') + def _default_log_json(self): + """Get the log_json value from the environment.""" + return os.getenv('JUPYTER_ENABLE_JSON_LOGGING', 'false').lower() == 'true' + + @validate('log_json') + def _validate_log_json(self, proposal): + # If log_json=True, see if the json_logging package can be imported and + # override _log_formatter_cls if so. + value = proposal['value'] + if value: + try: + import json_logging + self.log.debug('initializing json logging') + json_logging.init_non_web(enable_json=True) + self._log_formatter_cls = json_logging.JSONLogFormatter + except ImportError: + # If configured for json logs and we can't do it, log a hint. + # Only log the error once though. + if not self._json_logging_import_error_logged: + self.log.warning( + 'Unable to use json logging due to missing packages. ' + 'Run "pip install notebook[json-logging]" to fix.' + ) + self._json_logging_import_error_logged = True + value = False + return value + @default('log_level') def _default_log_level(self): return logging.INFO diff --git a/notebook/tests/test_log.py b/notebook/tests/test_log.py new file mode 100644 index 0000000000..b2964be25f --- /dev/null +++ b/notebook/tests/test_log.py @@ -0,0 +1,40 @@ +import unittest +from unittest import mock + +from notebook import log + + +class TestLogRequest(unittest.TestCase): + + @mock.patch('notebook.log.prometheus_log_method') + def test_log_request_json(self, mock_prometheus): + headers = {'Referer': 'test'} + request = mock.Mock( + request_time=mock.Mock(return_value=1), + headers=headers, + method='GET', + remote_ip='1.2.3.4', + uri='/notebooks/foo/bar' + ) + handler = mock.MagicMock( + request=request, + get_status=mock.Mock(return_value=500) + ) + logger = mock.MagicMock() + log.log_request(handler, log=logger, log_json=True) + # Since the status was 500 there should be two calls to log.error, + # one with the request headers and another with the other request + # parameters. + self.assertEqual(2, logger.error.call_count) + logger.error.assert_has_calls([ + mock.call("", extra=dict(props=dict(headers))), + mock.call("", extra=dict(props={ + 'status': handler.get_status(), + 'method': request.method, + 'ip': request.remote_ip, + 'uri': request.uri, + 'request_time': 1000.0, + 'referer': headers['Referer'] + })) + ]) + mock_prometheus.assert_called_once_with(handler) diff --git a/notebook/tests/test_notebookapp.py b/notebook/tests/test_notebookapp.py index d8543feed9..2c42d4359f 100644 --- a/notebook/tests/test_notebookapp.py +++ b/notebook/tests/test_notebookapp.py @@ -190,6 +190,12 @@ def test_list_running_servers(self): assert len(servers) >= 1 assert self.port in {info['port'] for info in servers} + def test_log_json_default(self): + self.assertFalse(self.notebook.log_json) + + def test_validate_log_json(self): + self.assertFalse(self.notebook._validate_log_json(dict(value=False))) + # UNIX sockets aren't available on Windows. if not sys.platform.startswith('win'): @@ -201,3 +207,29 @@ def test_list_running_sock_servers(self): servers = list(notebookapp.list_running_servers()) assert len(servers) >= 1 assert self.sock in {info['sock'] for info in servers} + + +class NotebookAppJSONLoggingTests(NotebookTestBase): + """Tests for when json logging is enabled.""" + @classmethod + def setup_class(cls): + super(NotebookAppJSONLoggingTests, cls).setup_class() + try: + import json_logging + cls.json_logging_available = True + except ImportError: + cls.json_logging_available = False + + @classmethod + def get_patch_env(cls): + test_env = super(NotebookAppJSONLoggingTests, cls).get_patch_env() + test_env.update({'JUPYTER_ENABLE_JSON_LOGGING': 'true'}) + return test_env + + def test_log_json_enabled(self): + self.assertTrue(self.notebook._default_log_json()) + + def test_validate_log_json(self): + self.assertEqual( + self.notebook._validate_log_json(dict(value=True)), + self.json_logging_available) diff --git a/setup.py b/setup.py index c495fd69ed..e7ca209f6f 100755 --- a/setup.py +++ b/setup.py @@ -119,6 +119,7 @@ 'nbval', 'nose-exclude', 'selenium', 'pytest', 'pytest-cov'], 'docs': ['sphinx', 'nbsphinx', 'sphinxcontrib_github_alt', 'sphinx_rtd_theme'], 'test:sys_platform != "win32"': ['requests-unixsocket'], + 'json-logging': ['json-logging'] }, python_requires = '>=3.5', entry_points = {