Repository: cvmfs/collectd-cvmfs

Issue:
collectd could get stuck in some cases if autofs hangs while mounting the repository
On SLC6 nodes I have spotted some scenarios where collectd could get stuck while trying to the the `MountTime` for a cvmfs repository.

In the affected nodes, you would see an autofs in a state like this:
```
root      7065  0.0  0.0 606552  1316 ?        Ssl  Oct10   1:29 automount --pid-file /var/run/autofs.pid
root     31188  0.0  0.0 111756   544 ?        S    Oct17   0:00  \_ /bin/mount -t cvmfs ilc.desy.de /cvmfs/ilc.desy.de
root     31189  0.0  0.0  16224   748 ?        S    Oct17   0:00      \_ /sbin/mount.cvmfs ilc.desy.de /cvmfs/ilc.desy.de -o rw
cvmfs    31209 99.9  0.0  68504  1056 ?        R    Oct17 9685:47          \_ /usr/bin/cvmfs2 -o rw,fsname=cvmfs2,allow_other,grab_mountpoin
```
In this state, `os.listdir` will hang forever and not event collectd will be able to kill it after an interval.

I have tried an alternative implementation using thread to run `listdir` but the `start()` call to the thread hangs as well and it cannot reach the next step: to join the thread with a timeout.

After some tests, it was found that the `scandir` package does a better job, being able to run it in a thread and kill it.

Even if collectd is able to kill scandir after a problematic interval, I think a more sensible approach would be to define a timeout for attempts to mount a given repo. Something like this:

```
    import scandir
    def async_scandir(self, repo_mountpoint, timeout):
        contents = []
        t = threading.Thread(target=lambda: contents.extend(scandir(repo_mountpoint)))
        t.daemon = True
        t.start()
        t.join(timeout)
        if t.is_alive():
            raise Exception('Scandir timed out')
        return contents
```

Discussion:
luisfdez: With the latest code, the _user experience_ will be things like:
```
$ grep cvmfs /var/log/collectd.log
[2019-07-25 10:36:59] cvmfs: failed to get MountTime for repo atlas-condb.cern.ch: Scandir timed out after 30 seconds

$ collectdctl getval hostname.domain.ch/cvmfs-atlas-condb.cern.ch/timedout-mount
value=1.000000e+00
```

Patch:
diff --git a/.gitignore b/.gitignore
index c274220..a76c8a4 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,14 +1,13 @@
-*.pyc
-
-.installed.cfg
-bin
-develop-eggs
-
-*.egg-info
-
-tmp
-build
-dist
-
-.pytest_cache
+*.pyc
+
+.installed.cfg
+bin
+develop-eggs
+
+*.egg-info
+
+tmp
+build
+dist
+.pytest_cache
 .tox
\ No newline at end of file
diff --git a/README.rst b/README.rst
index 8c4386d..5d54aad 100644
--- a/README.rst
+++ b/README.rst
@@ -16,6 +16,7 @@ Example::
         Repo "ams.cern.ch"
 
         MountTime True
+        MountTimeout 10
         Memory True
 
         Attribute ndownload nioerr
@@ -31,6 +32,7 @@ Example::
 * ``TypesDB``: types used by the plugin and shipped with the package. 
 * ``Repo``: cvmfs repository to monitor.
 * ``MountTime``: boolean value to specify whether mount time should be reported or not.
+* ``MountTimeout``: timeout in seconds while trying to mount the repositories.
 * ``Memory``: boolean value to specify whether the memory footprint should be reported or not.
 * ``Attribute``: attribute to monitor on the given repositories. You can get the list from of valid attributes from the type db in ``resources/collectd_cvmfs.db``.
 * ``Interval``: interval in seconds to probe the CVMFS repositories.
@@ -45,14 +47,14 @@ The metrics are published in the following structure::
 
     Plugin: cvmfs
     PluginInstance: <repo>
-    Type: {<Attribute>|MountTime|Memory}
+    Type: {<Attribute>|MountTime|Memory|Mountok}
     
     # Only with Memory:
     TypeInstance: [rss|vms]
 
-
 Example::
 
     lxplus123.cern.ch/cvmfs-lhcb.cern.ch/mounttime values=[0.000999927520751953]
     lxplus123.cern.ch/cvmfs-lhcb.cern.ch/nioerr values=[0]
     lxplus123.cern.ch/cvmfs-lhcb.cern.ch/memory-rss values=[31760384]
