added debug info to rrdpush sending side, for tracing issue #2154
Costa Tsaousis (ktsaou) committed
May 7, 2017 at 12:29 UTC
81dcdb206bf53d8e1d8b97c3383d6c53e4966754
2 files changed
+28
-5
src/log.h
+1
@@ -31,6 +31,7 @@
31
#define D_BACKEND 0x0000000008000000
32
#define D_STATSD 0x0000000010000000
33
#define D_POLLFD 0x0000000020000000
34
+#define D_STREAM 0x0000000040000000
35
#define D_SYSTEM 0x8000000000000000
36
37
//#define DEBUG (D_WEB_CLIENT_ACCESS|D_LISTENER|D_RRD_STATS)
src/rrdpush.c
+27
-5
@@ -282,6 +282,7 @@ void *rrdpush_sender_thread(void *ptr) {
282
ofd = &fds[1];
283
284
for(; host->rrdpush_enabled && !netdata_exit ;) {
285
+ debug(D_STREAM, "STREAM: Checking if we need to timeout the connection...");
286
if(host->rrdpush_socket != -1 && now_monotonic_sec() - last_sent_t > timeout) {
287
error("STREAM %s [send to %s]: could not send metrics for %d seconds - closing connection - we have sent %zu bytes on this connection.", host->hostname, connected_to, timeout, sent_connection);
288
close(host->rrdpush_socket);
@@ -289,6 +290,8 @@ void *rrdpush_sender_thread(void *ptr) {
290
}
291
292
if(unlikely(host->rrdpush_socket == -1)) {
293
+ debug(D_STREAM, "STREAM: Attempting to connect...");
294
+
295
// stop appending data into rrdpush_buffer
296
// they will be lost, so there is no point to do it
297
host->rrdpush_connected = 0;
@@ -366,21 +369,28 @@ void *rrdpush_sender_thread(void *ptr) {
369
ofd->fd = host->rrdpush_socket;
370
ofd->revents = 0;
371
if(begin < buffer_strlen(host->rrdpush_buffer)) {
372
+ debug(D_STREAM, "STREAM: Requesting data output on streaming socket...");
373
ofd->events = POLLOUT;
374
fdmax = 2;
375
}
376
else {
377
+ debug(D_STREAM, "STREAM: Not requesting data output on streaming socket (nothing to send now)...");
378
ofd->events = 0;
379
fdmax = 1;
380
}
381
382
+ debug(D_STREAM, "STREAM: Waiting for poll() events...");
383
if(netdata_exit) break;
378
- int retval = poll(fds, fdmax, timeout * 1000);
384
+ int retval = poll(fds, fdmax, 1000);
385
if(netdata_exit) break;
386
387
if(unlikely(retval == -1)) {
382
- if(errno == EAGAIN || errno == EINTR)
388
+ debug(D_STREAM, "STREAM: poll() failed...");
389
+
390
+ if(errno == EAGAIN || errno == EINTR) {
391
+ debug(D_STREAM, "STREAM: poll() failed with EAGAIN or EINTR...");
392
continue;
393
+ }
394
395
error("STREAM %s [send to %s]: failed to poll().", host->hostname, connected_to);
396
close(host->rrdpush_socket);
@@ -389,12 +399,15 @@ void *rrdpush_sender_thread(void *ptr) {
399
}
400
else if(likely(retval)) {
401
if (ifd->revents & POLLIN) {
402
+ debug(D_STREAM, "STREAM: Data added to send buffer...");
403
+
404
char buffer[1000 + 1];
405
if (read(host->rrdpush_pipe[PIPE_READ], buffer, 1000) == -1)
406
error("STREAM %s [send to %s]: cannot read from internal pipe.", host->hostname, connected_to);
407
}
408
409
if (ofd->revents & POLLOUT && begin < buffer_strlen(host->rrdpush_buffer)) {
410
+ debug(D_STREAM, "STREAM: Sending socket is ready for output...");
411
412
// BEGIN RRDPUSH LOCKED SESSION
413
@@ -406,11 +419,14 @@ void *rrdpush_sender_thread(void *ptr) {
419
if (pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, NULL) != 0)
420
error("STREAM %s [send]: cannot set pthread cancel state to DISABLE.", host->hostname);
421
422
+ debug(D_STREAM, "STREAM: Getting exclusive lock on host...");
423
rrdpush_lock(host);
424
411
- ssize_t ret = send(host->rrdpush_socket, &host->rrdpush_buffer->buffer[begin],
412
- buffer_strlen(host->rrdpush_buffer) - begin, MSG_DONTWAIT);
425
+ debug(D_STREAM, "STREAM: Sending data from %zu to %zu...", begin, buffer_strlen(host->rrdpush_buffer));
426
+ ssize_t ret = send(host->rrdpush_socket, &host->rrdpush_buffer->buffer[begin], buffer_strlen(host->rrdpush_buffer) - begin, MSG_DONTWAIT);
427
if (unlikely(ret == -1)) {
428
+ debug(D_STREAM, "STREAM: Send failed...");
429
+
430
if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
431
error("STREAM %s [send to %s]: failed to send metrics - closing connection - we have sent %zu bytes on this connection.", host->hostname, connected_to, sent_connection);
432
close(host->rrdpush_socket);
@@ -418,6 +434,8 @@ void *rrdpush_sender_thread(void *ptr) {
434
}
435
}
436
else if(likely(ret > 0)) {
437
+ debug(D_STREAM, "STREAM: Sent %zd bytes...", ret);
438
+
439
sent_connection += ret;
440
sent_bytes += ret;
441
begin += ret;
@@ -437,6 +455,7 @@ void *rrdpush_sender_thread(void *ptr) {
455
host->rrdpush_socket = -1;
456
}
457
458
+ debug(D_STREAM, "STREAM: Releasing exclusive lock on host...");
459
rrdpush_unlock(host);
460
461
if (pthread_setcancelstate(PTHREAD_CANCEL_ENABLE, NULL) != 0)
@@ -445,9 +464,12 @@ void *rrdpush_sender_thread(void *ptr) {
464
// END RRDPUSH LOCKED SESSION
465
}
466
}
448
- // else timeout
467
+ else {
468
+ debug(D_STREAM, "STREAM: poll() timed out.");
469
+ }
470
471
// protection from overflow
472
+ debug(D_STREAM, "STREAM: Checking for buffer overflow...");
473
if(host->rrdpush_buffer->len > max_size) {
474
errno = 0;
475
error("STREAM %s [send to %s]: too many data pending - buffer is %zu bytes long, %zu unsent - we have sent %zu bytes in total, %zu on this connection. Closing connection to flush the data.", host->hostname, connected_to, host->rrdpush_buffer->len, host->rrdpush_buffer->len - begin, sent_bytes, sent_connection);