3303: Add logfile support to arv-mount.

The primary thrust of this commit is to teach arv-mount to log to a
file.  This can help make it easier to track down exceptions that
happen while the process is daemonized.

To support better logging information, it also sends exception
tracebacks directly to the log.  This required reorganizing the code
to daemonize earlier.

Refs #3303.

diff --git a/services/fuse/arvados_fuse/__init__.py b/services/fuse/arvados_fuse/__init__.py
index 2bbf137044023e5963a31063121df57483b4e9eb..5d782d2641133643546622b95713d88b8587b15b 100644 (file)
--- a/services/fuse/arvados_fuse/__init__.py
+++ b/services/fuse/arvados_fuse/__init__.py
@@ -416,13 +416,9 @@ class Operations(llfuse.Operations):
     so request handlers do not run concurrently unless the lock is explicitly released
     with llfuse.lock_released.'''
 
-    def __init__(self, uid, gid, debug=False):
+    def __init__(self, uid, gid):
         super(Operations, self).__init__()
 
-        if debug:
-            logging.basicConfig(level=logging.DEBUG)
-            logging.info("arv-mount debug enabled")
-
         self.inodes = Inodes()
         self.uid = uid
         self.gid = gid

diff --git a/services/fuse/bin/arv-mount b/services/fuse/bin/arv-mount
index b874f5ff5bfcb298a3085ab87d1037b20b398593..0f3e8719b9f683a6bedbed470b280b0b65d2f710 100755 (executable)
--- a/services/fuse/bin/arv-mount
+++ b/services/fuse/bin/arv-mount
@@ -3,9 +3,11 @@
 import argparse
 import arvados
 import daemon
+import logging
 import os
 import signal
 import subprocess
+import traceback
 
 from arvados_fuse import *
 
@@ -30,20 +32,41 @@ with "--".
 collections on the server.""")
     parser.add_argument('--groups', action='store_true', help="""Mount as a virtual directory consisting of subdirectories representing groups on the server.""")
     parser.add_argument('--debug', action='store_true', help="""Debug mode""")
+    parser.add_argument('--logfile', help="""Write debug logs and errors to the specified file (default stderr).""")
     parser.add_argument('--foreground', action='store_true', help="""Run in foreground (default is to daemonize unless --exec specified)""", default=False)
     parser.add_argument('--exec', type=str, nargs=argparse.REMAINDER,
                         dest="exec_args", metavar=('command', 'args', '...', '--'),
                         help="""Mount, run a command, then unmount and exit""")
 
     args = parser.parse_args()
+    args.mountpoint = os.path.realpath(args.mountpoint)
+    if args.logfile:
+        args.logfile = os.path.realpath(args.logfile)
 
-    # Create the request handler
-    operations = Operations(os.getuid(), os.getgid(), args.debug)
-
-    if args.debug:
-        arvados.config.settings()['ARVADOS_DEBUG'] = 'true'
+    # Daemonize as early as possible, so we don't accidentally close
+    # file descriptors we're using.
+    if not (args.exec_args or args.foreground):
+        os.chdir(args.mountpoint)
+        daemon_ctx = daemon.DaemonContext(working_directory='.')
+        daemon_ctx.open()
+    else:
+        daemon_ctx = None
+
+    # Set up logging.
+    # If we're daemonized without a logfile, there's nowhere to log, so don't.
+    if args.logfile or (daemon_ctx is None):
+        log_conf = {}
+        if args.debug:
+            log_conf['level'] = logging.DEBUG
+            arvados.config.settings()['ARVADOS_DEBUG'] = 'true'
+        if args.logfile:
+            log_conf['filename'] = args.logfile
+        logging.basicConfig(**log_conf)
+        logging.debug("arv-mount debugging enabled")
 
     try:
+        # Create the request handler
+        operations = Operations(os.getuid(), os.getgid())
         api = arvados.api('v1')
 
         if args.groups:
@@ -57,7 +80,8 @@ collections on the server.""")
             # Set up the request handler with the 'magic directory' at the root
             operations.inodes.add_entry(MagicDirectory(llfuse.ROOT_INODE, operations.inodes))
     except Exception as ex:
-        print("arv-mount: %s" % ex)
+        logging.error("arv-mount: exception during API setup")
+        logging.error(traceback.format_exc())
         exit(1)
 
     # FUSE options, see mount.fuse(8)
@@ -90,19 +114,22 @@ collections on the server.""")
             signal.signal(signal.SIGINT, signal.SIG_DFL)
             signal.signal(signal.SIGTERM, signal.SIG_DFL)
             signal.signal(signal.SIGQUIT, signal.SIG_DFL)
-        except OSError as e:
-            sys.stderr.write('arv-mount: %s -- exec %s\n' % (str(e), args.exec_args))
-            rc = e.errno
         except Exception as e:
-            sys.stderr.write('arv-mount: %s\n' % str(e))
+            logging.error('arv-mount: exception during exec %s' % (args.exec_args,))
+            logging.error(traceback.format_exc())
+            try:
+                rc = e.errno
+            except AttributeError:
+                pass
         finally:
             subprocess.call(["fusermount", "-u", "-z", args.mountpoint])
 
         exit(rc)
     else:
-        os.chdir(args.mountpoint)
-        if not args.foreground:
-            daemon_ctx = daemon.DaemonContext(working_directory='.')
-            daemon_ctx.open()
-        llfuse.init(operations, '.', opts)
-        llfuse.main()
+        try:
+            llfuse.init(operations, args.mountpoint, opts)
+            llfuse.main()
+        except Exception as e:
+            logging.error('arv-mount: exception during mount')
+            logging.error(traceback.format_exc())
+            exit(getattr(e, 'errno', 1))