+    lxplus123.cern.ch/cvmfs-repo.domain.ch/mountok values=[1]
\ No newline at end of file
diff --git a/resources/collectd_cvmfs.db b/resources/collectd_cvmfs.db
index 47323b6..74c4d42 100644
--- a/resources/collectd_cvmfs.db
+++ b/resources/collectd_cvmfs.db
@@ -1,6 +1,9 @@
 # Shows the time that takes to ls a repository
 mounttime value:GAUGE:0:u
 
+# Shows whether a mount command succeeded (1) or not (0)
+mountok value:GAUGE:0:1
+
 # Attributes
 # http://cvmfs.readthedocs.io/en/stable/cpt-details.html#getxattr
 
diff --git a/setup.py b/setup.py
index f418fe8..e2294b3 100644
--- a/setup.py
+++ b/setup.py
@@ -9,7 +9,8 @@ version = '1.1.0'
 
 install_requires = [
     'xattr',
-    'psutil'
+    'psutil',
+    'scandir;python_version<"3.5"'
 ]
 
 
diff --git a/src/collectd_cvmfs/__init__.py b/src/collectd_cvmfs/__init__.py
index 51b7c80..75a162e 100644
--- a/src/collectd_cvmfs/__init__.py
+++ b/src/collectd_cvmfs/__init__.py
@@ -2,15 +2,22 @@ import collectd
 import xattr
 import os
 import psutil
+import threading
 import time
 import uuid
 
+try:
+    from os import scandir
+except ImportError:
+    from scandir import scandir
+
 CVMFS_ROOT = '/cvmfs'
 PLUGIN_NAME = 'cvmfs'
 
 CONFIG_DEFAULT_MEMORY = True
 CONFIG_DEFAULT_MOUNTTIME = True
 CONFIG_DEFAULT_INTERVAL = -1
+CONFIG_DEFAULT_MOUNTTIMEOUT = 5
 
 class CvmfsProbeConfig(object):
     def __init__(self):
@@ -18,6 +25,7 @@ class CvmfsProbeConfig(object):
         self.attributes = []
         self.memory = CONFIG_DEFAULT_MEMORY
         self.mounttime = CONFIG_DEFAULT_MOUNTTIME
+        self.mounttimeout = CONFIG_DEFAULT_MOUNTTIMEOUT
         self.interval = CONFIG_DEFAULT_INTERVAL
         self.config_name = uuid.uuid4().hex
         self.verbose = False
@@ -33,17 +41,31 @@ class CvmfsProbeConfig(object):
             self.verbose
         )
 
+
 class CvmfsProbe(object):
     def debug(self, msg, verbose=False):
         if verbose:
             collectd.info('{0} plugin: {1}'.format(PLUGIN_NAME, msg))
 
-    def read_mounttime(self, repo_mountpoint):
+
+    def safe_scandir(self, directory, timeout):
+        contents = []
+        t = threading.Thread(target=lambda: contents.extend(scandir(directory)))
+        t.daemon = True
+        t.start()
+        t.join(timeout)
+        if t.is_alive():
+            raise Exception("Scandir timed out after {0} seconds".format(timeout))
+        return contents
+
+
+    def read_mounttime(self, repo_mountpoint, timeout):
         start = time.time()
-        os.listdir(repo_mountpoint)
+        self.safe_scandir(repo_mountpoint, timeout)
         end = time.time()
         return end - start
 
+
     def read(self, config):
         self.debug("probing config: {0}".format((config)), config.verbose)
         val = collectd.Values(plugin=PLUGIN_NAME)
@@ -52,11 +74,14 @@ class CvmfsProbe(object):
             val.interval = config.interval
             repo_mountpoint = os.path.join(CVMFS_ROOT, repo)
 
-            if config.mounttime:
-                try:
-                    val.dispatch(type='mounttime', values=[self.read_mounttime(repo_mountpoint)], interval=config.interval)
-                except Exception:
-                    collectd.warning('cvmfs: failed to get MountTime for repo %s' % repo)
+            try:
+                mounttime = self.read_mounttime(repo_mountpoint, config.mounttimeout)
+                if config.mounttime:
+                    val.dispatch(type='mounttime', values=[mounttime], interval=config.interval)
+                    val.dispatch(type='mountok', values=[1], interval=config.interval)
+            except Exception as e:
+                collectd.warning('cvmfs: failed to get MountTime for repo %s: %s' % (repo, e))
+                val.dispatch(type='mountok', values=[0], interval=config.interval)
 
             if config.memory:
                 try:
@@ -74,6 +99,7 @@ class CvmfsProbe(object):
                 except Exception:
                     collectd.warning('cvmfs: failed to inspect attribute "%s" in  repo "%s"' % (attribute_name, repo_mountpoint))
 
+
     def str2bool(self, boolstr):
         if boolstr.lower() == 'true':
             return True
@@ -101,6 +127,8 @@ class CvmfsProbe(object):
                     config.mounttime = self.str2bool(node.values[0])
                 except:
                     collectd.info("cvmfs: MountTime value %s is not valid. It must be either True or False" % (node.values[0]))
+            elif key == 'mounttimeout':
+                config.mounttimeout = int(node.values[0])
             elif key == 'interval':
                 config.interval = int(node.values[0])
             elif key == 'verbose':
diff --git a/tox.ini b/tox.ini
index b59ef8e..c2389f7 100644
--- a/tox.ini
+++ b/tox.ini
@@ -1,5 +1,5 @@
 [tox]
-envlist = py27,py35
+envlist = py27,py34,py35
 
 [testenv]
 changedir=tests


Test patch:
diff --git a/tests/test_collectd_cvmfs.py b/tests/test_collectd_cvmfs.py
index 63e41fd..854bd06 100644
--- a/tests/test_collectd_cvmfs.py
+++ b/tests/test_collectd_cvmfs.py
@@ -4,8 +4,8 @@ import pytest
 from mock import MagicMock, Mock, mock_open, patch
 
 configure_data = [
-    (["ams.cern.ch"], ["nioerr"], True, True, 200),
-    (["alice.cern.ch", "atlas.cern.ch", "cms.cern.cn"], ["ndownload", "nioerr", "usedfd"], False, False, 200)
+    (["ams.cern.ch"], ["nioerr"], True, True, 30, 200),
+    (["alice.cern.ch", "atlas.cern.ch", "cms.cern.cn"], ["ndownload", "nioerr", "usedfd"], False, False, 30, 200)
 ]
 
 MOCK_METRICS_XATTR = 2
@@ -40,12 +40,13 @@ def test_configure_defaults(collectd_cvmfs):
         assert probe_config.attributes == []
         assert probe_config.memory == collectd_cvmfs.CONFIG_DEFAULT_MEMORY
         assert probe_config.mounttime == collectd_cvmfs.CONFIG_DEFAULT_MOUNTTIME
+        assert probe_config.mounttimeout == collectd_cvmfs.CONFIG_DEFAULT_MOUNTTIMEOUT
         assert args_sent['name'] == probe_config.config_name
         assert args_sent['callback'] == probe_instance.read
 
 
