Fix logger when using outside POCS

[wtgee]

If loading one of the classes that uses PanBase outside of POCS (as in with jupyter-console) the logger will complain about the custom fileline that we have added.

Traceback (most recent call last):
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/logging/__init__.py", line 578, in format
    s = self.formatMessage(record)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/logging/__init__.py", line 547, in formatMessage
    return self._style.format(record)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/logging/__init__.py", line 399, in format
    return self._fmt.format(**record.__dict__)
KeyError: 'fileline'
Call stack:
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/ipykernel_launcher.py", line 16, in <module>
    app.launch_new_instance()
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 434, in complete_request
    matches = self.do_complete(code, cursor_pos)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 257, in do_complete
    txt, matches = self.shell.complete('', line, line_cursor)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 1996, in complete
    return self.Completer.complete(text, line, cursor_pos)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/IPython/core/completer.py", line 1925, in complete
    return self._complete(line_buffer=line_buffer, cursor_pos=cursor_pos, text=text, cursor_line=0)[:2]
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/IPython/core/completer.py", line 1998, in _complete
    cursor_pos, cursor_line, full_text)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/IPython/core/completer.py", line 1369, in _jedi_matches
    return filter(completion_filter, interpreter.completions())
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/jedi/api/__init__.py", line 154, in completions
    self._evaluator, self._get_module(), self._code_lines,
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/jedi/api/__init__.py", line 390, in _get_module
    parser_module = super(Interpreter, self)._get_module_node()
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/jedi/cache.py", line 121, in wrapper
    result = method(self, *args, **kwargs)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/jedi/api/__init__.py", line 125, in _get_module_node
    cache_path=settings.cache_directory
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/parso/grammar.py", line 77, in parse
    return self._parse(code=code, **kwargs)
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/parso/grammar.py", line 130, in _parse
    new_lines=lines
  File "/home/wtgee/anaconda3/envs/panoptes-env/lib/python3.6/site-packages/parso/python/diff.py", line 164, in update
    logging.debug('diff parser end')
Message: 'diff parser end'

[jamessynge]

I don't quite get the cause of this issue. If you have a couple of minutes, can you explain?

[wtgee]

I'm not entirely sure, but I think it is when you load another module that use logging first and then load up one of our loggers that has the custom parser. I will try to recreate reliably and get more info. I just wanted to make sure to get the Issue filed while I was trying to fix something else.

[jeremylan]

Hi @wtgee @jamessynge

I was having a look at this issue as the logging error kinda annoyed me.
The error is caused by this line in ${POCS}/conf_files/log.yaml:

format: '{levelname:.1s}{asctime}.{msecs:03.0f} {fileline:20s} {message}'

The argument fileline is a custom filter defined in ${POCS}/pocs/utils/logger.py.
This filter gets added to the logger, but I suspect it does not apply to all loggers hence the error reported.

This can be reproduced every time a social sink function is called.

I saw a similar issue reported here:

https://stackoverflow.com/questions/6850798/why-doesnt-filter-attached-to-the-root-logger-propagate-to-descendant-loggers

I think maybe the easiest fix would be to use filename and lineno directly in the logger config file? This works:

format: '{levelname:.1s}{asctime}.{msecs:03.0f} {filename:15s} {lineno} {message}'

even though it is no longer a fixed 20 character.

[wtgee]

Hi @jeremylan, thanks for looking into this! Oddly enough it just started coming up for me with some of the work I am doing in some jupyter notebooks where it is also a particularly annoying issue. Part of the problem is that is has been hard to replicate so I'm glad to hear you can do that with the new social features.

Off the top of my head I can't remember why we are using the filter versus just using the solution you proposed, but I want to say there is a good reason besides just the fixed character length. I'll try to dig back through some emails to see what that reason is but if I can't find it then let's put in your fix above.

Also, thanks for the link to the similar issue. It definitely seems to be an issue of which module loads logging first. Hopefully with the reproducibility we can easily figure it out.

[wtgee]

Closed by #678