fixed infinite loop in statsd apps; log is now locked to avoid multiplexing log lines
Costa Tsaousis (ktsaou) committed
May 2, 2017 at 22:19 UTC
40f5b0dfc37142bbb4f9d2ca2c2744342cc56a05
4 files changed
+114
-72
src/apps_plugin.c
-2
@@ -1730,7 +1730,6 @@ static inline int print_process_and_parents(struct pid_stat *p, usec_t time) {
1730
}
1731
1732
static inline void print_process_tree(struct pid_stat *p, char *msg) {
1733
- log_date(stderr);
1733
fprintf(stderr, "%s: process %s (%d, %s) with parents:\n", msg, p->comm, p->pid, p->updated?"running":"exited");
1734
print_process_and_parents(p, p->stat_collected_usec);
1735
}
@@ -1839,7 +1838,6 @@ static inline void process_exited_processes() {
1838
continue;
1839
1840
if(unlikely(debug)) {
1842
- log_date(stderr);
1841
fprintf(stderr, "Absorb %s (%d %s total resources: utime=" KERNEL_UINT_FORMAT " stime=" KERNEL_UINT_FORMAT " gtime=" KERNEL_UINT_FORMAT " minflt=" KERNEL_UINT_FORMAT " majflt=" KERNEL_UINT_FORMAT ")\n"
1842
, p->comm
1843
, p->pid
src/log.c
+102
-67
@@ -23,6 +23,37 @@ void syslog_init(void) {
23
}
24
}
25
26
+#define LOG_DATE_LENGTH 26
27
+
28
+static inline void log_date(char *buffer, size_t len) {
29
+ if(unlikely(!buffer || !len))
30
+ return;
31
+
32
+ time_t t;
33
+ struct tm *tmp, tmbuf;
34
+
35
+ t = now_realtime_sec();
36
+ tmp = localtime_r(&t, &tmbuf);
37
+
38
+ if (tmp == NULL) {
39
+ buffer[0] = '\0';
40
+ return;
41
+ }
42
+
43
+ if (unlikely(strftime(buffer, len, "%Y-%m-%d %H:%M:%S", tmp) == 0))
44
+ buffer[0] = '\0';
45
+
46
+ buffer[len - 1] = '\0';
47
+}
48
+
49
+static netdata_mutex_t log_mutex = NETDATA_MUTEX_INITIALIZER;
50
+static inline void log_lock() {
51
+ netdata_mutex_lock(&log_mutex);
52
+}
53
+static inline void log_unlock() {
54
+ netdata_mutex_unlock(&log_mutex);
55
+}
56
+
57
int open_log_file(int fd, FILE **fp, const char *filename, int *enabled_syslog) {
58
int f;
59
@@ -136,8 +167,10 @@ int error_log_limit(int reset) {
167
168
if(reset) {
169
if(prevented) {
139
- log_date(stderr);
140
- fprintf(stderr, "%s: Resetting logging for process '%s' (prevented %lu logs in the last %ld seconds).\n"
170
+ char date[LOG_DATE_LENGTH];
171
+ log_date(date, LOG_DATE_LENGTH);
172
+ fprintf(stderr, "%s: %s: Resetting logging for process '%s' (prevented %lu logs in the last %ld seconds).\n"
173
+ , date
174
, program_name
175
, program_name
176
, prevented
@@ -155,8 +188,10 @@ int error_log_limit(int reset) {
188
189
if(now - start > error_log_throttle_period) {
190
if(prevented) {
158
- log_date(stderr);
159
- fprintf(stderr, "%s: Resuming logging from process '%s' (prevented %lu logs in the last %ld seconds).\n"
191
+ char date[LOG_DATE_LENGTH];
192
+ log_date(date, LOG_DATE_LENGTH);
193
+ fprintf(stderr, "%s: %s: Resuming logging from process '%s' (prevented %lu logs in the last %ld seconds).\n"
194
+ , date
195
, program_name
196
, program_name
197
, prevented
@@ -175,8 +210,10 @@ int error_log_limit(int reset) {
210
211
if(counter > error_log_errors_per_period) {
212
if(!prevented) {
178
- log_date(stderr);
179
- fprintf(stderr, "%s: Too many logs (%lu logs in %ld seconds, threshold is set to %lu logs in %ld seconds). Preventing more logs from process '%s' for %ld seconds.\n"
213
+ char date[LOG_DATE_LENGTH];
214
+ log_date(date, LOG_DATE_LENGTH);
215
+ fprintf(stderr, "%s: %s: Too many logs (%lu logs in %ld seconds, threshold is set to %lu logs in %ld seconds). Preventing more logs from process '%s' for %ld seconds.\n"
216
+ , date
217
, program_name
218
, counter
219
, now - start
@@ -199,38 +236,17 @@ int error_log_limit(int reset) {
236
return 0;
237
}
238
202
-// ----------------------------------------------------------------------------
203
-// print the date
204
-
205
-// FIXME
206
-// this should print the date in a buffer the way it
207
-// is now, logs from multiple threads may be multiplexed
208
-
209
-void log_date(FILE *out)
210
-{
211
- char outstr[26];
212
- time_t t;
213
- struct tm *tmp, tmbuf;
214
-
215
- t = now_realtime_sec();
216
- tmp = localtime_r(&t, &tmbuf);
217
-
218
- if (tmp == NULL) return;
219
- if (unlikely(strftime(outstr, sizeof(outstr), "%Y-%m-%d %H:%M:%S", tmp) == 0)) return;
220
-
221
- fprintf(out, "%s: ", outstr);
222
-}
223
-
239
// ----------------------------------------------------------------------------
240
// debug log
241
227
-void debug_int( const char *file, const char *function, const unsigned long line, const char *fmt, ... )
228
-{
242
+void debug_int( const char *file, const char *function, const unsigned long line, const char *fmt, ... ) {
243
va_list args;
244
231
- log_date(stdout);
245
+ char date[LOG_DATE_LENGTH];
246
+ log_date(date, LOG_DATE_LENGTH);
247
+
248
va_start( args, fmt );
233
- printf("%s: DEBUG (%04lu@%-10.10s:%-15.15s): ", program_name, line, file, function);
249
+ printf("%s: %s: DEBUG (%04lu@%-10.10s:%-15.15s): ", date, program_name, line, file, function);
250
vprintf(fmt, args);
251
va_end( args );
252
putchar('\n');
@@ -254,21 +270,26 @@ void info_int( const char *file, const char *function, const unsigned long line,
270
// prevent logging too much
271
if(error_log_limit(0)) return;
272
257
- log_date(stderr);
273
+ if(error_log_syslog) {
274
+ va_start( args, fmt );
275
+ vsyslog(LOG_INFO, fmt, args );
276
+ va_end( args );
277
+ }
278
+
279
+ char date[LOG_DATE_LENGTH];
280
+ log_date(date, LOG_DATE_LENGTH);
281
+
282
+ log_lock();
283
284
va_start( args, fmt );
260
- if(debug_flags) fprintf(stderr, "%s: INFO : (%04lu@%-10.10s:%-15.15s): ", program_name, line, file, function);
261
- else fprintf(stderr, "%s: INFO : ", program_name);
285
+ if(debug_flags) fprintf(stderr, "%s: %s: INFO : (%04lu@%-10.10s:%-15.15s): ", date, program_name, line, file, function);
286
+ else fprintf(stderr, "%s: %s: INFO : ", date, program_name);
287
vfprintf( stderr, fmt, args );
288
va_end( args );
289
290
fputc('\n', stderr);
291
267
- if(error_log_syslog) {
268
- va_start( args, fmt );
269
- vsyslog(LOG_INFO, fmt, args );
270
- va_end( args );
271
- }
292
+ log_unlock();
293
}
294
295
// ----------------------------------------------------------------------------
@@ -296,8 +317,7 @@ static const char *strerror_result_string(const char *a, const char *b) { (void)
317
#error "cannot detect the format of function strerror_r()"
318
#endif
319
299
-void error_int( const char *prefix, const char *file, const char *function, const unsigned long line, const char *fmt, ... )
300
-{
320
+void error_int( const char *prefix, const char *file, const char *function, const unsigned long line, const char *fmt, ... ) {
321
// save a copy of errno - just in case this function generates a new error
322
int __errno = errno;
323
@@ -306,11 +326,20 @@ void error_int( const char *prefix, const char *file, const char *function, cons
326
// prevent logging too much
327
if(error_log_limit(0)) return;
328
309
- log_date(stderr);
329
+ if(error_log_syslog) {
330
+ va_start( args, fmt );
331
+ vsyslog(LOG_ERR, fmt, args );
332
+ va_end( args );
333
+ }
334
+
335
+ char date[LOG_DATE_LENGTH];
336
+ log_date(date, LOG_DATE_LENGTH);
337
+
338
+ log_lock();
339
340
va_start( args, fmt );
312
- if(debug_flags) fprintf(stderr, "%s: %s: (%04lu@%-10.10s:%-15.15s): ", program_name, prefix, line, file, function);
313
- else fprintf(stderr, "%s: %s: ", program_name, prefix);
341
+ if(debug_flags) fprintf(stderr, "%s: %s: %s: (%04lu@%-10.10s:%-15.15s): ", date, program_name, prefix, line, file, function);
342
+ else fprintf(stderr, "%s: %s: %s: ", date, program_name, prefix);
343
vfprintf( stderr, fmt, args );
344
va_end( args );
345
@@ -322,33 +351,33 @@ void error_int( const char *prefix, const char *file, const char *function, cons
351
else
352
fputc('\n', stderr);
353
354
+ log_unlock();
355
+}
356
+
357
+void fatal_int( const char *file, const char *function, const unsigned long line, const char *fmt, ... ) {
358
+ va_list args;
359
+
360
if(error_log_syslog) {
361
va_start( args, fmt );
327
- vsyslog(LOG_ERR, fmt, args );
362
+ vsyslog(LOG_CRIT, fmt, args );
363
va_end( args );
364
}
330
-}
365
332
-void fatal_int( const char *file, const char *function, const unsigned long line, const char *fmt, ... )
333
-{
334
- va_list args;
366
+ char date[LOG_DATE_LENGTH];
367
+ log_date(date, LOG_DATE_LENGTH);
368
336
- log_date(stderr);
369
+ log_lock();
370
371
va_start( args, fmt );
339
- if(debug_flags) fprintf(stderr, "%s: FATAL: (%04lu@%-10.10s:%-15.15s): ", program_name, line, file, function);
340
- else fprintf(stderr, "%s: FATAL: ", program_name);
372
+ if(debug_flags) fprintf(stderr, "%s: %s: FATAL: (%04lu@%-10.10s:%-15.15s): ", date, program_name, line, file, function);
373
+ else fprintf(stderr, "%s: %s: FATAL: ", date, program_name);
374
vfprintf( stderr, fmt, args );
375
va_end( args );
376
377
perror(" # ");
378
fputc('\n', stderr);
379
347
- if(error_log_syslog) {
348
- va_start( args, fmt );
349
- vsyslog(LOG_CRIT, fmt, args );
350
- va_end( args );
351
- }
380
+ log_unlock();
381
382
netdata_cleanup_and_exit(1);
383
}
@@ -356,23 +385,29 @@ void fatal_int( const char *file, const char *function, const unsigned long line
385
// ----------------------------------------------------------------------------
386
// access log
387
359
-void log_access( const char *fmt, ... )
360
-{
388
+void log_access( const char *fmt, ... ) {
389
va_list args;
390
391
+ if(access_log_syslog) {
392
+ va_start( args, fmt );
393
+ vsyslog(LOG_INFO, fmt, args );
394
+ va_end( args );
395
+ }
396
+
397
if(stdaccess) {
364
- log_date(stdaccess);
398
+ static netdata_mutex_t access_mutex = NETDATA_MUTEX_INITIALIZER;
399
+
400
+ netdata_mutex_lock(&access_mutex);
401
+
402
+ char date[LOG_DATE_LENGTH];
403
+ log_date(date, LOG_DATE_LENGTH);
404
+ fprintf(stdaccess, "%s: ", date);
405
406
va_start( args, fmt );
407
vfprintf( stdaccess, fmt, args );
408
va_end( args );
409
fputc('\n', stdaccess);
370
- }
410
372
- if(access_log_syslog) {
373
- va_start( args, fmt );
374
- vsyslog(LOG_INFO, fmt, args );
375
- va_end( args );
411
+ netdata_mutex_unlock(&access_mutex);
412
}
413
}
378
-
src/log.h
-1
@@ -68,7 +68,6 @@ extern void reopen_all_log_files();
68
#define error(args...) error_int("ERROR", __FILE__, __FUNCTION__, __LINE__, ##args)
69
#define fatal(args...) fatal_int(__FILE__, __FUNCTION__, __LINE__, ##args)
70
71
-extern void log_date(FILE *out);
71
extern void debug_int( const char *file, const char *function, const unsigned long line, const char *fmt, ... ) PRINTFLIKE(4, 5);
72
extern void info_int( const char *file, const char *function, const unsigned long line, const char *fmt, ... ) PRINTFLIKE(4, 5);
73
extern void error_int( const char *prefix, const char *file, const char *function, const unsigned long line, const char *fmt, ... ) PRINTFLIKE(5, 6);
src/statsd.c
+12
-2
@@ -293,7 +293,7 @@ static struct statsd {
293
.threads = 0,
294
.sockets = {
295
.config_section = CONFIG_SECTION_STATSD,
296
- .default_bind_to = "udp:localhost:8125 tcp:localhost:8125",
296
+ .default_bind_to = "udp:localhost tcp:localhost",
297
.default_port = STATSD_LISTEN_PORT,
298
.backlog = STATSD_LISTEN_BACKLOG
299
},
@@ -957,6 +957,7 @@ int statsd_readfile(const char *path, const char *filename) {
957
debug(D_STATSD, "STATSD: ignoring line %zu of file '%s/%s', it is empty.", line, path, filename);
958
continue;
959
}
960
+ debug(D_STATSD, "STATSD: processing line %zu of file '%s/%s': %s", line, path, filename, buffer);
961
962
int len = (int) strlen(s);
963
if (*s == '[' && s[len - 1] == ']') {
@@ -986,7 +987,7 @@ int statsd_readfile(const char *path, const char *filename) {
987
chart->priority = STATSD_CHART_PRIORITY;
988
chart->chart_type = RRDSET_TYPE_LINE;
989
989
- chart->next = chart;
990
+ chart->next = app->charts;
991
app->charts = chart;
992
}
993
@@ -1519,6 +1520,8 @@ static inline RRD_ALGORITHM statsd_algorithm_for_metric(STATSD_METRIC *m) {
1520
}
1521
1522
static inline void statsd_update_app_chart(STATSD_APP *app, STATSD_APP_CHART *chart) {
1523
+ debug(D_STATSD, "updating chart '%s' for app '%s'", chart->id, app->name);
1524
+
1525
if(!chart->st) {
1526
chart->st = rrdset_create_custom(
1527
localhost
@@ -1549,11 +1552,16 @@ static inline void statsd_update_app_chart(STATSD_APP *app, STATSD_APP_CHART *ch
1552
}
1553
1554
rrdset_done(chart->st);
1555
+ debug(D_STATSD, "completed update of chart '%s' for app '%s'", chart->id, app->name);
1556
}
1557
1558
static inline void statsd_update_all_app_charts(void) {
1559
+ debug(D_STATSD, "updating app charts");
1560
+
1561
STATSD_APP *app;
1562
for(app = statsd.apps; app ;app = app->next) {
1563
+ debug(D_STATSD, "updating charts for app '%s'", app->name);
1564
+
1565
STATSD_APP_CHART *chart;
1566
for(chart = app->charts; chart ;chart = chart->next) {
1567
if(unlikely(chart->dimensions_linked_count)) {
@@ -1561,6 +1569,8 @@ static inline void statsd_update_all_app_charts(void) {
1569
}
1570
}
1571
}
1572
+
1573
+ debug(D_STATSD, "completed update of app charts");
1574
}
1575
1576
static inline void statsd_flush_index_metrics(STATSD_INDEX *index, void (*flush_metric)(STATSD_METRIC *)) {