From 1929fb53b841b81ef4fb1006a6a71a18430dfd84 Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Wed, 7 Oct 2020 15:17:22 -0500
Subject: [PATCH 01/12] Add support for JSON formatted logs

This adds a new extra package dependency on `json-logging`
and an environment variable, which when set to "true" regardless
of case, will try to use the json-logging non-web app log formatter.

If the `json-logging` package is not installed but the environment
variable is True, something like this will be logged but it will not
crash the application:

```
$ ENABLE_JSON_LOGGING=true jupyter notebook
Unable to use json logging due to missing packages. Run "pip install notebook[json-logging]" to fix.
Traceback (most recent call last):
  File "/home/osboxes/jupyter/notebook/notebook/notebookapp.py", line 144, in <module>
    import json_logging
ModuleNotFoundError: No module named 'json_logging'
```

Initially I tried to add a new Bool config option to toggle this but
the problem is (from my limited understanding of traitlets and tornado)
is that `_log_formatter_cls` needs to be set early and trying to se the
log formatter later in `init_logging` is too late - or at least I couldn't
figure out a way to reset the log formatter dynamically (I tried calling
`_log_format_changed` [1] but that didn't work).

With this working you get logs like this:

```
{"written_at": "2020-10-07T21:10:51.606Z", "written_ts": 1602105051606265000, "msg": "404 GET /nbextensions/widgets/notebook/js/extension.js (127.0.0.1) 9.26ms referer=http://localhost:8888/notebooks/Untitled.ipynb", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "WARNING", "module": "log", "line_no": 49}
{"written_at": "2020-10-07T21:10:54.443Z", "written_ts": 1602105054443309000, "msg": "Starting buffering for f260ddd7-938c-42d0-ac3b-455bea76694f:49f30b53fc4b4ec6a8f2fb748a171613", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "INFO", "module": "kernelmanager", "line_no": 222}
{"written_at": "2020-10-07T21:10:54.446Z", "written_ts": 1602105054446264000, "msg": "Kernel shutdown: f260ddd7-938c-42d0-ac3b-455bea76694f", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "INFO", "module": "multikernelmanager", "line_no": 201}
```

An obvious improvement here would to be able to split the `msg` fields apart
so that we can log things like response status code, request method, request
URL, response_time_ms etc. That should be possible with the `JSONLogWebFormatter`
from `json-logging` but when I tried using that I was getting errors from
the library about a correlation id (which is based on a request header we
don't use). The `json-logging` library supports several web frameworks like
Flask but unfortunately does not have built in support for Tornado, but it does
support custom formatters so that might be a follow up option to improve on this.

[1] https://github.com/ipython/traitlets/blob/4.3.3/traitlets/config/application.py#L195

Closes #5798
---
 notebook/notebookapp.py | 17 ++++++++++++++++-
 setup.py                |  1 +
 2 files changed, 17 insertions(+), 1 deletion(-)

diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index dc7c84c572..6c1323edf8 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -138,6 +138,19 @@
 except ImportError:
     terminado_available = False
 
+# Tolerate missing json_logging package.
+enable_json_logs = os.getenv('ENABLE_JSON_LOGGING', 'false').lower() == 'true'
+try:
+    import json_logging
+except ImportError:
+    # If configured for json logs and we can't do it, log a hint.
+    if enable_json_logs:
+        logging.getLogger(__name__).exception(
+            'Unable to use json logging due to missing packages. '
+            'Run "pip install notebook[json-logging]" to fix.'
+        )
+    enable_json_logs = False
+
 #-----------------------------------------------------------------------------
 # Module globals
 #-----------------------------------------------------------------------------
@@ -702,7 +715,9 @@ class NotebookApp(JupyterApp):
         password=(NotebookPasswordApp, NotebookPasswordApp.description.splitlines()[0]),
     )
 
-    _log_formatter_cls = LogFormatter
+    # Unless there is a way to re-initialize the log formatter (like with _log_format_changed?)
+    # we need to load the json logging formatter early here otherwise traitlets complains.
+    _log_formatter_cls = json_logging.JSONLogFormatter if enable_json_logs else LogFormatter
 
     @default('log_level')
     def _default_log_level(self):
diff --git a/setup.py b/setup.py
index b1dccc909f..7d6a7c71ee 100755
--- a/setup.py
+++ b/setup.py
@@ -120,6 +120,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 = {

From b617d910521d7ffb5d9099b2307c6026dca4f3da Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Wed, 7 Oct 2020 16:57:43 -0500
Subject: [PATCH 02/12] Check for json log formatting in log_request

This gets us closer to logging parts of the request
as separate json fields but not all the way there.

For example:

```json
{"written_at": "2020-10-07T21:52:16.975Z", "written_ts": 1602107536975497000, "msg": "{'status': 404, 'method': 'GET', 'ip': '127.0.0.1', 'uri': '/nbextensions/widgets/notebook/js/extension.js', 'request_time': 1.9807815551757812, 'referer': 'http://localhost:8888/notebooks/test.ipynb'}", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "WARNING", "module": "log", "line_no": 54}
```
---
 notebook/log.py         | 12 +++++++++++-
 notebook/notebookapp.py |  9 +++++----
 notebook/utils.py       |  4 ++++
 3 files changed, 20 insertions(+), 5 deletions(-)

diff --git a/notebook/log.py b/notebook/log.py
index af87528fe3..d81a8ea669 100644
--- a/notebook/log.py
+++ b/notebook/log.py
@@ -9,6 +9,10 @@
 from tornado.log import access_log
 from .prometheus.log_functions import prometheus_log_method
 
+from .utils import enable_json_logs
+
+_enable_json_logs = enable_json_logs()
+
 
 def log_request(handler):
     """log a bit more information about each request than tornado's default
@@ -46,5 +50,11 @@ def log_request(handler):
     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 _enable_json_logs:
+        # FIXME: this still logs the msg as a serialized json string,
+        # presumably because it's using tornado's access_log rather than
+        # the logger setup in notebook app with _log_formatter_cls.
+        log_method(ns)
+    else:
+        log_method(msg.format(**ns))
     prometheus_log_method(handler)
diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index 6c1323edf8..45c1cb5eb9 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -113,6 +113,7 @@
 from ._tz import utcnow, utcfromtimestamp
 from .utils import (
     check_pid,
+    enable_json_logs,
     pathname2url,
     run_sync,
     unix_socket_in_use,
@@ -139,17 +140,17 @@
     terminado_available = False
 
 # Tolerate missing json_logging package.
-enable_json_logs = os.getenv('ENABLE_JSON_LOGGING', 'false').lower() == 'true'
+_enable_json_logs = enable_json_logs()
 try:
     import json_logging
 except ImportError:
     # If configured for json logs and we can't do it, log a hint.
-    if enable_json_logs:
+    if _enable_json_logs:
         logging.getLogger(__name__).exception(
             'Unable to use json logging due to missing packages. '
             'Run "pip install notebook[json-logging]" to fix.'
         )
-    enable_json_logs = False
+    _enable_json_logs = False
 
 #-----------------------------------------------------------------------------
 # Module globals
@@ -717,7 +718,7 @@ class NotebookApp(JupyterApp):
 
     # Unless there is a way to re-initialize the log formatter (like with _log_format_changed?)
     # we need to load the json logging formatter early here otherwise traitlets complains.
-    _log_formatter_cls = json_logging.JSONLogFormatter if enable_json_logs else LogFormatter
+    _log_formatter_cls = json_logging.JSONLogFormatter if _enable_json_logs else LogFormatter
 
     @default('log_level')
     def _default_log_level(self):
diff --git a/notebook/utils.py b/notebook/utils.py
index 1196d6d898..cbb0cf10a0 100644
--- a/notebook/utils.py
+++ b/notebook/utils.py
@@ -401,3 +401,7 @@ def unix_socket_in_use(socket_path):
         return True
     finally:
         sock.close()
+
+
+def enable_json_logs():
+    return os.getenv('ENABLE_JSON_LOGGING', 'false').lower() == 'true'

From ca95490d7c6022e9910d63ac77ebbe7ba8710d69 Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Fri, 9 Oct 2020 14:25:34 -0500
Subject: [PATCH 03/12] Add log_json config option with default and validation
 handling

This adds the `NotebookApp.log_json` CLI option which defaults to
False. The default value comes from the `JUPYTER_ENABLE_JSON_LOGGING`
environment variable. A validation hook is added such that if json
logging is enabled but the `json-logging` package is not installed,
an error is logged and the effective `log_json` value is False.

If enabled and the `json-logging` package is installed, the `init_logging`
method will initialize the non-web [1] json logging formatter.

[1] https://github.com/bobbui/json-logging-python#21-non-web-application-log
---
 notebook/notebookapp.py | 62 ++++++++++++++++++++++++++++++-----------
 notebook/utils.py       |  2 +-
 2 files changed, 47 insertions(+), 17 deletions(-)

diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index 45c1cb5eb9..7359f23ad1 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -139,19 +139,6 @@
 except ImportError:
     terminado_available = False
 
-# Tolerate missing json_logging package.
-_enable_json_logs = enable_json_logs()
-try:
-    import json_logging
-except ImportError:
-    # If configured for json logs and we can't do it, log a hint.
-    if _enable_json_logs:
-        logging.getLogger(__name__).exception(
-            'Unable to use json logging due to missing packages. '
-            'Run "pip install notebook[json-logging]" to fix.'
-        )
-    _enable_json_logs = False
-
 #-----------------------------------------------------------------------------
 # Module globals
 #-----------------------------------------------------------------------------
@@ -716,9 +703,45 @@ class NotebookApp(JupyterApp):
         password=(NotebookPasswordApp, NotebookPasswordApp.description.splitlines()[0]),
     )
 
-    # Unless there is a way to re-initialize the log formatter (like with _log_format_changed?)
-    # we need to load the json logging formatter early here otherwise traitlets complains.
-    _log_formatter_cls = json_logging.JSONLogFormatter if _enable_json_logs else LogFormatter
+    _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 enable_json_logs()
+
+    @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_formatter_cls = json_logging.JSONLogFormatter
+                # Note that we don't need to trigger _log_format_changed here
+                # because init_logging will set the JSONLogFormatter on all
+                # of the registered loggers.
+            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:
+                    logging.getLogger(__name__).exception(
+                        '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):
@@ -1606,6 +1629,13 @@ def init_configurables(self):
         )
 
     def init_logging(self):
+        if self.log_json:
+            self.log.debug('initializing json logging')
+            # Note that we don't guard against ImportError here because if the
+            # package is missing then _validate_log_json should have set
+            # log_json=False.
+            import json_logging
+            json_logging.init_non_web(enable_json=True)
         # This prevents double log messages because tornado use a root logger that
         # self.log is a child of. The logging module dispatches log messages to a log
         # and all of its ancenstors until propagate is set to False.
diff --git a/notebook/utils.py b/notebook/utils.py
index cbb0cf10a0..5f3f70164e 100644
--- a/notebook/utils.py
+++ b/notebook/utils.py
@@ -404,4 +404,4 @@ def unix_socket_in_use(socket_path):
 
 
 def enable_json_logs():
-    return os.getenv('ENABLE_JSON_LOGGING', 'false').lower() == 'true'
+    return os.getenv('JUPYTER_ENABLE_JSON_LOGGING', 'false').lower() == 'true'

From 6a74393f95d27a80850dd0963ed3fa600332995f Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Fri, 9 Oct 2020 15:09:54 -0500
Subject: [PATCH 04/12] Pass NotebookApp logger to log_request

In order to use the same logger from the notebook app we
need to pass it through to the log_request function. To
do that we need to use a partial function so the `log` kwarg
is available. If not provided the default logger is the same
as before, the tornado web access logger.

This is necessary for the `log_json` settings to be used for
both the notebook app logs and the web app request logging.

There is still a todo needed here so that the individual
request fields get formatted separately rather than dumped
into the `msg` field.
---
 notebook/log.py         | 27 ++++++++++-----------------
 notebook/notebookapp.py |  5 ++++-
 2 files changed, 14 insertions(+), 18 deletions(-)

diff --git a/notebook/log.py b/notebook/log.py
index d81a8ea669..46cd935857 100644
--- a/notebook/log.py
+++ b/notebook/log.py
@@ -9,12 +9,8 @@
 from tornado.log import access_log
 from .prometheus.log_functions import prometheus_log_method
 
-from .utils import enable_json_logs
 
-_enable_json_logs = enable_json_logs()
-
-
-def log_request(handler):
+def log_request(handler, log=access_log):
     """log a bit more information about each request than tornado's default
     
     - move static file get success to debug-level (reduces noise)
@@ -26,15 +22,15 @@ 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,
@@ -50,11 +46,8 @@ def log_request(handler):
     if status >= 500 and status != 502:
         # log all headers if it caused an error
         log_method(json.dumps(dict(request.headers), indent=2))
-    if _enable_json_logs:
-        # FIXME: this still logs the msg as a serialized json string,
-        # presumably because it's using tornado's access_log rather than
-        # the logger setup in notebook app with _log_formatter_cls.
-        log_method(ns)
-    else:
-        log_method(msg.format(**ns))
+    # if _enable_json_logs:
+    #     log_method(ns)
+    # else:
+    log_method(msg.format(**ns))
     prometheus_log_method(handler)
diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index 7359f23ad1..6920866be7 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -11,6 +11,7 @@
 import binascii
 import datetime
 import errno
+import functools
 import gettext
 import hashlib
 import hmac
@@ -251,9 +252,11 @@ 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)
         settings = dict(
             # basics
-            log_function=log_request,
+            log_function=log_function,
             base_url=base_url,
             default_url=default_url,
             template_path=template_path,

From 3e32ce576ca396c37d7f25cdb5575f377746cf0d Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Fri, 9 Oct 2020 15:26:01 -0500
Subject: [PATCH 05/12] Cleanup for log_json review

---
 notebook/log.py         | 3 ---
 notebook/notebookapp.py | 3 +--
 notebook/utils.py       | 4 ----
 3 files changed, 1 insertion(+), 9 deletions(-)

diff --git a/notebook/log.py b/notebook/log.py
index 46cd935857..027897f8ca 100644
--- a/notebook/log.py
+++ b/notebook/log.py
@@ -46,8 +46,5 @@ def log_request(handler, log=access_log):
     if status >= 500 and status != 502:
         # log all headers if it caused an error
         log_method(json.dumps(dict(request.headers), indent=2))
-    # if _enable_json_logs:
-    #     log_method(ns)
-    # else:
     log_method(msg.format(**ns))
     prometheus_log_method(handler)
diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index 6920866be7..2d0164d256 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -114,7 +114,6 @@
 from ._tz import utcnow, utcfromtimestamp
 from .utils import (
     check_pid,
-    enable_json_logs,
     pathname2url,
     run_sync,
     unix_socket_in_use,
@@ -720,7 +719,7 @@ class NotebookApp(JupyterApp):
     @default('log_json')
     def _default_log_json(self):
         """Get the log_json value from the environment."""
-        return enable_json_logs()
+        return os.getenv('JUPYTER_ENABLE_JSON_LOGGING', 'false').lower() == 'true'
 
     @validate('log_json')
     def _validate_log_json(self, proposal):
diff --git a/notebook/utils.py b/notebook/utils.py
index 5f3f70164e..1196d6d898 100644
--- a/notebook/utils.py
+++ b/notebook/utils.py
@@ -401,7 +401,3 @@ def unix_socket_in_use(socket_path):
         return True
     finally:
         sock.close()
-
-
-def enable_json_logs():
-    return os.getenv('JUPYTER_ENABLE_JSON_LOGGING', 'false').lower() == 'true'

From 47e06b013bc15ac5c8484f1437876c948e0f5b3f Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Fri, 9 Oct 2020 16:02:30 -0500
Subject: [PATCH 06/12] Log request properties separately when log_json=True

This updates the log_request method to get the request
properties logged separately if `log_json=True`. This
ends up looking like:

```
{"written_at": "2020-10-09T20:59:52.044Z", "written_ts": 1602277192044732000, "msg": "", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "WARNING", "module": "log", "line_no": 50, "status": 404, "method": "GET", "ip": "127.0.0.1", "uri": "/api/kernels/a6dd447b-282a-4e1c-ab65-eb340ad12965/channels?session_id=472907c27ed94e2cbfbae86501f7d159", "request_time": 8.63, "referer": "None"}
```
---
 notebook/log.py         | 11 +++++++----
 notebook/notebookapp.py |  3 ++-
 2 files changed, 9 insertions(+), 5 deletions(-)

diff --git a/notebook/log.py b/notebook/log.py
index 027897f8ca..2a80ba6623 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, log=access_log):
+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)
@@ -36,9 +36,9 @@ def log_request(handler, log=access_log):
         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')
@@ -46,5 +46,8 @@ def log_request(handler, log=access_log):
     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=ns))
