Merge pull request #340 from thomas-mangin/T2226-debug

cmd: T2226: improve debugging

4 files changed, 200 insertions, 51 deletions

diff --git a/python/vyos/airbag.py b/python/vyos/airbag.py
index 664974d5f..b0565192d 100644
--- a/python/vyos/airbag.py
+++ b/python/vyos/airbag.py
@@ -19,10 +19,10 @@ import logging
 import logging.handlers
 from datetime import datetime
 
+from vyos import debug
 from vyos.config import Config
 from vyos.version import get_version
 from vyos.util import run
-from vyos.util import debug
 
 
 # we allow to disable the extra logging
@@ -77,8 +77,7 @@ def bug_report(dtype, value, trace):
 # reach the end of __main__ and was not intercepted
 def intercepter(dtype, value, trace):
     bug_report(dtype, value, trace)
-    # debug returns either '' or 'developer' if debuging is enabled
-    if debug('developer'):
+    if debug.enabled('developer'):
         import pdb
         pdb.pm()
 
diff --git a/python/vyos/debug.py b/python/vyos/debug.py
new file mode 100644
index 000000000..20090fb85
--- /dev/null
+++ b/python/vyos/debug.py
@@ -0,0 +1,182 @@
+# Copyright 2019 VyOS maintainers and contributors <maintainers@vyos.io>
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public
+# License along with this library.  If not, see <http://www.gnu.org/licenses/>.
+
+import os
+import sys
+
+
+def message(message, flag='', destination=sys.stdout):
+    """
+    print a debug message line on stdout if debugging is enabled for the flag
+    also log it to a file if the flag 'log' is enabled
+
+    message: the message to print
+    flag: which flag must be set for it to print
+    destination: which file like object to write to (default: sys.stdout)
+
+    returns if any message was logged or not
+    """
+    enable = enabled(flag)
+    if enable:
+        destination.write(_format(flag,message))
+
+    # the log flag is special as it logs all the commands
+    # executed to a log
+    logfile = _logfile('log', '/tmp/developer-log')
+    if not logfile:
+        return enable
+
+    try:
+        # at boot the file is created as root:vyattacfg
+        # at runtime the file is created as user:vyattacfg
+        # the default permission are 644
+        mask = os.umask(0o113)
+
+        with open(logfile, 'a') as f:
+            f.write(_format('log', message))
+    finally:
+        os.umask(mask)
+
+    return enable
+
+
+def enabled(flag):
+    """
+    a flag can be set by touching the file in /tmp or /config
+
+    The current flags are:
+     - developer: the code will drop into PBD on un-handled exception
+     - log: the code will log all command to a file
+     - ifconfig: when modifying an interface,
+       prints command with result and sysfs access on stdout for interface
+     - command: print command run with result
+
+    Having the flag setup on the filesystem is required to have
+    debuging at boot time, however, setting the flag via environment
+    does not require a seek to the filesystem and is more efficient
+    it can be done on the shell on via .bashrc for the user
+
+    The function returns an empty string if the flag was not set otherwise
+    the function returns either the file or environment name used to set it up
+    """
+
+    # this is to force all new flags to be registered here to be
+    # documented both here and a reminder to update readthedocs :-)
+    if flag not in ['developer', 'log', 'ifconfig', 'command']:
+        return ''
+
+    return _fromenv(flag) or _fromfile(flag)
+
+
+def _format(flag, message):
+    """
+    format a log message
+    """
+    return f'DEBUG/{flag.upper():<7} {message}\n'
+
+
+def _fromenv(flag):
+    """
+    check if debugging is set for this flag via environment
+
+    For a given debug flag named "test"
+    The presence of the environment VYOS_TEST_DEBUG (uppercase) enables it
+
+    return empty string if not
+    return content of env value it is
+    """
+
+    flagname = f'VYOS_{flag.upper()}_DEBUG'
+    flagenv = os.environ.get(flagname, None)
+
+    if flagenv is None:
+        return ''
+    return flagenv
+
+
+def _fromfile(flag):
+    """
+    Check if debug exist for a given debug flag name
+
+    Check is a debug flag was set by the user. the flag can be set either:
+     - in /tmp for a non-persistent presence between reboot
+     - in /config for always on (an existence at boot time)
+
+    For a given debug flag named "test"
+    The presence of the file vyos.test.debug (all lowercase) enables it
+
+    The function returns an empty string if the flag was not set otherwise
+    the function returns the full flagname
+    """
+
+    for folder in ('/tmp', '/config'):
+        flagfile = f'{folder}/vyos.{flag}.debug'
+        if os.path.isfile(flagfile):
+            return flagfile
+
+    return ''
+
+
+def _contentenv(flag):
+    return os.environ.get(f'VYOS_{flag.upper()}_DEBUG', '').strip()
+
+
+def _contentfile(flag):
+    """
+    Check if debug exist for a given debug flag name
+
+    Check is a debug flag was set by the user. the flag can be set either:
+     - in /tmp for a non-persistent presence between reboot
+     - in /config for always on (an existence at boot time)
+
+    For a given debug flag named "test"
+    The presence of the file vyos.test.debug (all lowercase) enables it
+
+    The function returns an empty string if the flag was not set otherwise
+    the function returns the full flagname
+    """
+
+    for folder in ('/tmp', '/config'):
+        flagfile = f'{folder}/vyos.{flag}.debug'
+        if not os.path.isfile(flagfile):
+            continue
+        with open(flagfile) as f:
+            return f.readline().strip()
+
+    return ''
+
+
+def _logfile(flag, default):
+    """
+    return the name of the file to use for logging when the flag 'log' is set
+    if it could not be established or the location is invalid it returns
+    an empty string
+    """
+
+    # For log we return the location of the log file
+    log_location = _contentenv(flag) or _contentfile(flag)
+
+    # it was not set
+    if not log_location:
+        return ''
+
+    # Make sure that the logs can only be in /tmp, /var/log, or /tmp
+    if not log_location.startswith('/tmp/') and \
+       not log_location.startswith('/config/') and \
+       not log_location.startswith('/var/log/'):
+        return default
+    if '..' in log_location:
+        return default
+    return log_location
diff --git a/python/vyos/ifconfig/control.py b/python/vyos/ifconfig/control.py
index 464cd585e..7bb63beed 100644
--- a/python/vyos/ifconfig/control.py
+++ b/python/vyos/ifconfig/control.py
@@ -16,8 +16,9 @@
 
 import os
 
