Improved logging

src/core/wopi.py

@@ -158,6 +158,8 @@ def setLock(fileid, reqheaders, acctok):
                                    os.path.splitext(acctok['filename'])[1] not in srv.nonofficetypes)
     except IOError as e:
         # expected failures are handled in storeWopiLock
+        log.error('msg="%s: unable to store WOPI lock" filename="%s" token="%s" lock="%s" reason="%s"' %
+                  (op.title(), acctok['filename'], flask.request.args['access_token'][-20:], lock, e))
         return str(e), http.client.INTERNAL_SERVER_ERROR
 
 

src/core/wopiutils.py

@@ -319,9 +319,7 @@ def storeWopiLock(fileid, operation, lock, oldlock, acctok, isoffice):
             log.info('msg="%s" filename="%s" token="%s" lock="%s" result="refreshed"' %
                      (operation.title(), acctok['filename'], flask.request.args['access_token'][-20:], lock))
             return 'OK', http.client.OK
-        # any other error is logged and raised
-        log.error('msg="%s: unable to store WOPI lock" filename="%s" token="%s" lock="%s" reason="%s"' %
-                  (operation.title(), acctok['filename'], flask.request.args['access_token'][-20:], lock, e))
+        # any other error is raised
         raise
 
 

src/core/xrootiface.py

@@ -268,6 +268,7 @@ def rmxattr(endpoint, filepath, userid, key):
 def setlock(endpoint, filepath, userid, value):
     '''Set a lock as an xattr with the special option "c" (create-if-not-exists) on behalf of the given userid'''
     try:
+        log.debug('msg="Invoked setlock" filepath="%s"' % filepath)
         setxattr(endpoint, filepath, userid, LOCKKEY, str(value) + '&mgm.option=c')
     except IOError as e:
         if EXCL_XATTR_MSG in str(e):
@@ -276,19 +277,22 @@ def setlock(endpoint, filepath, userid, value):
 
 def getlock(endpoint, filepath, userid):
     '''Get the lock metadata as an xattr on behalf of the given userid'''
+    log.debug('msg="Invoked getlock" filepath="%s"' % filepath)
     return getxattr(endpoint, filepath, userid, LOCKKEY)
 
 
 def refreshlock(endpoint, filepath, userid, value):
     '''Refresh the lock value as an xattr on behalf of the given userid'''
+    log.debug('msg="Invoked refreshlock" filepath="%s"' % filepath)
     if getxattr(endpoint, filepath, userid, LOCKKEY):
-        setxattr(endpoint, filepath, userid, LOCKKEY, value)   # non-atomic, but the lock is already held
+        setxattr(endpoint, filepath, userid, LOCKKEY, value)   # non-atomic, but the lock was already held
     else:
         raise IOError('File was not locked')
 
 
 def unlock(endpoint, filepath, userid):
     '''Remove a lock as an xattr on behalf of the given userid'''
+    log.debug('msg="Invoked unlock" filepath="%s"' % filepath)
     rmxattr(endpoint, filepath, userid, LOCKKEY)