From 8d3335359e3785be35818b0c4519cc499f3f2fa8 Mon Sep 17 00:00:00 2001
From: Brett Smith <brett@curoverse.com>
Date: Mon, 21 Jul 2014 11:33:30 -0400
Subject: [PATCH] 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.
---
 services/fuse/arvados_fuse/__init__.py |  6 +--
 services/fuse/bin/arv-mount            | 59 +++++++++++++++++++-------
 2 files changed, 44 insertions(+), 21 deletions(-)

diff --git a/services/fuse/arvados_fuse/__init__.py b/services/fuse/arvados_fuse/__init__.py
index 2bbf137044..5d782d2641 100644
--- 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 b874f5ff5b..0f3e8719b9 100755
--- 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))
-- 
2.30.2