Add logging

[kinow]

Closes #67

Uses the Python logging module. The configuration is kept in an INI file, natively supported. By default there is a logging_config.ini with the logging configuration, instead of initializing in the Python code.

This way, in argparse we use a FileType parameter that defaults to the module's own logging_config.ini, but the user should be able to customize the logging via --logging-config /opt/test/logging.ini or any other location. The parameter is defined in:

    parser.add_argument('--logging-config', type=argparse.FileType('r'),
                        help='path to logging configuration file',
                        action="store", dest="logging_config",
                        default=join(here, 'logging_config.ini'))

We have a default handler outputting to the console, with the common formatter. And loggers for:

• tornado.access set to WARN level
• tornado.application set to WARN level
• cylc.flow set to DEBUG level
• cylc.uiserver set to DEBUG level

Python code uses the logging module by creating loggers with __name__, so we can control the logging down to the level of a single file. For example, here's the output after this PR (before it was blank):

$ cylc-uiserver -s /home/kinow/Development/python/workspace/cylc-ui/dist/ -p 9999
2019-09-09 14:07:03,134 cylc.uiserver.main INFO     JupyterHub Service Prefix: /
2019-09-09 14:07:03,134 cylc.uiserver.main INFO     Listening on 9999 and serving static content from /home/kinow/Development/python/workspace/cylc-ui/dist/
2019-09-09 14:07:03,134 cylc.uiserver.main INFO     Starting Cylc UI
2019-09-09 14:07:03,134 cylc.uiserver.main INFO     /home/kinow/Development/python/workspace/cylc-ui/dist/
^C2019-09-09 14:07:06,887 cylc.uiserver.main INFO     exiting...
2019-09-09 14:07:06,939 cylc.uiserver.main INFO     exit success

We could make any log entry from main.py to be ignored, unless it is a WARN (or higher like ERROR etc)

diff --git a/cylc/uiserver/logging_config.ini b/cylc/uiserver/logging_config.ini
index 8704a32..0c000fb 100644
--- a/cylc/uiserver/logging_config.ini
+++ b/cylc/uiserver/logging_config.ini
@@ -5,7 +5,7 @@ keys=basic
 keys=console
 
 [loggers]
-keys=root, tornado_access, tornado_application, cylc_flow, cylc_uiserver
+keys=root, tornado_access, tornado_application, cylc_flow, cylc_uiserver, cylc_uiserver_main
 
 # Formatters
 [formatter_basic]
@@ -45,3 +45,9 @@ level=DEBUG
 handlers=console
 propagate=0
 qualname=cylc.uiserver
+
+[logger_cylc_uiserver_main]
+level=WARN
+handlers=console
+propagate=0
+qualname=cylc.uiserver.main

The Python logging module respects the hierarchy, so in main.py, creating a logger with __name__, means that it will use the qualified name cylc.uiserver.main, which will match the newly created logger from the example above.

Cheers
Bruno

[codecov-io]

Codecov Report

Merging #73 into master will increase coverage by 0.75%.
The diff coverage is 50%.

@@            Coverage Diff             @@
##           master      #73      +/-   ##
==========================================
+ Coverage   44.56%   45.32%   +0.75%     
==========================================
  Files           6        6              
  Lines         267      278      +11     
  Branches       42       42              
==========================================
+ Hits          119      126       +7     
- Misses        147      151       +4     
  Partials        1        1