-from vyos.util import debug, debug_msg
-from vyos.util import popen, cmd
+from vyos import debug
+from vyos.util import popen
+from vyos.util import cmd
 from vyos.ifconfig.section import Section
 
 
@@ -35,10 +36,10 @@ class Control(Section):
         # if debug is not explicitely disabled the the config, enable it
         self.debug = ''
         if kargs.get('debug', True):
-            self.debug = debug('ifconfig')
+            self.debug = debug.enabled('ifconfig')
 
     def _debug_msg (self, message):
-        return debug_msg(message, self.debug)
+        return debug.message(message, self.debug)
 
     def _popen(self, command):
         return popen(command, self.debug)
diff --git a/python/vyos/util.py b/python/vyos/util.py
index 14020e2d9..49c47cd85 100644
--- a/python/vyos/util.py
+++ b/python/vyos/util.py
@@ -21,48 +21,7 @@ from subprocess import PIPE
 from subprocess import STDOUT
 from subprocess import DEVNULL
 
-
-def debug(flag):
-    """
-    Check is a debug flag was set by the user.
-    a flag can be set by touching the file /tmp/vyos.flag.debug
-    with flag being the flag name, the current flags are:
-     - developer: the code will drop into PBD on un-handled exception
-     - ifconfig: prints command and sysfs access on stdout for interface
-    The function returns an empty string if the flag was not set,
-    """
-
-    # this is to force all new flags to be registered here to be documented:
-    if flag not in ['developer', 'ifconfig']:
-        return ''
-    for folder in ('/tmp', '/config'):
-        if os.path.isfile(f'{folder}/vyos.{flag}.debug'):
-            return flag
-    return ''
-
-
-def debug_msg(message, flag=''):
-    """
-    print a debug message line on stdout if debugging is enabled for the flag
-    """
-
-    if debug(flag):
-        print(f'DEBUG/{flag:<6} {message}')
-
-    if not debug('developer'):
-        return
-
-    logfile = '/tmp/full-log'
-    existed = os.path.exists(logfile)
-
-    with open(logfile, 'a') as f:
-        f.write(f'DEBUG/{flag:<6} {message}\n')
-        if not existed:
-            # at boot the file is created as root:vyattacfg
-            # at runtime the file is created as user:vyattacfg
-            # do not use run/cmd to not have a recursive call to this code
-            os.system(f'chmod g+w {logfile}')
-
+from vyos import debug
 
 # There is many (too many) ways to run command with python
 # os.system, subprocess.Popen, subproces.{run,call,check_output}
@@ -98,7 +57,14 @@ def popen(command, flag='', shell=None, input=None, timeout=None, env=None,
     to get both stdout, and stderr: popen('command', stdout=PIPE, stderr=STDOUT)
     to discard stdout and get stderr: popen('command', stdout=DEVNUL, stderr=PIPE)
     """
-    debug_msg(f"cmd '{command}'", flag)
+
+    # log if the flag is set, otherwise log if command is set
+    if not debug.enabled(flag):
+        flag = 'command'
+
+    cmd_msg = f"cmd '{command}'"
+    debug.message(cmd_msg, flag)
+
     use_shell = shell
     stdin = None
     if shell is None:
@@ -129,7 +95,8 @@ def popen(command, flag='', shell=None, input=None, timeout=None, env=None,
     nl = '\n' if decoded1 and decoded2 else ''
     decoded = decoded1 + nl + decoded2
     if decoded:
-        debug_msg(f"returned:\n{decoded}", flag)
+        ret_msg = f"returned:\n{decoded}"
+        debug.message(ret_msg, flag)
     return decoded, p.returncode