+    else:
+        log_method(msg.format(**ns))
     prometheus_log_method(handler)
diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index 2d0164d256..b88334ca53 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -252,7 +252,8 @@ def init_settings(self, jupyter_app, kernel_manager, contents_manager,
             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_function = functools.partial(
+            log_request, log=log, log_json=jupyter_app.log_json)
         settings = dict(
             # basics
             log_function=log_function,

From 8b06db3eaeefe6a9b7fe0be8f1c92a1a5b3e08de Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Mon, 12 Oct 2020 11:54:38 -0500
Subject: [PATCH 07/12] Address review comments

---
 notebook/log.py         |  5 ++++-
 notebook/notebookapp.py | 14 +++-----------
 2 files changed, 7 insertions(+), 12 deletions(-)

diff --git a/notebook/log.py b/notebook/log.py
index 2a80ba6623..eb246bc400 100644
--- a/notebook/log.py
+++ b/notebook/log.py
@@ -45,7 +45,10 @@ def log_request(handler, log=access_log, log_json=False):
         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))
+        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:
diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index b88334ca53..65ce50bcf2 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -730,15 +730,14 @@ def _validate_log_json(self, proposal):
         if value:
             try:
                 import json_logging
+                self.log.info('initializing json logging')
+                json_logging.init_non_web(enable_json=True)
                 self._log_formatter_cls = json_logging.JSONLogFormatter