Impacted Files	Coverage Δ
cylc/uiserver/data_mgr.py	34.14% <33.33%> (+1.71%)	⬆️
cylc/uiserver/workflows_mgr.py	25% <40%> (+0.3%)	⬆️
cylc/uiserver/main.py	69.23% <71.42%> (+2.56%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6440805...03e3a22. Read the comment docs.

[kinow]

And an example of what happens when we have the default configuration, and something goes wrong in the Tornado application (e.g. invalid request, without the OAuth information):

$ cylc-uiserver -s /home/kinow/Development/python/workspace/cylc-ui/dist/ -p 9999
2019-09-09 14:25:53,136 cylc.uiserver.main INFO     JupyterHub Service Prefix: /
2019-09-09 14:25:53,137 cylc.uiserver.main INFO     Listening on 9999 and serving static content from /home/kinow/Development/python/workspace/cylc-ui/dist/
2019-09-09 14:25:53,137 cylc.uiserver.main INFO     Starting Cylc UI
2019-09-09 14:25:53,137 cylc.uiserver.main INFO     /home/kinow/Development/python/workspace/cylc-ui/dist/
2019-09-09 14:25:58,799 tornado.application ERROR    Uncaught exception GET / (127.0.0.1)
HTTPServerRequest(protocol='http', host='localhost:9999', method='GET', uri='/', version='HTTP/1.1', remote_ip='127.0.0.1')
Traceback (most recent call last):
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/traitlets/traitlets.py", line 528, in get
    value = obj._trait_values[self.name]
KeyError: 'oauth_client_id'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/tornado/web.py", line 1697, in _execute
    result = method(*self.path_args, **self.path_kwargs)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/tornado/web.py", line 1908, in wrapper
    return method(self, *args, **kwargs)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/tornado/web.py", line 3160, in wrapper
    if not self.current_user:
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/tornado/web.py", line 1337, in current_user
    self._current_user = self.get_current_user()
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/jupyterhub/services/auth.py", line 894, in get_current_user
    user_model = self.hub_auth.get_user(self)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/jupyterhub/services/auth.py", line 496, in get_user
    user_model = self._get_user_cookie(handler)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/jupyterhub/services/auth.py", line 542, in _get_user_cookie
    token = handler.get_secure_cookie(self.cookie_name)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/jupyterhub/services/auth.py", line 531, in cookie_name
    return self.oauth_client_id
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/traitlets/traitlets.py", line 556, in __get__
    return self.get(obj, cls)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/traitlets/traitlets.py", line 535, in get
    value = self._validate(obj, dynamic_default())
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/traitlets/traitlets.py", line 593, in _validate
    value = self._cross_validate(obj, value)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/traitlets/traitlets.py", line 599, in _cross_validate
    value = obj._trait_validators[self.name](obj, proposal)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/traitlets/traitlets.py", line 907, in __call__
    return self.func(*args, **kwargs)
  File "/home/kinow/Development/python/workspace/cylc-uiserver/venv/lib/python3.7/site-packages/jupyterhub/services/auth.py", line 568, in _ensure_not_empty
    raise ValueError("%s cannot be empty." % proposal.trait.name)
ValueError: oauth_client_id cannot be empty.
2019-09-09 14:25:58,804 tornado.access ERROR    500 GET / (127.0.0.1) 7.86ms
2019-09-09 14:25:58,922 tornado.access WARNING  404 GET /favicon.ico (127.0.0.1) 1.11ms

At the moment the stack trace is printed only in the browser (which I learned how to fix while working on this issue, so will send another PR for #71). After this PR, the exception is logged to the console, because we have a logger in the default file for tornado.application, and because it is higher or equal than WARN.

[matthewrmshin]

Some quick comments.

[matthewrmshin]

Note discussion at cylc/cylc-flow#2505.

[matthewrmshin]

Looks good. I'll do some local testing.

[matthewrmshin]

Just noticed that the jupyterhub command also has a --log-level=<Enum> option. I wonder if we can make use of that when we have the hub spawning the UIS.

[dwsutherland]

@kinow - Conflicts with newly merged #70 I think...

[kinow]

Thanks @dwsutherland , conflicts solved.

[dwsutherland]

I can see errors being logged now.. Like Client errors after stopping the suite, then the data manager asking for data:

2019-09-12 08:52:47,496 cylc.uiserver.data_mgr ERROR    Suite "noz" already stopped
Traceback (most recent call last):
  File "/home/sutherlander/repos/kinow/cylc-uiserver/cylc/uiserver/data_mgr.py", line 36, in get_workflow_data
    pb_msg = await client.async_request(method)
  File "/home/sutherlander/.envs/kinow-uis/lib/python3.7/site-packages/cylc/flow/network/client.py", line 149, in async_request
    self.timeout_handler()
  File "/home/sutherlander/.envs/kinow-uis/lib/python3.7/site-packages/cylc/flow/network/client.py", line 310, in _timeout_handler
    raise ClientError('Suite "%s" already stopped' % suite)
cylc.flow.exceptions.ClientError: Suite "noz" already stopped

We may have to revisit this, as it's expected behaviour... but LGTM!

[kinow]

Brilliant! We can change the error log to debug or something if that's better, but much quicker to work on this in another issue, you are right. Thanks!!