search

NSLS-II / nslsii

NSLS-II related devices
BSD 3-Clause "New" or "Revised" License
10 stars 22 forks source link

Configure logging for bluesky and ophyd #80

Closed jklynch closed 4 years ago

jklynch commented 4 years ago

This PR configures bluesky and ophyd logging to use a single rotating log file.

danielballan commented 4 years ago

@jklynch You might consider incorporating this as well. Many beamlines have rolled their own solution for monitoring the execution of the startup scripts (even just add a print at the top of each file) but it looks like IPython has a built-in logger for this that we could use.

https://github.com/NSLS-II/nslsii/issues/74

danielballan commented 4 years ago

... but please feel free to leave that "out of scope" if you think it adds too much to this PR / gums up the wheels.

jklynch commented 4 years ago

I tried out the suggestion from #74 and I have some possible additions to the logging configuration in response.

I added configuration for get_ipython().log:

get_ipython().log.addHandler(log_file_handler)
get_ipython().log.setLevel("DEBUG")

and added a call to a "bluesky.ipython" logger in nslsii.common.ipynb.logutils.py which will send exception logs to the combined bluesky-ophyd-caproto log file.

Here is a demonstration that proposes one extra piece of ipython logging configuration to stifle all stack trace output to the console (keeping only the exception name). This is maybe extreme but it is the only easy way I have found to limit exception output to the ipython console. The user is directed by ipython to use %tb to see the full stack trace. In addition the user is directed to the bluesky log file for the stack trace. In practice the path to the bluesky log file would be displayed.

First the console output, then the log file. Note the [TerminalIPythonApp] messages are produced by ipython.

(nl) [vagrant@localhost ~]$ EPICS_CA_AUTO_ADDR_LIST=NO EPICS_CA_ADDR_LIST=127.0.0.1 ipython --profile=collection
Python 3.7.6 (default, Jan  8 2020, 19:59:22)
Type 'copyright', 'credits' or 'license' for more information
IPython 7.12.0 -- An enhanced Interactive Python. Type '?' for help.

IPython profile: collection
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/20-motors.py
**** The executable "caRepeater" couldn't be located
**** because of errno = "No such file or directory".
**** You may need to modify your PATH environment variable.
**** Unable to start "CA Repeater" process.
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/25-sclr.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/27-xspress3.py
warming up the hdf5 plugin...
done
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/30-fly_scans.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/89-usercallbacks.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/90-setup.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/91-userscans.py
[TerminalIPythonApp] Starting IPython's mainloop...

In [1]: def divide_by_zero():
   ...:     1/0
   ...:

In [2]: divide_by_zero()
An exception has occurred, use %tb to see the full traceback.

ZeroDivisionError: division by zero

see bluesky log file for full stack trace

In [3]: %tb
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
<ipython-input-2-3550c8d3434d> in <module>
----> 1 divide_by_zero()

<ipython-input-1-356ebaaa1290> in divide_by_zero()
      1 def divide_by_zero():
----> 2     1/0
      3

ZeroDivisionError: division by zero

Log file:

