Merge pull request #28 from slaclab/add_logging

Add logging to library and to some scripts to show example usage

README.md

@@ -29,9 +29,9 @@ If neither of the above are set, the suite will try to use _suiteConfig.py_. If
 ```
 _(documentation on the library functionality is still to come, but example usage is seen in the /suite_scripts folder)_
 
-* /suite_scripts: scripts that use the calibrationSuite library code
+* /suite_scripts: scripts that use the calibrationSuite library code ('high-level scripts')
 
-* /standalone_scripts: scripts that do not use the calibrationSuite library code
+* /standalone_scripts: scripts that do not use the calibrationSuite library code ('high-level scripts')
 
 * /tests: tests files, can be ran with 'pytest .' from the root project directory 
 _(Currently only test for the fitFunctions library file is running, more tests are to be added)_
@@ -49,4 +49,46 @@ main branch tag v1.0.0 are the scripts used for the 2/17/24 beamtime
 
 If you are new to git/github, start here: [https://confluence.slac.stanford.edu/pages/viewpage.action?pageId=428802060](https://confluence.slac.stanford.edu/pages/viewpage.action?pageId=428802060)
 
-Then read the following for an overview of the development process: [https://confluence.slac.stanford.edu/pages/viewpage.action?pageId=429562464](https://confluence.slac.stanford.edu/pages/viewpage.action?pageId=429562464)
+Then read the following for an overview of the development process: [https://confluence.slac.stanford.edu/pages/viewpage.action?pageId=429562464](https://confluence.slac.stanford.edu/pages/viewpage.action?pageId=429562464)
+
+For commit messages, we can try to follow the PyDM guidelines: https://slaclab.github.io/pydm/development/development.html#commit-guidelines
+
+### Logging
+
+Loggings calls are added to the library code, and also to the [EventScanParallelSlice.py](https://github.com/slaclab/beamtime-calibration-suite/blob/main/suite_scripts/EventScanParallelSlice.py) and
+[AnalyzeH5.py](https://github.com/slaclab/beamtime-calibration-suite/blob/main/suite_scripts/AnalyzeH5.py) files in /suite_scripts to act as examples of generating logs from both the library
+and high-level scripts.
+
+Using the following method will append log messages to the log-file if it already exists, or create a new
+log-file if the file doesn't exist. If you want a new log-file for each run of a high-level script, 
+atm you will need to rename the log-file after each run so a new one will be generated.
+
+To have your high-level script generate logs from the calibrationSuite library code, add the following at the top of the script:
+
+```
+import os
+import calibrationSuite.loggingSetup as ls
+currFileName = os.path.basename(__file__)
+ls.setupScriptLogging(currFileName[:-3] + ".log", logging.INFO)
+```
+
+You can pass a chosen log-file name to the setupScriptLogging function,
+but using the above will create and write to file named <curr script name>.log
+
+To add additional logging from the high-level script itself(to the same file specified to setupScriptLogging),
+you can also add the following to the top of the script:
+
+``` 
+import logging
+logger = logging.getLogger(__name__)
+```
+
+Then can add log statements throughout the script with:
+
+``` 
+logger.error("Example error msg!") # for logging when the program goes wrong
+logger.exception("Example exception msg!) # for logging error and also including stack-trace in log 
+logger.info("Example info msg!") # for logging useful info on the state of the program
+```
+
+_(Note: these must take a statement evaluating to a single string, if a,b,c are strings can't do 'logger.info(a,b,c)' but can do 'logger.info(a+b+c)'. Also for example if a is an int, must do 'logger.info(str(a)))_

calibrationSuite/Stats.py

@@ -1,4 +1,6 @@
 import numpy
+import logging
+logger = logging.getLogger(__name__)
 
 class Stats(object):
     def __init__(self, shape):
@@ -35,6 +37,9 @@ def accumulate(self, x, y=0):
         d = numpy.sin((numpy.array(list(range(10)))+i)/3.14159)
         s.accumulate(d, d[7])
 
-    print(s.mean())
-    print(s.rms())
-    print(s.corr(s.mean()[7], s.rms()[7]))
+    print("mean: " + str(s.mean()))
+    print("rms: " + str(s.rms()))
+    print("s.corr(s.mean()[7], s.rms()[7]): " + str(s.corr(s.mean()[7], s.rms()[7])))
+    logger.info("mean: " + str(s.mean()))
+    logger.info("rms: " + str(s.rms()))
+    logger.info("s.corr(s.mean()[7], s.rms()[7]): " + str(s.corr(s.mean()[7], s.rms()[7])))

calibrationSuite/ancillaryMethods.py

@@ -1,5 +1,7 @@
 import numpy as np
 from scipy.stats import binned_statistic
+import logging
+logger = logging.getLogger(__name__)
 
 def makeProfile(x, y, bins, range=None, spread=False):
     ## NaN for empty bins are suppressed
@@ -16,6 +18,7 @@ def makeProfile(x, y, bins, range=None, spread=False):
     if bin_N.sum()==0:
         ##no data
         print("no data in profile")
+        logger.error("no data in profile")
         return None, None, None
 
     ##yErr = np.sqrt(means2 - means**2)

calibrationSuite/basicSuiteScript.py

@@ -46,6 +46,8 @@ def __init__(self, analysisType='scan'):
             sys.exit(1)
         experimentHash = config.experimentHash
 
+        logger.info("in BasicSuiteScript, inheriting from PsanaBase, type is psana%d" %(self.psanaType))
+
         self.gainModes = {"FH":0, "FM":1, "FL":2, "AHL-H":3, "AML-M":4, "AHL-L":5, "AML-L":6}
         self.ePix10k_cameraTypes = {1:"Epix10ka", 4:"Epix10kaQuad", 16:"Epix10ka2M"}
         self.camera = 0
@@ -76,6 +78,8 @@ def __init__(self, analysisType='scan'):
         ##if False:
         except:
             print("had trouble finding", self.ROIfileNames)
+            for currName in self.ROIfileNames:
+                logger.exception("had trouble finding" + currName)        
             self.ROI = None
             self.ROIs = None
         try:
@@ -230,6 +234,7 @@ def rowCommonModeCorrection(self, frame, arbitraryCut=1000):
                 except:
                     rowCM = -666
                     print("rowCM problem")
+                    logger.error("rowCM problem")
                     print(frame[r, colOffset:colOffset + self.detColsPerBank])
                 colOffset += self.detColsPerBank
         return frame
@@ -254,6 +259,7 @@ def colCommonModeCorrection(self, frame, arbitraryCut=1000):
                 except:
                     colCM = -666
                     print("colCM problem")
+                    logger.error("colCM problem")
                     print(frame[rowOffset:rowOffset + self.detRowsPerBank], c)
                 rowOffset += self.detRowsPerBank
         return frame
@@ -278,11 +284,19 @@ def dumpEventCodeStatistics(self):
                 self.nDaqCodeEvents,
                 self.nBeamCodeEvents)
               )
+        logger.info("have counted %d run triggers, %d DAQ triggers, %d beam events"
+              %(self.nRunCodeEvents,
+                self.nDaqCodeEvents,
+                self.nBeamCodeEvents)
+              )
+
 
 if __name__ == "__main__":
     bSS = BasicSuiteScript()
     print("have built a BasicSuiteScript")
+    logger.info("have built a BasicSuiteScript")
     bSS.setupPsana()
     evt = bSS.getEvt()
     print(dir(evt))
+    logger.info(dir(evt))
 

calibrationSuite/cluster.py

@@ -1,4 +1,6 @@
 import numpy
+import logging
+logger = logging.getLogger(__name__)
 
 class Cluster(object):
     def __init__(self, row, col, energy):

calibrationSuite/fitFunctions.py

@@ -2,6 +2,8 @@
 from scipy.optimize import curve_fit
 from scipy.stats import norm
 from statsmodels.nonparametric.bandwidths import bw_silverman
+import logging
+logger = logging.getLogger(__name__)
 
 def linear(x, a, b):
     return a*x + b
@@ -62,11 +64,11 @@ def getGaussianFitFromHistogram(binCenters, counts, x0=None, x1=None):
         x, y = getRestrictedHistogram(x, y, x0, x1)
 
     a, mean, std = estimateGaussianParameters(zip(x,y))
-    popt, pcov = curve_fit(fitFunctions.gaussian, x, y, [3, mean, std])
+    popt, pcov = curve_fit(gaussian, x, y, [3, mean, std])
     ##a = popt[0]
     ##mu = popt[1]
     ##sigma = popt[2]
-    fittedFunc = fitFunctions.gaussian(x, *popt)
+    fittedFunc = gaussian(x, *popt)
 
     ## should perhaps return an object with attributes for future flexibility
     return popt, fittedFunc
@@ -163,5 +165,4 @@ def testMissingBinTest():
     mbt_a = missingBinTest(binCenters, ha)
     mbt_b = missingBinTest(binCenters, hb)
     print("per n sigma check for gap in gaussian, notched gaussian:", mbt_a, mbt_b)
-    print((range(1,6)*mbt_a).sum(), (range(1,6)*mbt_b).sum())
-
+    print((range(1,6)*mbt_a).sum(), (range(1,6)*mbt_b).sum())

calibrationSuite/loggingSetup.py

@@ -0,0 +1,11 @@
+import logging
+
+def setupScriptLogging(fileName, logLevel):
+    # Setup logging to file '<filename>.log', and configures the underlying calibration-library logging.
+    # Log file gets appended to each new run, and can manually delete for fresh log.
+    # (Could change so makes new unique log each run or overwrites existing log)
+    logging.basicConfig(
+        filename= fileName,
+        level=logLevel, # For full logging set to INFO which includes ERROR logging too
+        format='%(asctime)s - %(levelname)s - %(message)s' # levelname is log severity (ERROR, INFO, etc)
+    )

calibrationSuite/psana1Base.py

@@ -1,10 +1,13 @@
 from psana import *
 from PSCalib.NDArrIO import load_txt
+import logging
+logger = logging.getLogger(__name__)
 
 class PsanaBase(object):
     def __init__(self, analysisType='scan'):
         self.psanaType = 1
         print("in psana1Base")
+        logger.info("in psana1Base")
         self.gainModes = {"FH":0, "FM":1, "FL":2, "AHL-H":3, "AML-M":4, "AHL-L":5, "AML-L":6}
         self.ePix10k_cameraTypes = {1:"Epix10ka", 4:"Epix10kaQuad", 16:"Epix10ka2M"}
         self.g0cut = 1<<14
@@ -19,7 +22,8 @@ def get_ds(self, run=None):
 
 
     def setupPsana(self):
-        ##print("have built basic script class, exp %s run %d" %(self.exp, self.run))
+        logger.info("have built basic script class, exp %s run %d" %(self.exp, self.run))
+
         if self.runRange is None:
             self.ds = self.get_ds(self.run)
         else:
@@ -81,9 +85,11 @@ def getEvtFromRuns(self):
             try:
                 self.run = self.runRange[i+1]
                 print("switching to run %d" %(self.run))
+                logger.info("switching to run %d" %(self.run))
                 self.ds = self.get_ds(self.run)
             except:
                 print("have run out of new runs")
+                logger.exception("have run out of new runs")
                 return None
             ##print("get event from new run")
             evt = next(self.ds.events())
@@ -94,6 +100,7 @@ def getFlux(self, evt):
             fluxes = self.wave8.get(evt).peakA()
             if fluxes is None:
                 print("No flux found")## if self.verbose?
+                logger.error("No flux found")
                 return None
             f = fluxes[self.fluxChannels].mean()*self.fluxSign
             try:

calibrationSuite/psana2Base.py

@@ -13,11 +13,15 @@
 rank = comm.Get_rank()
 size = comm.Get_size()
 
+import logging
+logger = logging.getLogger(__name__)
 
 class PsanaBase(object):
     def __init__(self, analysisType='scan'):
         self.psanaType = 2
         print("in psana2Base")
+        logger.info("in psana2Base")
+
         self.gainModes = {"FH":0, "FM":1, "FL":2, "AHL-H":3, "AML-M":4, "AHL-L":5, "AML-L":6}
         self.ePix10k_cameraTypes = {1:"Epix10ka", 4:"Epix10kaQuad", 16:"Epix10ka2M"}
         ##self.g0cut = 1<<15 ## 2022
@@ -26,7 +30,7 @@ def __init__(self, analysisType='scan'):
 
         self.allowed_timestamp_mismatch = 1000
 
-##        self.setupPsana()
+        ##self.setupPsana()
 
     def get_ds(self, run=None):
         if run is None:
@@ -70,6 +74,7 @@ def setupPsana(self):
         except:
             self.mfxDg1 = None
             print("No flux source found")## if self.verbose?
+            logger.exception("No flux source found")        
         try:
             self.mfxDg2 = self.myrun.Detector('MfxDg2BmMon')
         except:
@@ -163,9 +168,11 @@ def getEvtFromRuns(self):
             try:
                 self.run = self.runRange[i+1]
                 print("switching to run %d" %(self.run))
+                logger.info("switching to run %d" %(self.run))
                 self.ds = self.get_ds(self.run)
             except:
                 print("have run out of new runs")
+                logger.exception("have run out of new runs")
                 return None
             ##print("get event from new run")
             evt = next(self.ds.events())
@@ -252,6 +259,7 @@ def getScanValue(self, step, useStringInfo=False):
             ##print(payload)
             sv = eval(payload.split()[-1][:-1])
             print("step", int(self.step_value(step)), sv)
+            logger.info("step" + str(int(self.step_value(step))) + str(sv))
             return sv
         return self.step_value(step)