-                # Note that we don't need to trigger _log_format_changed here
-                # because init_logging will set the JSONLogFormatter on all
-                # of the registered loggers.
             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:
-                    logging.getLogger(__name__).exception(
+                    logging.getLogger(__name__).warning(
                         'Unable to use json logging due to missing packages. '
                         'Run "pip install notebook[json-logging]" to fix.'
                     )
@@ -1632,13 +1631,6 @@ def init_configurables(self):
         )
 
     def init_logging(self):
-        if self.log_json:
-            self.log.debug('initializing json logging')
-            # Note that we don't guard against ImportError here because if the
-            # package is missing then _validate_log_json should have set
-            # log_json=False.
-            import json_logging
-            json_logging.init_non_web(enable_json=True)
         # This prevents double log messages because tornado use a root logger that
         # self.log is a child of. The logging module dispatches log messages to a log
         # and all of its ancenstors until propagate is set to False.

From fac228567eeaf6b15b196b82c7f294ff682d464e Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Mon, 12 Oct 2020 11:59:13 -0500
Subject: [PATCH 08/12] Fix logging in _validate_log_json

Just use the app logger since that has the default LogFormatter
logging until we change it to JSON.
---
 notebook/notebookapp.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/notebook/notebookapp.py b/notebook/notebookapp.py
