WARNING: problem with updatePlotImage

[prjemian]

shows up in the log file:

usaxs@usaxscontrol /share1/local_livedata $ grep updatePlotImage log.txt  | tail -20
2019-06-20 11:31:45.834 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:31:55.739 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:32:05.829 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:32:15.947 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:32:25.562 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:32:35.834 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:34:16.334 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:34:36.638 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:36:16.949 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:36:27.144 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:38:07.692 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:38:17.854 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:38:27.644 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:38:37.825 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:38:48.586 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:38:58.047 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:39:07.934 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:39:18.533 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:40:58.626 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 11:41:08.409 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'

[prjemian]

Also, periodic interspersed with possible vibrations during scan messages:

2019-06-18 20:31:56.330 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:31:58.134 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-18 20:32:06.388 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:32:08.251 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-18 20:32:16.397 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:32:18.292 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-18 20:32:26.471 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:32:28.310 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-18 20:32:36.413 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:32:38.193 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-18 20:32:46.567 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:32:48.276 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-18 20:34:37.059 (WARNING,34984,reduceFlyData,312)   possible vibrations during scan, re-generating AR from 10Hz sampling array
2019-06-18 20:34:38.809 (WARNING,34984,__main__,397) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'

might be related, might not

[prjemian]

First WARNING: https://github.com/APS-USAXS/livedata/blob/70848bf34bbc10086f4270f4aa0e51a52a45e153/pvwatch.py#L393-L397

Second WARNING from here: https://github.com/APS-USAXS/livedata/blob/70848bf34bbc10086f4270f4aa0e51a52a45e153/reduceFlyData.py#L312-L313

but discovered from this block: https://github.com/APS-USAXS/livedata/blob/70848bf34bbc10086f4270f4aa0e51a52a45e153/reduceFlyData.py#L499-L521

where (I believe) mode_number == AR_MODE_TRAJECTORY so the second block in the `if..elif`` is taken.

[prjemian]

With the first WARNING (operation not permitted), there is not enough info shown to identify the source of this unpermitted operation. BUT, since it is recurrent now, it might be easy to observe it in action.

[prjemian]

Taking a hint, added logger.warn(traceback.format_exc()) and recorded this output:

2019-06-20 12:02:58.241 (WARNING,93056,__main__,398) problem with updatePlotImage(): traceback=[Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'
2019-06-20 12:03:02.612 (WARNING,93056,__main__,399) Traceback (most recent call last):
  File "/home/beams11/USAXS/Documents/eclipse/USAXS/livedata/pvwatch.py", line 395, in main_event_loop_checks
    updatePlotImage()                          # update the plot
  File "/home/beams11/USAXS/Documents/eclipse/USAXS/livedata/pvwatch.py", line 128, in updatePlotImage
    scanplots.main(n=localConfig.NUM_SCANS_PLOTTED, cp=True)
  File "/home/beams11/USAXS/Documents/eclipse/USAXS/livedata/scanplots.py", line 448, in main
    wwwServerTransfers.nfsCpToWebServer(local_plot, www_plot)
  File "/home/beams11/USAXS/Documents/eclipse/USAXS/livedata/wwwServerTransfers.py", line 71, in nfsCpToWebServer
    shutil.copy2(sourceFile, destinationName)
  File "/APSshare/anaconda/x86_64/lib/python2.7/shutil.py", line 145, in copy2
    copystat(src, dst)
  File "/APSshare/anaconda/x86_64/lib/python2.7/shutil.py", line 114, in copystat
    os.chmod(dst, mode)
OSError: [Errno 1] Operation not permitted: '/net/joule/export/joule/WEBUSAXS/www_live/livedata.png'

[prjemian]

This is the line producing the error: https://github.com/APS-USAXS/livedata/blob/70848bf34bbc10086f4270f4aa0e51a52a45e153/scanplots.py#L448

[prjemian]

Need better diagnostic message about this. AND need to fix it! Try the file copy on the command line first. The file copy uses this python code: shutil.copy2(sourceFile, destinationName)

• local_plot: /share1/local_livedata/livedata.png
• www_plot: livedata.png
• sourceFile: /share1/local_livedata/livedata.png
• destinationName: /net/joule/export/joule/WEBUSAXS/www_live/livedata.png

Try this bash shell command line:

cp /share1/local_livedata/livedata.png /net/joule/export/joule/WEBUSAXS/www_live/livedata.png

[prjemian]

result:

usaxs@usaxscontrol ~/.../USAXS/livedata $ cp /share1/local_livedata/livedata.png /net/joule/export/joule/WEBUSAXS/www_live/livedata.png
cp: overwrite ‘/net/joule/export/joule/WEBUSAXS/www_live/livedata.png’? y

Need to force this when file exists.

[prjemian]

This hint says to use shutils.copy() (rather than shutils.copy2()) to allow overwrite.

[prjemian]

Also, in wwwServerTransfers, replace with this block to report richer diagnostics at point of error:

    logger.debug(msg)
    try:
        #shutil.copy2(sourceFile, destinationName)
        shutil.copy(sourceFile, destinationName)
    except OSError as exc:
        msg = "OSError - could not " + msg
        logger.debug(msg)
        raise exc

[prjemian]

Still taking notes since these changes should be implemented in a branch with a PR. Summary of changes:

usaxs@usaxscontrol ~/.../USAXS/livedata $ git diff
diff --git a/pvwatch.py b/pvwatch.py
index be3893a..b3ef8fa 100755
--- a/pvwatch.py
+++ b/pvwatch.py
@@ -19,6 +19,7 @@ os.environ['HDF5_DISABLE_VERSION_CHECK'] = '2'
 import os.path          # testing if a file exists
 import shutil           # file copies
 import time             # provides sleep()
+import traceback
 from xml.dom import minidom
 from xml.etree import ElementTree

@@ -395,6 +396,7 @@ def main_event_loop_checks(mainLoopCount, nextReport, nextLog, delta_report, del
         except Exception as exc:
             msg = "problem with {}(): traceback={}".format("updatePlotImage", exc)
             logger.warn(msg)
+            logger.warn(traceback.format_exc())

     if dt >= nextLog:
         nextLog = dt + delta_log
diff --git a/wwwServerTransfers.py b/wwwServerTransfers.py
index 5655e8d..b636bb8 100755
--- a/wwwServerTransfers.py
+++ b/wwwServerTransfers.py
@@ -62,14 +62,20 @@ def nfsCpToWebServer(sourceFile, targetFile = "", demo = False):
     if len(targetFile) == 0:
         targetFile = sourceFile
     destinationName = os.path.join(SERVER_WWW_LIVEDATA_NFS, targetFile)
-    msg = "%s -p %s %s" % ("NFS copy", sourceFile, destinationName)
+    msg = "%s  %s %s" % ("cp", sourceFile, destinationName)
     # if demo:
     #     logger.debug(msg)
     #     print msg
     #     return

-    shutil.copy2(sourceFile, destinationName)
     logger.debug(msg)
+    try:
+        #shutil.copy2(sourceFile, destinationName)
+        shutil.copy(sourceFile, destinationName)
+    except OSError as exc:
+        msg = "OSError - could not " + msg
+        logger.debug(msg)
+        raise exc

 def scpToWebServer(sourceFile, targetFile = "", demo = False):

[prjemian]

Stepping through shutils.copy(), I see:

1. copy() and copy2() have identical code!
2. this succeeds: copyfile(src, dst)
3. this raises the OSError: copymode(src, dst)

That makes sense since we cannot change the file metadata through the NFS link.