diff --git a/docs/configuration.rst b/docs/configuration.rst --- a/docs/configuration.rst +++ b/docs/configuration.rst @@ -68,4 +68,4 @@ .. code:: bash - $ swh --log-level DEBUG fs mount swhfs/ + $ swh --log-level swh.fuse.fuse:DEBUG fs mount swhfs/ diff --git a/requirements-swh.txt b/requirements-swh.txt --- a/requirements-swh.txt +++ b/requirements-swh.txt @@ -1,4 +1,4 @@ # Add here internal Software Heritage dependencies, one per line. -swh.core +swh.core>=0.10.0 swh.model>=0.7.0 swh.web.client>=0.2.1 diff --git a/swh/fuse/cli.py b/swh/fuse/cli.py --- a/swh/fuse/cli.py +++ b/swh/fuse/cli.py @@ -148,7 +148,14 @@ "address": "/dev/log", }, }, - "root": {"level": ctx.obj["log_level"], "handlers": ["syslog"],}, + "loggers": { + fuse.Fuse.LOGGER_NAME: { + # XXX: "log_level" is the default one, but there is + # currently no way to retrieve specific logger log_level + "level": ctx.obj["log_level"], + "handlers": ["syslog"], + }, + }, } ) diff --git a/swh/fuse/fuse.py b/swh/fuse/fuse.py --- a/swh/fuse/fuse.py +++ b/swh/fuse/fuse.py @@ -28,6 +28,8 @@ """ Software Heritage Filesystem in Userspace (FUSE). Locally mount parts of the archive and navigate it as a virtual file system. """ + LOGGER_NAME = __name__ + def __init__( self, root_path: Path, cache: FuseCache, conf: Dict[str, Any], ): @@ -38,6 +40,7 @@ self.root = Root(fuse=self) self.conf = conf + self.logger = logging.getLogger(self.LOGGER_NAME) self.time_ns: int = time.time_ns() # start time, used as timestamp self.gid = os.getgid() @@ -87,7 +90,7 @@ # Retrieve it from cache so it is correctly typed return await self.cache.metadata.get(swhid) except requests.HTTPError as err: - logging.error("Cannot fetch metadata for object %s: %s", swhid, err) + self.logger.error("Cannot fetch metadata for object %s: %s", swhid, err) raise async def get_blob(self, swhid: SWHID) -> bytes: @@ -102,6 +105,7 @@ cache = await self.cache.blob.get(swhid) if cache: + self.logger.debug("get_blob: %s retrieved from cache", swhid) return cache try: @@ -109,9 +113,10 @@ resp = await loop.run_in_executor(None, self.web_api.content_raw, swhid) blob = b"".join(list(resp)) await self.cache.blob.set(swhid, blob) + self.logger.debug("get_blob: %s retrieved from Web API", swhid) return blob except requests.HTTPError as err: - logging.error("Cannot fetch blob for object %s: %s", swhid, err) + self.logger.error("Cannot fetch blob for object %s: %s", swhid, err) raise async def get_history(self, swhid: SWHID) -> List[SWHID]: @@ -122,6 +127,9 @@ cache = await self.cache.history.get(swhid) if cache: + self.logger.debug( + "get_history: %s retrieved from cache (%d parents)", swhid, len(cache) + ) return cache try: @@ -131,9 +139,13 @@ history = await loop.run_in_executor(None, self.web_api._call, call) await self.cache.history.set(history.text) # Retrieve it from cache so it is correctly typed - return await self.cache.history.get(swhid) + res = await self.cache.history.get(swhid) + self.logger.debug( + "get_history: %s retrieved from Graph API (%d parents)", swhid, len(res) + ) + return res except requests.HTTPError as err: - logging.error("Cannot fetch history for object %s: %s", swhid, err) + self.logger.error("Cannot fetch history for object %s: %s", swhid, err) # Ignore exception since swh-graph does not necessarily contain the # most recent artifacts from the archive. Computing the full history # from the Web API is too computationally intensive so simply return @@ -145,6 +157,11 @@ cache = await self.cache.metadata.get_visits(url_encoded) if cache: + self.logger.debug( + "get_visits: '%s', retrieved %d visits from cache", + url_encoded, + len(cache), + ) return cache try: @@ -158,9 +175,15 @@ visits = list(visits_it) await self.cache.metadata.set_visits(url_encoded, visits) # Retrieve it from cache so it is correctly typed - return await self.cache.metadata.get_visits(url_encoded) + res = await self.cache.metadata.get_visits(url_encoded) + self.logger.debug( + "get_visits: '%s', retrieved %d visits from Web API", + url_encoded, + len(res), + ) + return res except requests.HTTPError as err: - logging.error("Cannot fetch visits for object %s: %s", url_encoded, err) + self.logger.error("Cannot fetch visits for object %s: %s", url_encoded, err) raise async def get_attrs(self, entry: FuseEntry) -> pyfuse3.EntryAttributes: @@ -190,6 +213,7 @@ """ Open a directory referred by a given inode """ # Re-use inode as directory handle + self.logger.debug("opendir(inode=%d)", inode) return inode async def readdir(self, fh: int, offset: int, token: pyfuse3.ReaddirToken) -> None: @@ -198,6 +222,9 @@ # opendir() uses inode as directory handle inode = fh direntry = self.inode2entry(inode) + self.logger.debug( + "readdir(dirname=%s, fh=%d, offset=%d)", direntry.name, fh, offset + ) assert isinstance(direntry, FuseDirEntry) next_id = offset + 1 @@ -211,7 +238,7 @@ next_id += 1 self._inode2entry[attrs.st_ino] = entry except Exception as err: - logging.exception("Cannot readdir: %s", err) + self.logger.exception("Cannot readdir: %s", err) raise pyfuse3.FUSEError(errno.ENOENT) async def open( @@ -220,6 +247,7 @@ """ Open an inode and return a unique file handle """ # Re-use inode as file handle + self.logger.debug("open(inode=%d)", inode) return pyfuse3.FileInfo(fh=inode, keep_cache=True) async def read(self, fh: int, offset: int, length: int) -> bytes: @@ -229,12 +257,16 @@ inode = fh entry = self.inode2entry(inode) + self.logger.debug( + "read(name=%s, fh=%d, offset=%d, length=%d)", entry.name, fh, offset, length + ) assert isinstance(entry, FuseFileEntry) + try: data = await entry.get_content() return data[offset : offset + length] except Exception as err: - logging.exception("Cannot read: %s", err) + self.logger.exception("Cannot read: %s", err) raise pyfuse3.FUSEError(errno.ENOENT) async def lookup( @@ -244,18 +276,26 @@ name = os.fsdecode(name) parent_entry = self.inode2entry(parent_inode) + self.logger.debug( + "lookup(parent_name=%s, parent_inode=%d, name=%s)", + parent_entry.name, + parent_inode, + name, + ) assert isinstance(parent_entry, FuseDirEntry) + try: lookup_entry = await parent_entry.lookup(name) if lookup_entry: return await self.get_attrs(lookup_entry) except Exception as err: - logging.exception("Cannot lookup: %s", err) + self.logger.exception("Cannot lookup: %s", err) raise pyfuse3.FUSEError(errno.ENOENT) async def readlink(self, inode: int, _ctx: pyfuse3.RequestContext) -> bytes: entry = self.inode2entry(inode) + self.logger.debug("readlink(name=%s, inode=%d)", entry.name, inode) assert isinstance(entry, FuseSymlinkEntry) return os.fsencode(entry.get_target()) @@ -274,18 +314,16 @@ try: await fs.get_metadata(swhid) except Exception as err: - logging.exception("Cannot prefetch object %s: %s", swhid, err) + fs.looger.exception("Cannot prefetch object %s: %s", swhid, err) fuse_options = set(pyfuse3.default_options) fuse_options.add("fsname=swhfs") - if logging.root.level <= logging.DEBUG: - fuse_options.add("debug") try: pyfuse3.init(fs, root_path, fuse_options) await pyfuse3.main() except Exception as err: - logging.error("Error running FUSE: %s", err) + fs.logger.error("Error running FUSE: %s", err) finally: fs.shutdown() pyfuse3.close(unmount=True)