index 65ce50bcf2..50f1d374aa 100755
--- a/notebook/notebookapp.py
+++ b/notebook/notebookapp.py
@@ -730,14 +730,14 @@ def _validate_log_json(self, proposal):
         if value:
             try:
                 import json_logging
-                self.log.info('initializing 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:
-                    logging.getLogger(__name__).warning(
+                    self.log.warning(
                         'Unable to use json logging due to missing packages. '
                         'Run "pip install notebook[json-logging]" to fix.'
                     )

From 093aee290f26f31d6234e29775d5e03e55ca4c2e Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Mon, 12 Oct 2020 16:06:02 -0500
Subject: [PATCH 09/12] Add some basic tests for log_json config

Make sure the default value is handled properly based
on environment variables. Also checks the validation
code based on whether or not json_logging is imported.
---
 notebook/tests/test_notebookapp.py | 30 ++++++++++++++++++++++++++++++
 1 file changed, 30 insertions(+)

diff --git a/notebook/tests/test_notebookapp.py b/notebook/tests/test_notebookapp.py
index d8543feed9..7471459c13 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):
+        assert self.notebook.log_json == False
+
+    def test_validate_log_json(self):
+        assert self.notebook._validate_log_json(dict(value=False)) == False
+
 
 # UNIX sockets aren't available on Windows.
 if not sys.platform.startswith('win'):
@@ -201,3 +207,27 @@ 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):
+        assert self.notebook.log_json == self.json_logging_available
+
+    def test_validate_log_json(self):
+        assert self.notebook._validate_log_json(dict(value=True)) == self.json_logging_available

