python logging fixes

diff --git a/plugins.d/python.d.plugin b/plugins.d/python.d.plugin
index b729c3214391ebd11247a69f97e7b94c1360dca7..9fe4373ce818d993df19149b3738b683a8604fb3 100755 (executable)
--- a/plugins.d/python.d.plugin
+++ b/plugins.d/python.d.plugin
@@ -477,7 +477,7 @@ def run():
     configfile = CONFIG_DIR + "python.d.conf"
     msg.PROGRAM = PROGRAM
     msg.info("reading configuration file:", configfile)
-    log_counter = 200
+    log_throttle = 200
     log_interval = 3600
 
     conf = read_config(configfile)
@@ -498,7 +498,7 @@ def run():
         except (KeyError, TypeError):
             pass
         try:
-            log_counter = conf['logs_per_interval']
+            log_throttle = conf['logs_per_interval']
         except (KeyError, TypeError):
             pass
         try:
@@ -514,8 +514,10 @@ def run():
     # parse passed command line arguments
     modules = parse_cmdline(MODULES_DIR, *sys.argv)
     msg.DEBUG_FLAG = DEBUG_FLAG
-    msg.LOG_COUNTER = log_counter
+    msg.LOG_THROTTLE = log_throttle
     msg.LOG_INTERVAL = log_interval
+    msg.LOG_COUNTER = 0
+    msg.LOG_NEXT_CHECK = 0
     msg.info("MODULES_DIR='" + MODULES_DIR +
              "', CONFIG_DIR='" + CONFIG_DIR +
              "', UPDATE_EVERY=" + str(BASE_CONFIG['update_every']) +

diff --git a/python.d/python_modules/base.py b/python.d/python_modules/base.py
index c92b9c9749476b32f7ab16d5f6c607a2dba53e1a..14c7ca11401c99322fb291db4a2f8b118f768c0a 100644 (file)
--- a/python.d/python_modules/base.py
+++ b/python.d/python_modules/base.py
@@ -119,6 +119,7 @@ class SimpleService(threading.Thread):
         t_start = time.time()
         timetable = self.timetable
         chart_name = self.chart_name
+
         # check if it is time to execute job update() function
         if timetable['next'] > t_start:
             self.debug(chart_name, "will be run in", str(int((timetable['next'] - t_start) * 1000)), "ms")
@@ -129,20 +130,22 @@ class SimpleService(threading.Thread):
                    "ready to run, after", str(int((t_start - timetable['last']) * 1000)),
                    "ms (update_every:", str(timetable['freq'] * 1000),
                    "ms, latency:", str(int((t_start - timetable['next']) * 1000)), "ms")
+
         if self.__first_run:
             since_last = 0
+
         if not self.update(since_last):
             self.error("update function failed.")
             return False
+
         t_end = time.time()
         self.timetable['next'] = t_end - (t_end % timetable['freq']) + timetable['freq']
+
         # draw performance graph
         run_time = str(int((t_end - t_start) * 1000))
         # noinspection SqlNoDataSourceInspection
         print("BEGIN netdata.plugin_pythond_%s %s\nSET run_time = %s\nEND\n" %
               (self.chart_name, str(since_last), run_time))
-        # sys.stdout.write("BEGIN netdata.plugin_pythond_%s %s\nSET run_time = %s\nEND\n" %
-        #                  (self.chart_name, str(since_last), run_time))
 
         self.debug(chart_name, "updated in", str(run_time), "ms")
         self.timetable['last'] = t_start
@@ -156,21 +159,24 @@ class SimpleService(threading.Thread):
         :return: None
         """
         self.timetable['last'] = time.time()
+        self.debug("starting data collection - update frequency: " + str(self.update_every) + ", retries allowed: " + str(self.retries))
         while True:  # run forever, unless something is wrong
             try:
                 status = self._run_once()
             except Exception as e:
-                self.error("Something wrong: ", str(e))
+                self.alert("internal error - aborting data collection: " + str(e))
                 return
+
             if status:  # handle retries if update failed
                 time.sleep(self.timetable['next'] - time.time())
                 self.retries_left = self.retries
             else:
                 self.retries_left -= 1
                 if self.retries_left <= 0:
-                    self.error("no more retries. Exiting")
+                    self.alert("failed to collect data - no more retries allowed - aborting data collection")
                     return
                 else:
+                    self.error("failed to collect data. " + str(self.retries_left) + " retries left.")
                     time.sleep(self.timetable['freq'])
 
     # --- CHART ---
@@ -318,6 +324,12 @@ class SimpleService(threading.Thread):
         """
         msg.error(self.chart_name, *params)
 
+    def alert(self, *params):
+        """
+        Show error message on stderr
+        """
+        msg.alert(self.chart_name, *params)
+
     def debug(self, *params):
         """
         Show debug message on stderr
@@ -509,15 +521,15 @@ class SocketService(SimpleService):
         self.__empty_request = "".encode()
         SimpleService.__init__(self, configuration=configuration, name=name)
 
-    def _socketerror(self, msg=None):
+    def _socketerror(self, message=None):
         if self.unix_socket is not None:
-            self.error("unix socket '" + self.unix_socket + "':", msg)
+            self.error("unix socket '" + self.unix_socket + "':", message)
         else:
             if self.__socket_config is not None:
                 af, socktype, proto, canonname, sa = self.__socket_config
-                self.error("socket to '" + str(sa[0]) + "' port " + str(sa[1]) + ":", msg)
+                self.error("socket to '" + str(sa[0]) + "' port " + str(sa[1]) + ":", message)
             else:
-                self.error("unknown socket:", msg)
+                self.error("unknown socket:", message)
 
     def _connect2socket(self, res=None):
         """
