The python logging module no longer seems to work properly inside a notebook

[tudorprodan]

When running the example from the python logging documentation page in a jupyter notebook, the messages go to the notebook console as opposed to the notebook's webpage output via the capture mechanism. Just create an empty notebook, run the example below, you'll see what I mean.

import logging
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.debug('This message should appear on the console')
logging.info('So should this')
logging.warning('And this, too')

The logging module by default creates a StreamHandler object which will if not stream: stream = sys.stderr. A lot of modules use the logging module as in the example.

The problem is that the notebook actually inits the logging module before the output capture mechanism is set, so the default created StreamHandler actually has a reference to the original sys.stdout, before the notebook replaces it with it's own ipykernel.iostream.OutStream.

Shouldn't the notebook reset the logging module?

I've been looking into this because after an upgrade I noticed missing output from some stuff I was running often.

[takluyver]

We use logging in the kernel itself as well, and that shouldn't be redirected into the notebook. I was assuming that we set up a handler on the root logger, but looking at it, we seem to be correctly setting it on the application logger. So it should still be possible to handle other logs separately. I'm not sure what the root issue is here.

[tudorprodan]

The root issue is that the example code doesn't run as expected in the notebook.
Other modules use code like the example above and hence don't run as expected in the notebook.

To reproduce the issue, run the above sample code inside of a notebook.
Expected behaviour: You see the messages in the notebook.
Actual behaviour: You don't see the messages in the notebook.

Maybe when the notebook starts capturing output it should swap the default logging StreamHandler with one that points to the ipykernel.iostream.OutStream?

[tudorprodan]

@takluyver Oh I see what you mean, the code in traitlets.config.application._log_default does seem to only set that StreamHandler to the class' logger, and not to the root logger. But when in the notebook:

import logging
root_logger = logging.getLogger()
print 'root_logger =', root_logger
print 'handlers:', root_logger.handlers
handler = root_logger.handlers[0]
print 'handler stream:', handler.stream

import sys
print 'sys.stderr:', sys.stderr

root_logger = <logging.RootLogger object at 0x7fb847a50490>
handlers: [<logging.StreamHandler object at 0x146a2d0>]
handler stream: <open file '<stderr>', mode 'w' at 0x7fb847bae270>
sys.stderr: <ipykernel.iostream.OutStream object at 0x15ea290>

[takluyver]

Right, I don't know what's creating the root handler, though.

[tudorprodan]

Turns out I was looking at the wrong thing. I put a traceback in the logger constructor, and did see jupyter creating a logger via the traitletscode. But I missed the fact that I had another logger being created, which was actually the root logger.

The root logger is actually created by tornado, here:

>>>>>>>>>>>>>>>>>>   addHandler <logging.RootLogger object at 0x7ff897b8d490> <<<<<<<<<<<<<<<<<<<<<<
  File "/usr/lib64/python2.7/threading.py", line 524, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib64/python2.7/threading.py", line 551, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 504, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/site-packages/ipykernel/iostream.py", line 60, in _thread_main
    self.io_loop.start()
  File "/usr/lib64/python2.7/site-packages/zmq/eventloop/ioloop.py", line 162, in start
    super(ZMQIOLoop, self).start()
  File "/usr/lib64/python2.7/site-packages/tornado/ioloop.py", line 749, in start
    self._setup_logging()
  File "/usr/lib64/python2.7/site-packages/tornado/ioloop.py", line 374, in _setup_logging
    logging.basicConfig()
  File "/usr/lib64/python2.7/logging/__init__.py", line 1531, in basicConfig
    root.addHandler(hdlr)

The actual method does this:

    def _setup_logging(self):
        if not any([logging.getLogger().handlers,
                    logging.getLogger('tornado').handlers,
                    logging.getLogger('tornado.application').handlers]):
            logging.basicConfig()

https://github.com/tornadoweb/tornado/blob/stable/tornado/ioloop.py#L360

So if jupyter were to set up the root logger in each subprocess before tornado picks this up, everything would be fine. @takluyver what do you think?

[tudorprodan]

As far as I can tell, jupyter spawns a subprocess for each open notebook. This subprocess then spawns a thread for tornado.
Is my understanding correct?

If so, then all we have to do is configure the root logger with the proper captured sys.stderr and all will be well.

[takluyver]

Each notebook is talking to a separate kernel process that runs your code. The tornado event loop is running in the main thread of that to handle messages (this is separate to the tornado webserver that runs the notebook application).

I think probably the way to go is to configure a handler for the 'tornado' logger, and leave the root handler unconfigured.

[tudorprodan]

@takluyver Yes, but this is not the notebook server's tornado that sets up the logger.
The subprocess uses ZeroMQ which fires up a tornado IO loop inside the subprocess.
This suprocess IO loop is the one that eagerly configures the root logger.

[tudorprodan]

So there's the IPKernelApp.initialize method here:
https://github.com/ipython/ipykernel/blob/master/ipykernel/kernelapp.py#L405

This method calls, in this order:

• init_blackhole(self) - might set sys.stdout/stderr to /dev/null according to some settings
• init_sockets(self) - eventually sets up the IO loop
• init_io(self) - sets sys.stdout/stderr to the captured streams

The easy fix would be to just move the call to init_io before init_sockets, but I'm not sure what exactly init_blackhole is preventing. Maybe those other calls spit out a lot of undesirable output?

[minrk]

init_io must be called after init_sockets because it requires the sockets to have been created.

[takluyver]

I think we just need to set up a handler for the 'tornado' logger before starting the event loop. Then, from the code you posted above, tornado will detect that and not call basicConfig().

[tudorprodan]

@minrk Good point
@takluyver Yes, that does seem to be the best solution.

The ZMQ IOLoop (which creates the tornado IO loop) is created here:
https://github.com/ipython/ipykernel/blob/master/ipykernel/iostream.py#L53

Would that also be the right place to call some new _setup_tornado_logger method?

Then _setup_tornado_logger could init the tornado logger to stderr or similar.

[takluyver]

I think setting up logging handlers is an application-level concern, so it should be done on the kernel application class - we just need to ensure it happens early enough.