From 08f8ccd1f8be25bda83fc50a8cbd3ca07ab57d54 Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Mon, 12 Oct 2020 16:31:15 -0500
Subject: [PATCH 10/12] Add log_json=True test for log_request

Basic test just to make sure log_request handles log_json=True
properly.
---
 notebook/tests/test_log.py | 40 ++++++++++++++++++++++++++++++++++++++
 1 file changed, 40 insertions(+)
 create mode 100644 notebook/tests/test_log.py

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)

From 4ee4bb24f9c2bd3418c9d3b8a46fc2a26c515067 Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Mon, 12 Oct 2020 16:39:28 -0500
Subject: [PATCH 11/12] Use unittest assertion methods for improved logging

---
 notebook/tests/test_notebookapp.py | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/notebook/tests/test_notebookapp.py b/notebook/tests/test_notebookapp.py
index 7471459c13..0d773bfcbe 100644
--- a/notebook/tests/test_notebookapp.py
+++ b/notebook/tests/test_notebookapp.py
@@ -191,10 +191,10 @@ def test_list_running_servers(self):
         assert self.port in {info['port'] for info in servers}
 
     def test_log_json_default(self):
-        assert self.notebook.log_json == False
+        self.assertFalse(self.notebook.log_json)
 
     def test_validate_log_json(self):