@@ -774,7 +786,7 @@ class LogService(SimpleService):
         try:
             self.log_path = str(self.configuration['path'])
         except (KeyError, TypeError):
-            self.error("No path to log specified. Using: '" + self.log_path + "'")
+            self.info("No path to log specified. Using: '" + self.log_path + "'")
 
         if os.access(self.log_path, os.R_OK):
             return True
@@ -829,13 +841,14 @@ class ExecutableService(SimpleService):
         try:
             self.command = str(self.configuration['command'])
         except (KeyError, TypeError):
-            self.error("No command specified. Using: '" + self.command + "'")
+            self.info("No command specified. Using: '" + self.command + "'")
         command = self.command.split(' ')
 
         for arg in command[1:]:
             if any(st in arg for st in self.bad_substrings):
                 self.error("Bad command argument:" + " ".join(self.command[1:]))
                 return False
+
         # test command and search for it in /usr/sbin or /sbin when failed
         base = command[0].split('/')[-1]
         if self._get_raw_data() is None:
@@ -843,8 +856,10 @@ class ExecutableService(SimpleService):
                 command[0] = prefix + base
                 if os.path.isfile(command[0]):
                     break
+
         self.command = command
         if self._get_data() is None or len(self._get_data()) == 0:
             self.error("Command", self.command, "returned no data")
             return False
+
         return True

diff --git a/python.d/python_modules/msg.py b/python.d/python_modules/msg.py
index e10819c28432b3fe53e739e438f233817fc606a5..acce1d0f3c7e526dcddbceb66e7b46a7aad7a69e 100644 (file)
--- a/python.d/python_modules/msg.py
+++ b/python.d/python_modules/msg.py
@@ -6,9 +6,10 @@ from time import time, strftime
 
 DEBUG_FLAG = False
 PROGRAM = ""
-LOG_COUNTER = 2
-LOG_INTERVAL = 5
-NEXT_CHECK = 0
+LOG_COUNTER = 0
+LOG_THROTTLE = 10000 # has to be too big during init
+LOG_INTERVAL = 1     # has to be too low during init
+LOG_NEXT_CHECK = 0
 
 WRITE = sys.stderr.write
 FLUSH = sys.stderr.flush
@@ -20,23 +21,36 @@ def log_msg(msg_type, *args):
     :param msg_type: str
     """
     global LOG_COUNTER
-    if not DEBUG_FLAG:
-        LOG_COUNTER -= 1
+    global LOG_THROTTLE
+    global LOG_INTERVAL
+    global LOG_NEXT_CHECK
     now = time()
-    if LOG_COUNTER >= 0:
+
+    if not DEBUG_FLAG:
+        LOG_COUNTER += 1
+
+    # WRITE("COUNTER " + str(LOG_COUNTER) + " THROTTLE " + str(LOG_THROTTLE) + " INTERVAL " + str(LOG_INTERVAL) + " NOW " + str(now) + " NEXT " + str(LOG_NEXT_CHECK) + "\n")
+
+    if LOG_COUNTER <= LOG_THROTTLE or msg_type == "FATAL" or msg_type == "ALERT":
         timestamp = strftime('%Y-%m-%d %X')
         msg = "%s: %s %s: %s" % (timestamp, PROGRAM, str(msg_type), " ".join(args))
         WRITE(msg + "\n")
         FLUSH()
+    elif LOG_COUNTER == LOG_THROTTLE + 1:
+        timestamp = strftime('%Y-%m-%d %X')
+        msg = "%s: python.d.plugin: throttling further log messages for %s seconds" % (timestamp, str(int(LOG_NEXT_CHECK + 0.5) - int(now)))
+        WRITE(msg + "\n")
+        FLUSH()
 
-    global NEXT_CHECK
-    if NEXT_CHECK <= now:
-        NEXT_CHECK = now - (now % LOG_INTERVAL) + LOG_INTERVAL
-        if LOG_COUNTER < 0:
+    if LOG_NEXT_CHECK <= now:
+        if LOG_COUNTER >= LOG_THROTTLE:
             timestamp = strftime('%Y-%m-%d %X')
-            msg = "%s: python.d.plugin: Prevented %s log messages from displaying" % (timestamp, str(0 - LOG_COUNTER))
+            msg = "%s: python.d.plugin: Prevented %s log messages from displaying" % (timestamp, str(LOG_COUNTER - LOG_THROTTLE))
             WRITE(msg + "\n")
             FLUSH()
+        LOG_NEXT_CHECK = now - (now % LOG_INTERVAL) + LOG_INTERVAL
+        LOG_COUNTER = 0
+
 
 
 def debug(*args):
@@ -56,6 +70,13 @@ def error(*args):
     log_msg("ERROR", *args)
 
 
+def alert(*args):
+    """
+    Print message on stderr.
+    """
+    log_msg("ALERT", *args)
+
+
 def info(*args):
     """
     Print message on stderr.
@@ -71,4 +92,4 @@ def fatal(*args):
     # using sys.stdout causes IOError: Broken Pipe
     print('DISABLE')
     # sys.stdout.write('DISABLE\n')
-    sys.exit(1)
\ No newline at end of file
+    sys.exit(1)