def spool_lock(spoolpath):
lock = SoftFileLock(join(spoolpath, 'lock'))
lock.acquire()
try:
yield lock
finally:
lock.release()
def _do_action_under_lock_internal(lock_file,
func,
*args,
timeout=LOCK_TIMEOUT,
**kwargs):
# Using this instead of FileLock because it will be used across nodes
# on the Lustre filesystem.
lock_acquisition_seconds = None
lock = SoftFileLock(lock_file, timeout=timeout)
try:
start = time.time()
lock.acquire(timeout=timeout)
lock_acquisition_seconds = time.time() - start
except Timeout:
# Picked a default value such that this should not trip. If it does
# trip under normal circumstances then we need to reconsider this.
logger.error(
"Failed to acquire file lock %s within %s seconds. hostname=%s",
lock_file,
timeout,
socket.gethostname(),
)
raise
if lock_acquisition_seconds > 5:
logger.warning(
"cluster lock acquisition for %s took %s seconds",
func.__name__,
lock_acquisition_seconds,
)
try:
val = func(*args, **kwargs)
lock.release()
return val
except Exception as exc:
lock.release()
# SoftFileLock always deletes the file, so create it again.
# There is a small window where this won't work and another node takes over, so
# callers need to handle the possibility.
logger.exception(
"An exception occurred while holding the Cluster lock. The state of the cluster "
"is unknown.")
try:
fd = os.open(lock_file,
os.O_WRONLY | os.O_CREAT | os.O_EXCL | os.O_TRUNC)
os.close(fd)
logger.error("A deadlock will occur.")
except (IOError, OSError):
logger.exception(
"Unable to cause deadlock. Another node was promoted to submitter"
)
raise exc
def update_archival(outpath):
#add information to "package slip" meta meta data
infofile = os.path.join(outpath, "package_slip.json")
infofile_lock = os.path.join(outpath, "package_slip.json.lock")
lock_timeout = 5
lock = SoftFileLock(infofile_lock)
try:
with lock.acquire(timeout=lock_timeout):
if os.path.isfile(infofile):
# file exists, needs update
help.status_note(['Going to update ', infofile], d=is_debug)
with open(infofile, encoding='utf-8') as data_file:
data = json.load(data_file)
found = False
for key in data['standards_used']:
if key == archival_info['standards_used'][0]:
found = True
if not found:
data['standards_used'].append(
archival_info['standards_used'][0])
else:
# file does not exist, needs to be created
data = archival_info
# in any case: write current data back to info file
help.status_note(['Write info to ', infofile], d=is_debug)
with open(infofile, 'w', encoding='utf-8') as outfile:
# for json:
output_data = json.dumps(data,
sort_keys=True,
indent=4,
separators=(',', ': '))
outfile.write(str(output_data))
help.status_note([
str(os.stat(infofile).st_size), ' bytes written to ',
os.path.abspath(infofile)
],
d=is_debug)
except Timeout:
help.status_note([
'Cannot acquire lock within ', lock_timeout,
' seconds, raising exception!'
],
d=is_debug)
raise
except Exception as exc:
help.status_note(str(exc), d=is_debug)
raise
finally:
lock.release()
def update_archival(outpath):
#add information to "package slip" meta meta data
infofile = os.path.join(outpath, "package_slip.json")
infofile_lock = os.path.join(outpath, "package_slip.json.lock")
lock_timeout = 5
lock = SoftFileLock(infofile_lock)
try:
with lock.acquire(timeout=lock_timeout):
if os.path.isfile(infofile):
# file exists, needs update
status_note(['Going to update ', infofile], d=is_debug)
with open(infofile, encoding='utf-8') as data_file:
data = json.load(data_file)
found = False
for key in data['standards_used']:
if key == archival_info['standards_used'][0]:
found = True
if not found:
data['standards_used'].append(archival_info['standards_used'][0])
else:
# file does not exist, needs to be created
data = archival_info
# in any case: write current data back to info file
status_note(['Write info to ', infofile], d=is_debug)
with open(infofile, 'w', encoding='utf-8') as outfile:
# for json:
output_data = json.dumps(data, sort_keys=True, indent=4, separators=(',', ': '))
outfile.write(str(output_data))
status_note([str(os.stat(infofile).st_size), ' bytes written to ', os.path.abspath(infofile)], d=is_debug)
except Timeout:
status_note(['Cannot acquire lock within ', lock_timeout, ' seconds, raising exception!'], d=is_debug)
raise
except Exception as exc:
status_note(str(exc), d=is_debug)
raise
finally:
lock.release()
def _do_action_under_lock(self, func, *args, **kwargs):
# Using this instead of FileLock because it will be used across nodes
# on the Lustre filesystem.
lock = SoftFileLock(self._lock_file, timeout=self._timeout)
start = time.time()
try:
lock.acquire(timeout=self._timeout)
except Timeout:
# Picked a default value such that this should not trip. If it does
# trip under normal circumstances then we need to reconsider this.
logger.error(
"Failed to acquire file lock %s within %s seconds", self._lock_file, self._timeout
)
raise
duration = time.time() - start
if duration > 10:
logger.warning("Acquiring ResultsAggregator lock took too long: %s", duration)
try:
return func(*args, **kwargs)
finally:
lock.release()
class FileLocker(object):
def __init__(self, path, acquire_timeout=60*60, lock_timeout=15, expire=120):
self.path = path
self.mlock_path = self.path + '.2'
self.expire = expire
self.lock_timeout = lock_timeout
self.acquire_timeout = acquire_timeout
self.primary_locker = SoftFileLock(self.path, self.lock_timeout)
def touch(self):
try:
with open(self.mlock_path, 'a'):
try:
os.utime(self.mlock_path, None) # => Set current time anyway
except OSError:
pass
except Exception as e:
logger.error('Error touch the file: %s' % (e, ), exc_info=e)
def mtime(self):
try:
return os.stat(self.mlock_path).st_mtime
except:
return 0
def is_expired(self):
mtime = self.mtime()
return time.time() - mtime > self.expire
def delete_timing(self):
try:
os.unlink(self.mlock_path)
except:
pass
def release(self):
self.delete_timing()
self.primary_locker.release()
def force_release(self):
self.primary_locker.release(force=True)
try:
os.remove(self.path)
except OSError:
pass
def acquire_try_once(self, _depth=0):
if _depth > 0:
logger.info("Acquire_try_once depth=%s" % _depth)
if _depth > 2:
return False
# Try normal acquisition on the primary file
try:
self.primary_locker.acquire(self.lock_timeout, poll_intervall=0.5)
self.touch()
return True
except Timeout:
# Lock could not be acquired, check whether the timing file, whether
# the locker is still alive. If not, force release and reacquire
# to prevent starving on the deadly-locked resource.
if self.is_expired():
# Expired, release and force-acquire
logger.info("Acquire timeout, timing file is expired, reacquire")
self.force_release()
# Try to re-acquire recursively
return self.acquire_try_once(_depth + 1)
else:
return False
def acquire(self, timeout=None):
time_started = time.time()
while True:
res = self.acquire_try_once()
if res:
return True
time_now = time.time()
if timeout is not None and timeout < 0:
time.sleep(0.01)
continue
if timeout is not None and timeout == 0:
logger.info("Timeout, immediate")
raise Timeout
if timeout is None and time_now - time_started > self.acquire_timeout:
logger.info("Timeout, self.acquire_timeout")
raise Timeout
if timeout is not None and timeout > 0 and time_now - time_started > timeout:
logger.info("Timeout, defined")
raise Timeout
def __enter__(self):
return self.acquire()
def __exit__(self, *args):
self.release()
def store_metadata(
log_file: str,
proc_type: str,
metadata_dict: Dict[str, str],
sim_name: str = None,
metaconst_to_add: List[str] = METACONST_TO_ADD,
logger: Logger = get_basic_logger(),
):
"""Store metadata values in the specified json log file for a specific process type.
Metadata values are stored as key, value pairs if a key already exists,
it is not changed and instead new values are added with a postfix such as _1, _2, etc
The exception are keys that are in the metaconst_to_add list, additional keys are
also stored with a prefix, however their value is also added to the primary
key (i.e. the one without a postfix). This is only allowed for values that can be
converted to int or float.
To prevent locking or any race condition the a lock for the log file is
aquired at the start of the function and released at the end of it.
The lock is kept for the full duration of the function and not just the read/write
part as the file is overwritten and not updated.
Parameters
----------
log_file: str
The absolute log file path
proc_type: str
The process type this is for, one of LF/HF/BB/IM
metadata_dict: Dictionary with string keys and values
The metadata key and value pairs
sim_name: str
The simulation/realisation name for the data provided is added
to the json log file at the top level
metaconst_to_add: List of strings
Metadata keys for which their values are added (e.g. run_time)
logger:
Logger to pass log messages to. If None all messages will be printed to stdout or stderr depending on level
"""
# Check that it is a valid process type
if not const.ProcessType.has_str_value(proc_type):
logger.warning(
"{} is not a valid process type. Logged anyway.".format(proc_type))
lock_file = os.path.join(os.path.dirname(log_file), LOCK_FILENAME)
lock = SoftFileLock(lock_file)
# Attempt to acquire the lock
try:
lock.acquire(timeout=20)
except Timeout:
logger.error(
"Failed to acquire the lock for the metadata log file, "
"giving up on logging data. This should be investigated!"
"The metadata that was unable to be logged is attached: {}".format(
metadata_dict))
return
# Read the existing content if the log file exists
json_data, proc_data = None, None
if os.path.isfile(log_file):
with open(log_file, "r") as f:
json_data = json.load(f)
proc_data = json_data.get(proc_type, None)
# File doesn't exist yet
else:
json_data = {}
# Add the simulation to the log file
if (sim_name is not None
and const.MetadataField.sim_name.value not in json_data.keys()):
json_data[const.MetadataField.sim_name.value] = sim_name
elif (sim_name is not None
and json_data.get(const.MetadataField.sim_name.value) != sim_name):
logger.warning(
"Sim name {} does not match already existing sim name {} in metadata log file {}"
.format(sim_name,
json_data.get(const.MetadataField.sim_name.value),
log_file))
if proc_data is None:
proc_data = {}
json_data[proc_type] = proc_data
for k, v in metadata_dict.items():
if type(v) is str:
v = convert_to_numeric(v)
# Key doesn't exists yet
if k not in proc_data.keys():
proc_data[k] = v
print("{} not in proc_Data.keys(),value {}\n".format(k, v))
continue
# Key already exists
if k in proc_data.keys():
k_count = sum([1 for cur_k in proc_data.keys() if k in cur_k])
# Key has only been added once before (i.e. primary value)
# Duplicate and add _1 postfix
if k_count == 1:
proc_data["{}_1".format(k)] = proc_data[k]
# Add new value
proc_data["{}_2".format(k)] = v
# Several keys already exists, just add additional with count postfix
else:
# Don't need a +1 as the count includes the primary value
proc_data["{}_{}".format(k, k_count)] = v
# Write the json
with open(log_file, "w") as f:
json.dump(json_data, f)
lock.release()
class ConcurrentRotatingFileHandler(BaseRotatingHandler):
"""
Handler for logging to a set of files, which switches from one file to the
next when the current file reaches a certain size. Multiple processes can
write to the log file concurrently, but this may mean that the file will
exceed the given size.
"""
def __init__(
self,
filename,
mode="a",
maxBytes=0,
backupCount=0,
encoding=None,
debug=True,
supress_abs_warn=False,
):
"""
Open the specified file and use it as the stream for logging.
By default, the file grows indefinitely. You can specify particular
values of maxBytes and backupCount to allow the file to rollover at
a predetermined size.
Rollover occurs whenever the current log file is nearly maxBytes in
length. If backupCount is >= 1, the system will successively create
new files with the same pathname as the base file, but with extensions
".1", ".2" etc. appended to it. For example, with a backupCount of 5
and a base file name of "app.log", you would get "app.log",
"app.log.1", "app.log.2", ... through to "app.log.5". The file being
written to is always "app.log" - when it gets filled up, it is closed
and renamed to "app.log.1", and if files "app.log.1", "app.log.2" etc.
exist, then they are renamed to "app.log.2", "app.log.3" etc.
respectively.
If maxBytes is zero, rollover never occurs.
On Windows, it is not possible to rename a file that is currently opened
by another process. This means that it is not possible to rotate the
log files if multiple processes is using the same log file. In this
case, the current log file will continue to grow until the rotation can
be completed successfully. In order for rotation to be possible, all of
the other processes need to close the file first. A mechanism, called
"degraded" mode, has been created for this scenario. In degraded mode,
the log file is closed after each log message is written. So once all
processes have entered degraded mode, the next rotate log attempt should
be successful and then normal logging can be resumed.
This log handler assumes that all concurrent processes logging to a
single file will are using only this class, and that the exact same
parameters are provided to each instance of this class. If, for
example, two different processes are using this class, but with
different values for 'maxBytes' or 'backupCount', then odd behavior is
expected. The same is true if this class is used by one application, but
the RotatingFileHandler is used by another.
NOTE: You should always provide 'filename' as an absolute path, since
this class will need to re-open the file during rotation. If your
application call os.chdir() then subsequent log files could be created
in the wrong directory.
"""
# The question of absolute paths: I'm not sure what the 'right thing' is
# to do here. RotatingFileHander simply ignores this possibility. I was
# going call os.path.abspath(), but that potentially limits uses. For
# example, on Linux (any posix system?) you can rename a directory of a
# running app, and the app wouldn't notice as long as it only opens new
# files using relative paths. But since that's not a "normal" thing to
# do, and having an app call os.chdir() is a much more likely scenario
# that should be supported. For the moment, we are just going to warn
# the user if they provide a relative path and do some other voodoo
# logic that you'll just have to review for yourself.
# if the given filename contains no path, we make an absolute path
if not os.path.isabs(filename):
if FORCE_ABSOLUTE_PATH or not os.path.split(filename)[0]:
filename = os.path.abspath(filename)
elif not supress_abs_warn:
from warnings import warn
warn(
"The given 'filename' should be an absolute path. If your "
"application calls os.chdir(), your logs may get messed up. "
"Use 'supress_abs_warn=True' to hide this message."
)
try:
BaseRotatingHandler.__init__(self, filename, mode, encoding)
except TypeError: # Due to a different logging release without encoding support (Python 2.4.1 and earlier?)
BaseRotatingHandler.__init__(self, filename, mode)
self.encoding = encoding
self._rotateFailed = False
self.maxBytes = maxBytes
self.backupCount = backupCount
# Prevent multiple extensions on the lock file (Only handles the normal "*.log" case.)
self.lock_file = "%s.lock" % filename
self.stream_lock = SoftFileLock(self.lock_file)
# For debug mode, swap out the "_degrade()" method with a more a verbose one.
if debug:
self._degrade = self._degrade_debug
def _openFile(self, mode):
if self.encoding:
self.stream = codecs.open(self.baseFilename, mode, self.encoding)
else:
self.stream = open(self.baseFilename, mode)
def acquire(self):
""" Acquire thread and file locks. Also re-opening log file when running
in 'degraded' mode. """
# handle thread lock
Handler.acquire(self)
self.stream_lock.acquire()
if self.stream.closed:
self._openFile(self.mode)
def release(self):
""" Release file and thread locks. Flush stream and take care of closing
stream in 'degraded' mode. """
try:
if not self.stream.closed:
self.stream.flush()
if self._rotateFailed:
self.stream.close()
except IOError:
if self._rotateFailed:
self.stream.close()
finally:
try:
self.stream_lock.release()
finally:
# release thread lock
Handler.release(self)
def close(self):
"""
Closes the stream.
"""
if not self.stream.closed:
self.stream.flush()
self.stream.close()
Handler.close(self)
def flush(self):
""" flush(): Do nothing.
Since a flush is issued in release(), we don't do it here. To do a flush
here, it would be necessary to re-lock everything, and it is just easier
and cleaner to do it all in release(), rather than requiring two lock
ops per handle() call.
Doing a flush() here would also introduces a window of opportunity for
another process to write to the log file in between calling
stream.write() and stream.flush(), which seems like a bad thing. """
pass
def _degrade(self, degrade, msg, *args):
""" Set degrade mode or not. Ignore msg. """
self._rotateFailed = degrade
del msg, args # avoid pychecker warnings
def _degrade_debug(self, degrade, msg, *args):
""" A more colorful version of _degade(). (This is enabled by passing
"debug=True" at initialization).
"""
if degrade:
if not self._rotateFailed:
sys.stderr.write(
"Degrade mode - ENTERING - (pid=%d) %s\n"
% (os.getpid(), msg % args)
)
self._rotateFailed = True
else:
if self._rotateFailed:
sys.stderr.write(
"Degrade mode - EXITING - (pid=%d) %s\n"
% (os.getpid(), msg % args)
)
self._rotateFailed = False
def doRollover(self):
"""
Do a rollover, as described in __init__().
"""
if self.backupCount <= 0:
# Don't keep any backups, just overwrite the existing backup file
# Locking doesn't much matter here; since we are overwriting it anyway
self.stream.close()
self._openFile("w")
return
self.stream.close()
try:
# Attempt to rename logfile to tempname: There is a slight race-condition here, but it seems unavoidable
tmpname = None
while not tmpname or os.path.exists(tmpname):
tmpname = "%s.rotate.%08d" % (self.baseFilename, randint(0, 99999999))
try:
# Do a rename test to determine if we can successfully rename the log file
os.rename(self.baseFilename, tmpname)
except (IOError, OSError):
exc_value = sys.exc_info()[1]
self._degrade(
True, "rename failed. File in use? " "exception=%s", exc_value
)
return
# Q: Is there some way to protect this code from a KeboardInterupt?
# This isn't necessarily a data loss issue, but it certainly would
# break the rotation process during my stress testing.
# There is currently no mechanism in place to handle the situation
# where one of these log files cannot be renamed. (Example, user
# opens "logfile.3" in notepad)
for i in range(self.backupCount - 1, 0, -1):
sfn = "%s.%d" % (self.baseFilename, i)
dfn = "%s.%d" % (self.baseFilename, i + 1)
if os.path.exists(sfn):
# print "%s -> %s" % (sfn, dfn)
if os.path.exists(dfn):
os.remove(dfn)
os.rename(sfn, dfn)
dfn = self.baseFilename + ".1"
if os.path.exists(dfn):
os.remove(dfn)
os.rename(tmpname, dfn)
# print "%s -> %s" % (self.baseFilename, dfn)
self._degrade(False, "Rotation completed")
finally:
self._openFile(self.mode)
def shouldRollover(self, record):
"""
Determine if rollover should occur.
For those that are keeping track. This differs from the standard
library's RotatingLogHandler class. Because there is no promise to keep
the file size under maxBytes we ignore the length of the current record.
"""
del record # avoid pychecker warnings
if self._shouldRollover():
# if some other process already did the rollover we might
# checked log.1, so we reopen the stream and check again on
# the right log file
self.stream.close()
self._openFile(self.mode)
return self._shouldRollover()
return False
def _shouldRollover(self):
if self.maxBytes > 0: # are we rolling over?
try:
self.stream.seek(0, 2) # due to non-posix-compliant Windows feature
except IOError:
return True
if self.stream.tell() >= self.maxBytes:
return True
else:
self._degrade(False, "Rotation done or not needed at this time")
return False