fixed "final" bug, now passing both posix and stress tests

Author: s-m-e

.gitignore

@@ -95,3 +95,4 @@ test_suite
 test_mount
 test_logs
 fsx-linux*
+screenshots/

makefile

@@ -73,9 +73,16 @@ destroy_childfs:
 	python3 -c 'import tests; tests.lib.quick_cli_destroy_childfs()'
 
 test:
+	make test_posix
+	make test_stress
+
+test_posix:
 	# make docu
 	-rm tests/__pycache__/*.pyc
 	-rm tests/lib/__pycache__/*.pyc
 	# USAGE: make test T="-T chmod/01.t -T chmod/02.t"
 	# REFERENCE TEST WITH EXT4: make test T="-M ext4"
 	pytest $(T)
+
+test_stress:
+	tests/scripts/fsx

src/loggedfs/core.py

@@ -40,6 +40,7 @@
 import re
 import stat
 import sys
+import time
 
 try:
 	from time import time_ns
@@ -60,6 +61,29 @@
 except ImportError:
 	fuse_features = {}
 
+
+# +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+# LOGGING: Support nano-second timestamps
+# +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+
+class _LogRecord_ns_(logging.LogRecord):
+	def __init__(self, *args, **kwargs):
+		self.created_ns = time_ns() # Fetch precise timestamp
+		super().__init__(*args, **kwargs)
+
+class _Formatter_ns_(logging.Formatter):
+	default_nsec_format = '%s,%09d'
+	def formatTime(self, record, datefmt=None):
+		if datefmt is not None: # Do not handle custom formats here ...
+			return super().formatTime(record, datefmt) # ... leave to original implementation
+		ct = self.converter(record.created_ns / 1e9)
+		t = time.strftime(self.default_time_format, ct)
+		s = self.default_nsec_format % (t, record.created_ns - (record.created_ns // 10**9) * 10**9)
+		return s
+
+logging.setLogRecordFactory(_LogRecord_ns_)
+
+
 # +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 # ROUTINES
 # +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
@@ -92,9 +116,9 @@ def __format_args__(args_list, kwargs_dict, items_list, format_func):
 
 	for item in items_list:
 		if isinstance(item, int):
-			args_list[item] = format_func(args_list[item])
+			args_list[item] = format_func(args_list[item] if item < len(args_list) else -10)
 		elif isinstance(item, str):
-			kwargs_dict[item] = format_func(kwargs_dict[item])
+			kwargs_dict[item] = format_func(kwargs_dict.get(item, -11))
 
 
 def __get_abs_path__(args_list, kwargs_dict, path_item_list, abs_func):
@@ -140,10 +164,22 @@ def __get_user_name_from_uid__(uid):
 		return '[uid: omitted argument]'
 
 
+def __get_fh_from_fip__(fip):
+
+	if fip is None:
+		return -1
+	if not hasattr(fip, 'fh'):
+		return -2
+	if not isinstance(fip.fh, int):
+		return -3
+	return fip.fh
+
+
 def __log__(
 	format_pattern = '',
 	abs_path_fields = None, length_fields = None,
 	uid_fields = None, gid_fields = None,
+	fip_fields = None,
 	path_filter_field = 0
 	):
 
@@ -155,6 +191,8 @@ def __log__(
 		uid_fields = []
 	if gid_fields is None:
 		gid_fields = []
+	if fip_fields is None:
+		fip_fields = []
 
 	def wrapper(func):
 
@@ -181,7 +219,8 @@ def wrapped(self, *func_args, **func_kwargs):
 					(abs_path_fields, lambda x: self._full_path(x)),
 					(length_fields, lambda x: len(x)),
 					(uid_fields, lambda x: '%s(%d)' % (__get_user_name_from_uid__(x), x)),
-					(gid_fields, lambda x: '%s(%d)' % (__get_group_name_from_gid__(x), x))
+					(gid_fields, lambda x: '%s(%d)' % (__get_group_name_from_gid__(x), x)),
+					(fip_fields, lambda x: '%d' % __get_fh_from_fip__(x))
 					]:
 					__format_args__(func_args_f, func_kwargs_f, field_list, format_func)
 
@@ -346,8 +385,8 @@ def __init__(self,
 
 	def _init_logger(self, log_enabled, log_file, log_syslog, log_printprocessname):
 
-		log_formater = logging.Formatter('%(asctime)s (%(name)s) %(message)s')
-		log_formater_short = logging.Formatter('%(message)s')
+		log_formater = _Formatter_ns_('%(asctime)s (%(name)s) %(message)s')
+		log_formater_short = _Formatter_ns_('%(message)s')
 
 		self._log_printprocessname = bool(log_printprocessname)
 
@@ -461,7 +500,7 @@ def destroy(self, path):
 		os.close(self.root_path_fd)
 
 
-	@__log__(format_pattern = '{0}', abs_path_fields = [0])
+	@__log__(format_pattern = '{0} (fh={1})', abs_path_fields = [0], fip_fields = [1])
 	def getattr(self, path, fip):
 
 		if not fip:
@@ -492,9 +531,11 @@ def flush(self, path, fip):
 
 
 	# Ugly HACK, addressing https://github.com/fusepy/fusepy/issues/81 ????????
+	@__log__(format_pattern = '{0} (fh={2})', abs_path_fields = [0], fip_fields = [2])
 	def fsync(self, path, datasync, fip):
 
-		raise FuseOSError(errno.ENOSYS)
+		# raise FuseOSError(errno.ENOSYS)
+		return 0
 
 
 	@__log__(format_pattern = '{0}')
@@ -563,15 +604,15 @@ def mknod(self, path, mode, dev):
 		os.chmod(rel_path, mode, dir_fd = self.root_path_fd) # HACK should be lchmod, which is only available on BSD
 
 
-	@__log__(format_pattern = '({1}) {0}', abs_path_fields = [0])
+	@__log__(format_pattern = '({1}) {0} (fh={1})', abs_path_fields = [0], fip_fields = [1])
 	def open(self, path, fip):
 
 		fip.fh = os.open(self._rel_path(path), fip.flags, dir_fd = self.root_path_fd)
 
 		return 0 # Must return handle or zero # TODO ?
 
 
-	@__log__(format_pattern = '{1} bytes from {0} at offset {2}', abs_path_fields = [0])
+	@__log__(format_pattern = '{1} bytes from {0} at offset {2} (fh={3})', abs_path_fields = [0], fip_fields = [3])
 	def read(self, path, length, offset, fip):
 
 		# ret is a bytestring!
@@ -607,9 +648,11 @@ def readlink(self, path):
 
 
 	# Ugly HACK, addressing https://github.com/fusepy/fusepy/issues/81
+	@__log__(format_pattern = '{0} (fh={1})', abs_path_fields = [0], fip_fields = [1])
 	def release(self, path, fip):
 
-		raise FuseOSError(errno.ENOSYS)
+		# raise FuseOSError(errno.ENOSYS)
+		os.close(fip.fh)
 
 
 	@__log__(format_pattern = '{0} to {1}', abs_path_fields = [0, 1])
@@ -648,24 +691,12 @@ def symlink(self, target_path, source_path):
 		os.chown(target_rel_path, uid, gid, dir_fd = self.root_path_fd, follow_symlinks = False)
 
 
-	@__log__(format_pattern = '{0} to {1} bytes', abs_path_fields = [0])
+	@__log__(format_pattern = '{0} to {1} bytes (fh={fip})', abs_path_fields = [0], fip_fields = ['fip'])
 	def truncate(self, path, length, fip = None):
 
 		if fip is None:
 
-			try:
-				fh = os.open(
-					self._rel_path(path),
-					flags = os.O_WRONLY | os.O_TRUNC,
-					dir_fd = self.root_path_fd
-					)
-			except FileNotFoundError:
-				raise FuseOSError(errno.ENOENT)
-
-			ret = os.ftruncate(fh, length)
-			os.close(fh)
-
-			return ret
+			os.truncate(self._rel_path(path), length)
 
 		else:
 
@@ -704,15 +735,11 @@ def _fix_time_(atime, mtime):
 			os.utime(relpath, times = times, dir_fd = self.root_path_fd, follow_symlinks = False)
 
 
-	@__log__(format_pattern = '{1} bytes to {0} at offset {2}', abs_path_fields = [0], length_fields = [1])
+	@__log__(format_pattern = '{1} bytes to {0} at offset {2} (fh={3})', abs_path_fields = [0], length_fields = [1], fip_fields = [3])
 	def write(self, path, buf, offset, fip):
 
 		# buf is a bytestring!
 
 		res = os.pwrite(fip.fh, buf, offset)
 
-		#os.fdatasync(fip.fh)
-		#os.fdopen(fip.fh).flush()
-		#os.fsync(fip.fh)
-
 		return res

tests/lib/base.py

@@ -137,6 +137,19 @@ def init_d_childfs(self):
 		open(self.fstest_log_abs_path, 'a').close() # HACK create empty fstest log file
 
 
+	def assert_childfs_mountpoint(self):
+
+		assert is_path_mountpoint(self.mount_child_abs_path)
+
+
+	def assert_parentfs_mountpoint(self):
+
+		if self.travis:
+			return
+
+		assert is_path_mountpoint(self.mount_parent_abs_path)
+
+
 	def destroy_a_childfs(self):
 
 		if not self.fs_type == TEST_FS_LOGGEDFS:

tests/lib/climount.py

@@ -78,11 +78,13 @@ def quick_cli_destroy_parentfs():
 
 	fs = fstest_base_class()
 	fs.init_a_members()
+	fs.assert_parentfs_mountpoint()
 	fs.destroy_b_parentfs()
 
 
 def quick_cli_destroy_childfs():
 
 	fs = fstest_base_class()
 	fs.init_a_members()
+	fs.assert_childfs_mountpoint()
 	fs.destroy_a_childfs()

tests/lib/mount.py

@@ -75,8 +75,9 @@ def mount_loggedfs_python(in_abs_path, logfile, cfgfile, sudo = False):
 			os.path.join(os.environ['VIRTUAL_ENV'], 'bin', 'loggedfs'),
 			'-l', logfile,
 			'-c', cfgfile,
-			'-p', in_abs_path,
-			'-s'
+			'-p',
+			'-s',
+			in_abs_path,
 			],
 		return_output = True, sudo = sudo, sudo_env = sudo
 		)

tests/lib/procio.py

@@ -176,7 +176,7 @@ def download_file(in_url):
 
 def dump_yaml(filename, data):
 
-	f = open(filename, 'w+')
+	f = open(filename, 'w')
 	dump(data, f, Dumper = Dumper, default_flow_style = False)
 	f.close()
 
@@ -199,6 +199,6 @@ def read_file(filename):
 
 def write_file(filename, data):
 
-	f = open(filename, 'w+')
+	f = open(filename, 'w')
 	f.write(data)
 	f.close()

fsx renamed to tests/scripts/fsx

@@ -4,7 +4,7 @@
 # Filesystem monitoring with Fuse and Python
 # https://github.com/pleiszenburg/loggedfs-python
 #
-#	fsx: Development script for running fsx-linux
+#	tests/scripts/fsx: Development script for running fsx-linux
 #
 # 	Copyright (C) 2017-2018 Sebastian M. Ernst <[email protected]>
 #
@@ -25,7 +25,7 @@ FN=iotest
 
 make init
 cd tests/test_mount/test_child/
-fsx-linux -d -d -N 100 $FN -P ../../test_logs
+fsx-linux -d -d -N 1000 $FN -P ../../test_logs
 cd ../../..
 make destroy_childfs
 cp -a tests/test_mount/test_child/$FN tests/test_logs/$FN.fsxactual