...
[I 2020-03-05 19:14:04,781.781 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/20-motors.py
[I 2020-03-05 19:14:04,785.785 ophyd  ophydobj:184] first instance of OphydObject: id=139806005198544
[I 2020-03-05 19:14:04,810.810 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/25-sclr.py
[I 2020-03-05 19:14:04,854.854 ophyd  signal:200] put(value=0.0, timestamp=1583424512.432418, force=True, metadata={'status': <AlarmStatus.NO_ALARM: 0>, 'severity': <AlarmSeverity.NO_ALARM: 0>})
[I 2020-03-05 19:14:04,880.880 ophyd  signal:200] put(value=0.0, timestamp=1583424512.432718, force=True, metadata={'status': <AlarmStatus.NO_ALARM: 0>, 'severity': <AlarmSeverity.NO_ALARM: 0>})
...
[I 2020-03-05 19:14:06,604.604 ophyd.control_layer  signal:989] pv[XF:08BM-ES:1{Sclr:1}scaler1.NM19].get_with_metadata(...) returned
[I 2020-03-05 19:14:06,604.604 ophyd.control_layer  signal:986] pv[XF:08BM-ES:1{Sclr:1}scaler1.NM20].get_with_metadata(as_string=False, form=time, timeout=2.0)
[I 2020-03-05 19:14:06,604.604 ophyd.control_layer  signal:989] pv[XF:08BM-ES:1{Sclr:1}scaler1.NM20].get_with_metadata(...) returned
[I 2020-03-05 19:14:06,605.605 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/27-xspress3.py
[I 2020-03-05 19:14:06,742.742 ophyd  signal:200] put(value=0.0, timestamp=1583424514.447158, force=True, metadata={'status': <AlarmStatus.NO_ALARM: 0>, 'severity': <AlarmSeverity.NO_ALARM: 0>, 'precision': 0, 'units': ''})
[I 2020-03-05 19:14:06,747.747 ophyd  signal:200] put(value=0.0, timestamp=1583424514.447158, force=True, metadata={'status': <AlarmStatus.NO_ALARM: 0>, 'severity': <AlarmSeverity.NO_ALARM: 0>, 'precision': 0, 'units': ''})
...
[I 2020-03-05 19:14:12,213.213 ophyd.control_layer  signal:986] pv[XF:08BM-ES{Xsp:1}:ArrayCallbacks_RBV].get_with_metadata(as_string=False, form=time, timeout=2.0)
[I 2020-03-05 19:14:12,213.213 ophyd.control_layer  signal:989] pv[XF:08BM-ES{Xsp:1}:ArrayCallbacks_RBV].get_with_metadata(...) returned
[I 2020-03-05 19:14:12,214.214 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/30-fly_scans.py
[I 2020-03-05 19:14:12,218.218 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/89-usercallbacks.py
[I 2020-03-05 19:14:12,220.220 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/90-setup.py
[I 2020-03-05 19:14:12,222.222 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/91-userscans.py
[E 2020-03-05 19:14:19,180.180 bluesky.ipython  logutils:35] division by zero
Traceback (most recent call last):
  File "/home/vagrant/miniconda3/envs/nl/lib/python3.7/site-packages/IPython/core/interactiveshell.py", line 3331, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-2-3550c8d3434d>", line 1, in <module>
    divide_by_zero()
  File "<ipython-input-1-356ebaaa1290>", line 2, in divide_by_zero
    1/0
ZeroDivisionError: division by zero
codecov-io commented 4 years ago

Codecov Report

Merging #80 into master will increase coverage by 4.01%. The diff coverage is 64.51%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master      #80      +/-   ##
==========================================
+ Coverage   52.34%   56.36%   +4.01%     
==========================================
  Files          13       13              
  Lines         724      809      +85     
==========================================
+ Hits          379      456      +77     
- Misses        345      353       +8
Impacted Files Coverage Δ
nslsii/__init__.py 24.71% <45.56%> (+17.94%) :arrow_up:
nslsii/common/ipynb/logutils.py 92.85% <85.71%> (-7.15%) :arrow_down:
nslsii/tests/test_logutils.py 100.00% <100.00%> (ø)

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 ee11542...49377b8. Read the comment docs.

jklynch commented 4 years ago

Here is a demonstration of the state of logging configuration focusing on exception reporting. In short the ipython console will report only exception names but directs the user to "%tb verbose" and the bluesky log file for a full traceback. Also ipython console logging is on by default.

(nl) [vagrant@localhost ~]$ EPICS_CA_AUTO_ADDR_LIST=NO EPICS_CA_ADDR_LIST=127.0.0.1 ipython --profile=collection
Python 3.7.6 (default, Jan  8 2020, 19:59:22)
Type 'copyright', 'credits' or 'license' for more information
IPython 7.12.0 -- An enhanced Interactive Python. Type '?' for help.

IPython profile: collection
Activating auto-logging. Current session state plus future input saved.
Filename       : bluesky_ipython.log
Mode           : rotate
Output logging : True
Raw input log  : False
Timestamping   : True
State          : active
Exception reporting mode: Minimal
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/20-motors.py
**** The executable "caRepeater" couldn't be located
**** because of errno = "No such file or directory".
**** You may need to modify your PATH environment variable.
**** Unable to start "CA Repeater" process.
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/25-sclr.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/27-xspress3.py
warming up the hdf5 plugin...
done
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/30-fly_scans.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/89-usercallbacks.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/90-setup.py
[TerminalIPythonApp] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/91-userscans.py
[TerminalIPythonApp] Starting IPython's mainloop...

In [1]: def divide_by_zero():
   ...:     1/0
   ...:

In [2]: divide_by_zero()
An exception has occurred, use '%tb verbose' to see the full traceback.
ZeroDivisionError: division by zero

See /var/log/bluesky/bluesky.log for the full traceback.

In [3]: %tb verbose
---------------------------------------------------------------------------
ZeroDivisionError                         Traceback (most recent call last)
<ipython-input-2-3550c8d3434d> in <module>
----> 1 divide_by_zero()
        global divide_by_zero = <function divide_by_zero at 0x7f61fd037a70>

<ipython-input-1-356ebaaa1290> in divide_by_zero()
      1 def divide_by_zero():
----> 2     1/0
      3

ZeroDivisionError: division by zero

The ipython log looks like this:

# IPython log file

# Thu, 05 Mar 2020 20:53:07
def divide_by_zero():
    1/0

# Thu, 05 Mar 2020 20:53:13
divide_by_zero()
#[Out]# Traceback (most recent call last):
#[Out]#   File "/home/vagrant/miniconda3/envs/nl/lib/python3.7/site-packages/IPython/core/interactiveshell.py", line 3331, in run_code
#[Out]#     exec(code_obj, self.user_global_ns, self.user_ns)
#[Out]#   File "<ipython-input-2-3550c8d3434d>", line 1, in <module>
#[Out]#     divide_by_zero()
#[Out]#   File "<ipython-input-1-356ebaaa1290>", line 2, in divide_by_zero
#[Out]#     1/0
#[Out]# ZeroDivisionError: division by zero
# Thu, 05 Mar 2020 20:53:21
get_ipython().run_line_magic('tb', 'verbose')
# Thu, 05 Mar 2020 20:55:28
get_ipython().run_line_magic('less', 'bluesky_ipython.log')

/var/logs/bluesky/bluesky.log looks like this:

...
[I 2020-03-05 20:52:57,135.135 ophyd.control_layer  signal:1571] _write_pv.put(value=0.0, use_complete=False, callback=None, kwargs={})
[I 2020-03-05 20:52:57,136.136 ophyd.control_layer  signal:986] pv[XF:08BM-ES{Xsp:1}:ArrayCallbacks_RBV].get_with_metadata(as_string=False, form=time, timeout=2.0)
[I 2020-03-05 20:52:57,137.137 ophyd.control_layer  signal:989] pv[XF:08BM-ES{Xsp:1}:ArrayCallbacks_RBV].get_with_metadata(...) returned
[I 2020-03-05 20:52:57,138.138 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/30-fly_scans.py
[I 2020-03-05 20:52:57,142.142 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/89-usercallbacks.py
[I 2020-03-05 20:52:57,144.144 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/90-setup.py
[I 2020-03-05 20:52:57,145.145 TerminalIPythonApp  shellapp:327] Running file in user namespace: /home/vagrant/.ipython/profile_collection/startup/91-userscans.py
[E 2020-03-05 20:53:13,284.284 nslsii.ipython  logutils:53] division by zero
Traceback (most recent call last):
  File "/home/vagrant/miniconda3/envs/nl/lib/python3.7/site-packages/IPython/core/interactiveshell.py", line 3331, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-2-3550c8d3434d>", line 1, in <module>
    divide_by_zero()
  File "<ipython-input-1-356ebaaa1290>", line 2, in divide_by_zero
    1/0
ZeroDivisionError: division by zero
jklynch commented 4 years ago

The flake8 max-line-length was set in .travis.yml to a stingy 79 characters. I have moved that parameter from .travis.yml to .flake8 and increased it to 100 characters, for which I ask forgiveness.