@sdague@rmoe Here is an idea for a start on JSON log formatting though it might not be super useful if we can't split apart the request-specific parts of themsg field.

This is the error I get when trying to useJSONLogWebFormatter:

--- Logging error ---Traceback (most recent call last):  File "/usr/lib/python3.6/logging/__init__.py", line 994, in emit    msg = self.format(record)  File "/usr/lib/python3.6/logging/__init__.py", line 840, in format    return fmt.format(record)  File "/home/osboxes/jupyter/notebook/.tox/lib/python3.6/site-packages/json_logging/__init__.py", line 243, in format    log_object = self._format_log_object(record, request_util=_request_util)  File "/home/osboxes/jupyter/notebook/.tox/lib/python3.6/site-packages/json_logging/__init__.py", line 341, in _format_log_object    "correlation_id": request_util.get_correlation_id(within_formatter=True),AttributeError: 'NoneType' object has no attribute 'get_correlation_id'

And it looks like that's because I'm not going through one of theinit_* framework methods:

https://github.com/bobbui/json-logging-python/blob/1.2.8/json_logging/__init__.py#L132

Getting a little further by changing thelog_request method so I see something like this now:

{"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}

But themsg is a serialized JSON string now.

Thanks Matt. This is an interesting conundrum on a couple counts.

1. The logging formatter is something used very early - introducing potential chicken/egg situations.
2. The tornado logging is a different facility, yet ideally, we want to leverage the same configurable setting to determine if JSON formatting should be used.

I think these can be resolved in a more application-friendly manner by first introducing a boolean configurablejson_logging that can be configured via a configuration file usingc.NotebookApp.json_logging = True. We'd also want to tie this to a CLI flag (e.g.,--json-logging such that, when present, it enables JSON formatting). You should be able to follow the example ofallow_root for these two details.

Traitlets also provide the ability tovalidate a config option. This is where we could see if thejson_logging package can be imported and, if so, "tickle" the current log_format value after setting the log_formatter_cls. The reason for this "tickle" is to trigger theobservation that takes place in the traitletsApplication class - which will perform a reset using the formatter_cls value - as you had mentioned. Modeling the validation after the 'ip' traitlet can get you started here.

We could let the default value for thejson-logging flag still derive from the env - which is helpful in containerized envs and this could be done via a _default_json_logging() entry that returns configurable's default. Again, 'ip' uses a defaulting method that you can model this after.

I apologize for these details, but because there were so many unknowns I had, it was quicker just to try things out. I have some working code - but I'd rather help you navigate this if you don't mind. Otherwise, just let me know.

@kevin-bates thanks for those detailed pointers.

I'd rather help you navigate this if you don't mind

Yup, no problem and I definitely appreciate the patience with helping me learn here (I don't really have experience with tornado or traitlets, mostly copy/tweak/test when I need to make changes).

@kevin-bates I worked on your suggestions a bit this morning and captured the diffhere since it's not working. A few notes:

• I added the config option but with namelog_format_json so that it would show up alongsidelog_format andlog_datefmt etc in the help output:

--NotebookApp.log_datefmt=<Unicode>    Default: '%Y-%m-%d %H:%M:%S'    The date format used by logging formatters for %(asctime)s--NotebookApp.log_format=<Unicode>    Default: '[%(name)s]%(highlevel)s %(message)s'    The Logging format template--NotebookApp.log_format_json=<Bool>    Default: False    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 ENABLE_JSON_LOGGING=true.--NotebookApp.log_level=<Enum>    Default: 30    Choices: (0, 10, 20, 30, 40, 50, 'DEBUG', 'INFO', 'WARN', 'ERROR', 'CRITICAL')    Set the log level by value or name.

I think that's useful for someone looking at logging options to have those grouped together for context.

• I'm assuming I didn't implement_validate_log_format_json correctly because it doesn't seem to be getting hit. I've tried running with bothENABLE_JSON_LOGGING=true jupyter notebook andjupyter notebook --NotebookApp.log_format_json=True. I never see the logging statements I put in_validate_log_format_json though, nor do I see the ImportError traceback if I uninstalljson-logging and try to start the server withlog_format_json=True. Is there something I'm missing there about when that validation function is supposed to be called?

• I'm also not sure that I'm "tickling" thelog_format option correctly by doingself.log_format = self.log_format.

Thanks again for the help.

Thanks Matt. The "tickle" should actually change the format. In this case, I removed the color-coding attributes. Here's the code I had put together the other day. Since you've changed the traitlet's name, that change would need to be reflected, as well as perhaps logging that the import failed during the validation.

Lastly, the convention for envs is that they be prefixed withJUPYTER_.

I found no changes necessary other than in notebookapp.py, but would prefer that you confirm the same.

json_logging=Bool(config=True)@default('json_logging')def_default_json_logging(self):returnos.getenv('JUPYTER_ENABLE_JSON_LOGGING','false').lower()=='true'@validate('json_logging')def_validate_json_logging(self,proposal):value=proposal['value']ifvalueisTrue:try:importjson_loggingself._log_formatter_cls=json_logging.JSONLogFormatterself.log_format=u"[%(levelname)1.1s %(asctime)s.%(msecs).03d %(name)s] %(message)s"exceptImportError:value=Falsereturnvalue

My concern with the change tolog_format_json is that it implies the value should be some kind of format string - similar tolog_format, whereasjson_logging seems more about thekind of logging that will take place. The concern being that the "format" approach could be confusing. Yes, I would agree whatever the name is should be grouped near the others as its all the same "topic".

The "tickle" should actually change the format. In this case, I removed the color-coding attributes.

Got it. I'm not totally sure about that solution since if I setlog_format specifically and this changed it, I'd probably wonder what's going on if the formatting doesn't show up as expected. If there is no better solution we could at least document something about that in the config help.

the convention for envs is that they be prefixed with JUPYTER_.

Done.

I found no changes necessary other than in notebookapp.py

I see a bug in my code, I wasn't usingself._log_formatter_cls.

My concern with the change to log_format_json is that it implies the value should be some kind of format string

I renamed the config option to simplylog_json to take the "format" out of it.

I'll tinker with this locally and see what I come up with.

I'm also going to see what happens if we calljson_logging.init_non_web(enable_json=True) frominit_logging sinceinit_non_web does change the formatter forall of the loggers:

https://github.com/bobbui/json-logging-python/blob/1.2.8/json_logging/__init__.py#L153

I'm also going to see what happens if we call json_logging.init_non_web(enable_json=True) from init_logging since init_non_web does change the formatter for all of the loggers

This works and avoids the need to changelog_format to trigger the_log_format_changed observer. Updated the PR.

Still need to figure out how to getlog.log_request working properly because if you run without the environment variable set it doesn't log the request parameters in json format:

{"written_at": "2020-10-09T19:32:51.825Z", "written_ts": 1602271971825341000, "msg": "404 GET /nbextensions/widgets/notebook/js/extension.js (127.0.0.1) 8.94ms referer=http://localhost:8888/notebooks/Untitled.ipynb", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "WARNING", "module": "log", "line_no": 59}

and if you do it logs the request parameters as a serialized json string:

{"written_at": "2020-10-09T19:34:05.565Z", "written_ts": 1602272045565346000, "msg": "{'status': 404, 'method': 'GET', 'ip': '127.0.0.1', 'uri': '/api/kernels/48ecd2e7-ae9d-4484-8910-70fb46d72491/channels?session_id=5aa3a7dcedf1427e8ff41ae0cb3dae94', 'request_time': 1.8270015716552734, 'referer': 'None'}", "type": "log", "logger": "NotebookApp", "thread": "MainThread", "level": "WARNING", "module": "log", "line_no": 57}

I'd like to add tests for this but I'm not sure if there is a great way to test it. Maybe something like start the notebook app server with the env var set and verify the logged message can be serialized and then deserialized JSON? Though that would also mean havingjson-logging installed to run tests.

Hi Matt - would you mind merging with the latest master and pushing that commit? Your changes with legitimate test failures coincided with a general build issue and I'd like to have this PR be 'green' prior to its merge into master. Sorry for the inconvenience.

Looks good - thank you Matt.

Thanks for all of your help Kevin.

@kevin-bates quick question, do you have any idea of a timeline for the next planned release? Looking at recent releases it looks like you've been doing monthly releases which is cool. My team would like to avoid pulling this change in via a git hash so if there is a release planned on the horizon we'll wait, just wondering.

Would getting a release out in the next couple of weeks be sufficient - say last week of October/first week of November? Although convenient, I'd rather not set a fixed cadence unless there are other maintainers that can assist.

Would getting a release out in the next couple of weeks be sufficient - say last week of October/first week of November?

Yup, that would be great.