-@pytest.mark.parametrize("repos,attributes,memory,mounttime,interval", configure_data)
-def test_configure_single_ok(collectd_cvmfs, repos, attributes, memory, mounttime, interval):
+@pytest.mark.parametrize("repos,attributes,memory,mounttime,mounttimeout,interval", configure_data)
+def test_configure_single_ok(collectd_cvmfs, repos, attributes, memory, mounttime, mounttimeout, interval):
     # TODO: Simplify/fixturize the config init logic
     config = Mock()
     config.children = [
@@ -53,6 +54,7 @@ def test_configure_single_ok(collectd_cvmfs, repos, attributes, memory, mounttim
         Mock(key = 'Attribute', values = attributes),
         Mock(key = 'Memory', values = [str(memory)]),
         Mock(key = 'MountTime', values = [str(mounttime)]),
+        Mock(key = 'MountTimeout', values =[str(mounttimeout)]),
         Mock(key = 'Interval', values=[str(interval)])
     ]
 
@@ -69,19 +71,21 @@ def test_configure_single_ok(collectd_cvmfs, repos, attributes, memory, mounttim
         assert probe_config.attributes == attributes
         assert probe_config.memory == memory
         assert probe_config.mounttime == mounttime
+        assert probe_config.mounttimeout == mounttimeout
         assert args_sent['name'] == probe_config.config_name
         assert args_sent['callback'] == probe_instance.read
         assert args_sent['interval'] == interval
 
 
-@pytest.mark.parametrize("repos,attributes,memory,mounttime,interval", configure_data)
-def test_configure_multiple_ok(collectd_cvmfs, repos, attributes, memory, mounttime, interval):
+@pytest.mark.parametrize("repos,attributes,memory,mounttime,mounttimeout,interval", configure_data)
+def test_configure_multiple_ok(collectd_cvmfs, repos, attributes, memory, mounttime, mounttimeout, interval):
     # TODO: Simplify/fixturize the config init logic
     config = Mock()
     config.children = [Mock(key = 'Repo', values = [repo]) for repo in repos] + \
         [Mock(key = 'Attribute', values = [attr]) for attr in attributes] + \
         [Mock(key = 'Memory', values = [str(memory)]),
         Mock(key = 'MountTime', values = [str(mounttime)]),
+        Mock(key = 'MountTimeout', values =[str(mounttimeout)]),
         Mock(key = 'Interval', values=[str(interval)])]
 
     with patch('collectd.register_read') as register_mock:
@@ -123,8 +127,8 @@ def test_read_empty(collectd_cvmfs):
         val_mock.return_value.assert_not_called()
 
 
-@pytest.mark.parametrize("repos,attributes,memory,mounttime,interval", configure_data)
-def test_read_ok(collectd_cvmfs, repos, attributes, memory, mounttime, interval):
+@pytest.mark.parametrize("repos,attributes,memory,mounttime, mounttimeout, interval", configure_data)
+def test_read_ok(collectd_cvmfs, repos, attributes, memory, mounttime, mounttimeout, interval):
     # TODO: Simplify/fixturize the config init logic
     config = Mock()
     config.children = [
@@ -132,6 +136,7 @@ def test_read_ok(collectd_cvmfs, repos, attributes, memory, mounttime, interval)
         Mock(key = 'Attribute', values = attributes),
         Mock(key = 'Memory', values = [str(memory)]),
         Mock(key = 'MountTime', values = [str(mounttime)]),
+        Mock(key = 'MountTimeout', values =[str(mounttimeout)]),
         Mock(key = 'Interval', values=[str(interval)])
     ]
 
@@ -152,9 +157,37 @@ def test_read_ok(collectd_cvmfs, repos, attributes, memory, mounttime, interval)
                         collectd_cvmfs.collectd.Values.assert_called_once_with(plugin=collectd_cvmfs.PLUGIN_NAME)
                         if mounttime:
                             val_mock.return_value.dispatch.assert_any_call(type='mounttime', values=[MOCK_METRICS_MOUNTTIME], interval=probe_config.interval)
+                            val_mock.return_value.dispatch.assert_any_call(type='mountok', values=[1], interval=probe_config.interval)
                         if memory:
                             psutil_mock.assert_any_call(MOCK_METRICS_XATTR)
                             val_mock.return_value.dispatch.assert_any_call(type='memory', type_instance='rss', values=[MOCK_METRICS_MEM_RSS], interval=probe_config.interval)
                             val_mock.return_value.dispatch.assert_any_call(type='memory', type_instance='vms', values=[MOCK_METRICS_MEM_VMS], interval=probe_config.interval)
                         for attr in attributes:
-                            val_mock.return_value.dispatch.assert_any_call(type=attr, values=[MOCK_METRICS_XATTR], interval=probe_config.interval)
\ No newline at end of file
+                            val_mock.return_value.dispatch.assert_any_call(type=attr, values=[MOCK_METRICS_XATTR], interval=probe_config.interval)
+
+
+@pytest.mark.parametrize("repos,attributes,memory,mounttime,mounttimeout,interval", configure_data)
+def test_read_mounttime_failed(collectd_cvmfs, repos, attributes, memory, mounttime, mounttimeout, interval):
+    # TODO: Simplify/fixturize the config init logic
+    config = Mock()
+    config.children = [
+        Mock(key = 'Repo', values = repos),
+        Mock(key = 'Attribute', values = []),
+        Mock(key = 'Memory', values = ["false"]),
+        Mock(key = 'MountTime', values = [str(mounttime)]),
+        Mock(key = 'MountTimeout', values =[str(mounttimeout)]),
+        Mock(key = 'Interval', values=[str(interval)])
+    ]
+
+    probe_instance = collectd_cvmfs.CvmfsProbe()
+    probe_instance.configure(config)
+
+    with patch('collectd.register_read') as register_mock:
+        probe_instance.configure(config)
+        probe_config = register_mock.call_args[1]['data']
+
+        with patch('collectd_cvmfs.CvmfsProbe.safe_scandir', side_effect=Exception('Catacroc!')):
+            with patch('collectd.Values') as val_mock:
+                probe_instance.read(probe_config)
+                if mounttime:
+                    val_mock.return_value.dispatch.assert_any_call(type='mountok', values=[0], interval=probe_config.interval)
\ No newline at end of file