-        assert self.notebook._validate_log_json(dict(value=False)) == False
+        self.assertFalse(self.notebook._validate_log_json(dict(value=False)))
 
 
 # UNIX sockets aren't available on Windows.
@@ -227,7 +227,9 @@ def get_patch_env(cls):
         return test_env
 
     def test_log_json_enabled(self):
-        assert self.notebook.log_json == self.json_logging_available
+        self.assertEqual(self.notebook.log_json, self.json_logging_available)
 
     def test_validate_log_json(self):
-        assert self.notebook._validate_log_json(dict(value=True)) == self.json_logging_available
+        self.assertEqual(
+            self.notebook._validate_log_json(dict(value=True)),
+            self.json_logging_available)

From 6a883e0a1c2a474e9cfea13c2e28f78fc591cb8e Mon Sep 17 00:00:00 2001
From: Matt Riedemann <mriedem@ibm.com>
Date: Tue, 13 Oct 2020 10:25:07 -0500
Subject: [PATCH 12/12] Fix NotebookAppJSONLoggingTests.test_log_json_enabled

The intent of the test is to make sure that log_json defaults
to True when JUPYTER_ENABLE_JSON_LOGGING is set to "true" so
this makes the test more explicit and to pass when json-logging
is not installed so that does not interfere due to validation.
---
 notebook/tests/test_notebookapp.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/notebook/tests/test_notebookapp.py b/notebook/tests/test_notebookapp.py
index 0d773bfcbe..2c42d4359f 100644
--- a/notebook/tests/test_notebookapp.py
+++ b/notebook/tests/test_notebookapp.py
@@ -227,7 +227,7 @@ def get_patch_env(cls):
         return test_env
 
     def test_log_json_enabled(self):
-        self.assertEqual(self.notebook.log_json, self.json_logging_available)
+        self.assertTrue(self.notebook._default_log_json())
 
     def test_validate_log_json(self):
         self.assertEqual(