python logging fixes
Costa Tsaousis (ktsaou) committed
Nov 12, 2016 at 13:19 UTC
f5a1582c6acf8447d7bac5bcfafb6aab4b46a2bd
3 files changed
+63
-25
plugins.d/python.d.plugin
+5
-3
@@ -477,7 +477,7 @@ def run():
477
configfile = CONFIG_DIR + "python.d.conf"
478
msg.PROGRAM = PROGRAM
479
msg.info("reading configuration file:", configfile)
480
- log_counter = 200
480
+ log_throttle = 200
481
log_interval = 3600
482
483
conf = read_config(configfile)
@@ -498,7 +498,7 @@ def run():
498
except (KeyError, TypeError):
499
pass
500
try:
501
- log_counter = conf['logs_per_interval']
501
+ log_throttle = conf['logs_per_interval']
502
except (KeyError, TypeError):
503
pass
504
try:
@@ -514,8 +514,10 @@ def run():
514
# parse passed command line arguments
515
modules = parse_cmdline(MODULES_DIR, *sys.argv)
516
msg.DEBUG_FLAG = DEBUG_FLAG
517
- msg.LOG_COUNTER = log_counter
517
+ msg.LOG_THROTTLE = log_throttle
518
msg.LOG_INTERVAL = log_interval
519
+ msg.LOG_COUNTER = 0
520
+ msg.LOG_NEXT_CHECK = 0
521
msg.info("MODULES_DIR='" + MODULES_DIR +
522
"', CONFIG_DIR='" + CONFIG_DIR +
523
"', UPDATE_EVERY=" + str(BASE_CONFIG['update_every']) +
python.d/python_modules/base.py
+25
-10
@@ -119,6 +119,7 @@ class SimpleService(threading.Thread):
119
t_start = time.time()
120
timetable = self.timetable
121
chart_name = self.chart_name
122
+
123
# check if it is time to execute job update() function
124
if timetable['next'] > t_start:
125
self.debug(chart_name, "will be run in", str(int((timetable['next'] - t_start) * 1000)), "ms")
@@ -129,20 +130,22 @@ class SimpleService(threading.Thread):
130
"ready to run, after", str(int((t_start - timetable['last']) * 1000)),
131
"ms (update_every:", str(timetable['freq'] * 1000),
132
"ms, latency:", str(int((t_start - timetable['next']) * 1000)), "ms")
133
+
134
if self.__first_run:
135
since_last = 0
136
+
137
if not self.update(since_last):
138
self.error("update function failed.")
139
return False
140
+
141
t_end = time.time()
142
self.timetable['next'] = t_end - (t_end % timetable['freq']) + timetable['freq']
143
+
144
# draw performance graph
145
run_time = str(int((t_end - t_start) * 1000))
146
# noinspection SqlNoDataSourceInspection
147
print("BEGIN netdata.plugin_pythond_%s %s\nSET run_time = %s\nEND\n" %
148
(self.chart_name, str(since_last), run_time))
144
- # sys.stdout.write("BEGIN netdata.plugin_pythond_%s %s\nSET run_time = %s\nEND\n" %
145
- # (self.chart_name, str(since_last), run_time))
149
150
self.debug(chart_name, "updated in", str(run_time), "ms")
151
self.timetable['last'] = t_start
@@ -156,21 +159,24 @@ class SimpleService(threading.Thread):
159
:return: None
160
"""
161
self.timetable['last'] = time.time()
162
+ self.debug("starting data collection - update frequency: " + str(self.update_every) + ", retries allowed: " + str(self.retries))
163
while True: # run forever, unless something is wrong
164
try:
165
status = self._run_once()
166
except Exception as e:
163
- self.error("Something wrong: ", str(e))
167
+ self.alert("internal error - aborting data collection: " + str(e))
168
return
169
+
170
if status: # handle retries if update failed
171
time.sleep(self.timetable['next'] - time.time())
172
self.retries_left = self.retries
173
else:
174
self.retries_left -= 1
175
if self.retries_left <= 0:
171
- self.error("no more retries. Exiting")
176
+ self.alert("failed to collect data - no more retries allowed - aborting data collection")
177
return
178
else:
179
+ self.error("failed to collect data. " + str(self.retries_left) + " retries left.")
180
time.sleep(self.timetable['freq'])
181
182
# --- CHART ---
@@ -318,6 +324,12 @@ class SimpleService(threading.Thread):
324
"""
325
msg.error(self.chart_name, *params)
326
327
+ def alert(self, *params):
328
+ """
329
+ Show error message on stderr
330
+ """
331
+ msg.alert(self.chart_name, *params)
332
+
333
def debug(self, *params):
334
"""
335
Show debug message on stderr
@@ -509,15 +521,15 @@ class SocketService(SimpleService):
521
self.__empty_request = "".encode()
522
SimpleService.__init__(self, configuration=configuration, name=name)
523
512
- def _socketerror(self, msg=None):
524
+ def _socketerror(self, message=None):
525
if self.unix_socket is not None:
514
- self.error("unix socket '" + self.unix_socket + "':", msg)
526
+ self.error("unix socket '" + self.unix_socket + "':", message)
527
else:
528
if self.__socket_config is not None:
529
af, socktype, proto, canonname, sa = self.__socket_config
518
- self.error("socket to '" + str(sa[0]) + "' port " + str(sa[1]) + ":", msg)
530
+ self.error("socket to '" + str(sa[0]) + "' port " + str(sa[1]) + ":", message)
531
else:
520
- self.error("unknown socket:", msg)
532
+ self.error("unknown socket:", message)
533
534
def _connect2socket(self, res=None):
535
"""
@@ -774,7 +786,7 @@ class LogService(SimpleService):
786
try:
787
self.log_path = str(self.configuration['path'])
788
except (KeyError, TypeError):
777
- self.error("No path to log specified. Using: '" + self.log_path + "'")
789
+ self.info("No path to log specified. Using: '" + self.log_path + "'")
790
791
if os.access(self.log_path, os.R_OK):
792
return True
@@ -829,13 +841,14 @@ class ExecutableService(SimpleService):
841
try:
842
self.command = str(self.configuration['command'])
843
except (KeyError, TypeError):
832
- self.error("No command specified. Using: '" + self.command + "'")
844
+ self.info("No command specified. Using: '" + self.command + "'")
845
command = self.command.split(' ')
846
847
for arg in command[1:]:
848
if any(st in arg for st in self.bad_substrings):
849
self.error("Bad command argument:" + " ".join(self.command[1:]))
850
return False
851
+
852
# test command and search for it in /usr/sbin or /sbin when failed
853
base = command[0].split('/')[-1]
854
if self._get_raw_data() is None:
@@ -843,8 +856,10 @@ class ExecutableService(SimpleService):
856
command[0] = prefix + base
857
if os.path.isfile(command[0]):
858
break
859
+
860
self.command = command
861
if self._get_data() is None or len(self._get_data()) == 0:
862
self.error("Command", self.command, "returned no data")
863
return False
864
+
865
return True
python.d/python_modules/msg.py
+33
-12
@@ -6,9 +6,10 @@ from time import time, strftime
6
7
DEBUG_FLAG = False
8
PROGRAM = ""
9
-LOG_COUNTER = 2
10
-LOG_INTERVAL = 5
11
-NEXT_CHECK = 0
9
+LOG_COUNTER = 0
10
+LOG_THROTTLE = 10000 # has to be too big during init
11
+LOG_INTERVAL = 1 # has to be too low during init
12
+LOG_NEXT_CHECK = 0
13
14
WRITE = sys.stderr.write
15
FLUSH = sys.stderr.flush
@@ -20,23 +21,36 @@ def log_msg(msg_type, *args):
21
:param msg_type: str
22
"""
23
global LOG_COUNTER
23
- if not DEBUG_FLAG:
24
- LOG_COUNTER -= 1
24
+ global LOG_THROTTLE
25
+ global LOG_INTERVAL
26
+ global LOG_NEXT_CHECK
27
now = time()
26
- if LOG_COUNTER >= 0:
28
+
29
+ if not DEBUG_FLAG:
30
+ LOG_COUNTER += 1
31
+
32
+ # WRITE("COUNTER " + str(LOG_COUNTER) + " THROTTLE " + str(LOG_THROTTLE) + " INTERVAL " + str(LOG_INTERVAL) + " NOW " + str(now) + " NEXT " + str(LOG_NEXT_CHECK) + "\n")
33
+
34
+ if LOG_COUNTER <= LOG_THROTTLE or msg_type == "FATAL" or msg_type == "ALERT":
35
timestamp = strftime('%Y-%m-%d %X')
36
msg = "%s: %s %s: %s" % (timestamp, PROGRAM, str(msg_type), " ".join(args))
37
WRITE(msg + "\n")
38
FLUSH()
39
+ elif LOG_COUNTER == LOG_THROTTLE + 1:
40
+ timestamp = strftime('%Y-%m-%d %X')
41
+ msg = "%s: python.d.plugin: throttling further log messages for %s seconds" % (timestamp, str(int(LOG_NEXT_CHECK + 0.5) - int(now)))
42
+ WRITE(msg + "\n")
43
+ FLUSH()
44
32
- global NEXT_CHECK
33
- if NEXT_CHECK <= now:
34
- NEXT_CHECK = now - (now % LOG_INTERVAL) + LOG_INTERVAL
35
- if LOG_COUNTER < 0:
45
+ if LOG_NEXT_CHECK <= now:
46
+ if LOG_COUNTER >= LOG_THROTTLE:
47
timestamp = strftime('%Y-%m-%d %X')
37
- msg = "%s: python.d.plugin: Prevented %s log messages from displaying" % (timestamp, str(0 - LOG_COUNTER))
48
+ msg = "%s: python.d.plugin: Prevented %s log messages from displaying" % (timestamp, str(LOG_COUNTER - LOG_THROTTLE))
49
WRITE(msg + "\n")
50
FLUSH()
51
+ LOG_NEXT_CHECK = now - (now % LOG_INTERVAL) + LOG_INTERVAL
52
+ LOG_COUNTER = 0
53
+
54
55
56
def debug(*args):
@@ -56,6 +70,13 @@ def error(*args):
70
log_msg("ERROR", *args)
71
72
73
+def alert(*args):
74
+ """
75
+ Print message on stderr.
76
+ """
77
+ log_msg("ALERT", *args)
78
+
79
+
80
def info(*args):
81
"""
82
Print message on stderr.
@@ -71,4 +92,4 @@ def fatal(*args):
92
# using sys.stdout causes IOError: Broken Pipe
93
print('DISABLE')
94
# sys.stdout.write('DISABLE\n')
74
- sys.exit(1)
\ No newline at end of file
95
+ sys.exit(1)