relay_socket_t *open_output_socket_eventually(struct worker_base *base) { const config_t *config = base->config; relay_socket_t *sck = NULL; int nap = config->sleep_after_disaster_millisec; int max = config->max_socket_open_wait_millisec; while (!RELAY_ATOMIC_READ(base->stopping) && !sck) { if (open_socket(&base->output_socket, DO_CONNECT, config->server_socket_sndbuf_bytes, 0)) { sck = &base->output_socket; } else { /* no socket - wait a while, double the wait (up to a limit), and then redo the loop */ SAY("waiting %d millisec to retry socket %s", nap, base->output_socket.to_string); worker_wait_millisec(nap); if (nap < max) { nap = 2 * nap + (time(NULL) & 31); /* "Random" fuzz of up to 0.031s. */ } if (nap > max) { nap = max; } } } if (RELAY_ATOMIC_READ(base->stopping)) { WARN("Stopping, not opening sockets"); } return sck; }
void mark_second_elapsed() { char str[MAX_BUF_LEN+1]; stats_count_t received= RELAY_ATOMIC_READ(RECEIVED_STATS.received_count); stats_count_t active = RELAY_ATOMIC_READ(RECEIVED_STATS.active_connections); /* set it in the process name */ int wrote= snprintf( str, MAX_BUF_LEN, STATSfmt " ^" STATSfmt , received, active ); add_worker_stats_to_ps_str(str + wrote, MAX_BUF_LEN - wrote); setproctitle(str); }
void snapshot_stats(stats_basic_counters_t *counters, stats_basic_counters_t *totals) { stats_count_t received_count= RELAY_ATOMIC_READ(counters->received_count); /* number of items we have received */ stats_count_t sent_count= RELAY_ATOMIC_READ(counters->sent_count); /* number of items we have sent */ stats_count_t partial_count= RELAY_ATOMIC_READ(counters->partial_count); /* number of items we have spilled */ stats_count_t spilled_count= RELAY_ATOMIC_READ(counters->spilled_count); /* number of items we have spilled */ stats_count_t error_count= RELAY_ATOMIC_READ(counters->error_count); /* number of items that had an error */ stats_count_t disk_count= RELAY_ATOMIC_READ(counters->disk_count); /* number of items written to disk */ stats_count_t disk_error_count= RELAY_ATOMIC_READ(counters->disk_error_count); /* number of items we failed to write to disk */ stats_count_t send_elapsed_usec= RELAY_ATOMIC_READ(counters->send_elapsed_usec); /* time to send */ RELAY_ATOMIC_INCREMENT(totals->received_count, received_count); /* number of items we have received */ RELAY_ATOMIC_INCREMENT(totals->sent_count, sent_count); /* number of items we have sent */ RELAY_ATOMIC_INCREMENT(totals->partial_count, partial_count); /* number of items we have spilled */ RELAY_ATOMIC_INCREMENT(totals->spilled_count, spilled_count); /* number of items we have spilled */ RELAY_ATOMIC_INCREMENT(totals->error_count, error_count); /* number of items that had an error */ RELAY_ATOMIC_INCREMENT(totals->disk_count, disk_count); /* number of items written to disk */ RELAY_ATOMIC_INCREMENT(totals->disk_error_count, disk_error_count); /* number of items written to disk */ RELAY_ATOMIC_INCREMENT(totals->send_elapsed_usec, send_elapsed_usec); /* time to send */ RELAY_ATOMIC_DECREMENT(counters->received_count, received_count); /* number of items we have received */ RELAY_ATOMIC_DECREMENT(counters->sent_count, sent_count); /* number of items we have sent */ RELAY_ATOMIC_DECREMENT(counters->partial_count, partial_count); /* number of items we have spilled */ RELAY_ATOMIC_DECREMENT(counters->spilled_count, spilled_count); /* number of items we have spilled */ RELAY_ATOMIC_DECREMENT(counters->error_count, error_count); /* number of items that had an error */ RELAY_ATOMIC_DECREMENT(counters->disk_count, disk_count); /* number of items written to disk */ RELAY_ATOMIC_DECREMENT(counters->disk_error_count, disk_error_count); /* number of items written to disk */ RELAY_ATOMIC_DECREMENT(counters->send_elapsed_usec, send_elapsed_usec); /* time to send */ }
/* create a disk writer worker thread * main loop for the disk writer worker process */ void *disk_writer_thread(void *arg) { disk_writer_t *self = (disk_writer_t *)arg; queue_t private_queue; queue_t *main_queue = &self->queue; blob_t *b; uint32_t done_work= 0; recreate_fallback_path(self->fallback_path); SAY("disk writer started using path '%s' for files", self->fallback_path); memset(&private_queue, 0, sizeof(private_queue)); while( 1 ){ q_hijack(main_queue, &private_queue, &POOL.lock); b= private_queue.head; if ( b == NULL ) { if (done_work) { SAY("cleared disk queue of %d items", done_work); done_work= 0; } setup_for_epoch(self, 0); if (RELAY_ATOMIC_READ(self->exit)) { /* nothing to do and we have been asked to exit, so break from the loop */ break; } else { w_wait( CONFIG.polling_interval_ms ); } } else { do { done_work++; write_blob_to_disk(self, b); b_destroy( q_shift_nolock( &private_queue) ); } while ((b = private_queue.head) != NULL); (void)snapshot_stats( self->pcounters, self->ptotals ); } } (void)snapshot_stats( self->pcounters, self->ptotals ); SAY("disk_writer saved " STATSfmt " packets in its lifetime", self->ptotals->disk_count); return NULL; }
uint32_t is_aborted() { uint32_t v= RELAY_ATOMIC_READ(ABORT); return (v & DIE) == DIE; }
uint32_t not_aborted() { uint32_t v= RELAY_ATOMIC_READ(ABORT); return (v & DIE) == 0; }
uint32_t get_abort_val() { return RELAY_ATOMIC_READ(ABORT); }
/* the main loop for the socket worker process */ void *socket_worker_thread(void *arg) { socket_worker_t *self = (socket_worker_t *) arg; queue_t *main_queue = &self->queue; relay_socket_t *sck = NULL; queue_t private_queue; queue_t spill_queue; memset(&private_queue, 0, sizeof(queue_t)); memset(&spill_queue, 0, sizeof(queue_t)); const config_t *config = self->base.config; int join_err; #define RATE_UPDATE_PERIOD 15 time_t last_rate_update = 0; while (!RELAY_ATOMIC_READ(self->base.stopping)) { time_t now = time(NULL); if (!sck) { SAY("Opening forwarding socket"); sck = open_output_socket_eventually(&self->base); if (sck == NULL || !(sck->type == SOCK_DGRAM || sck->type == SOCK_STREAM)) { FATAL_ERRNO("Failed to open forwarding socket"); break; } connected_inc(); } long since_rate_update = now - last_rate_update; if (since_rate_update >= RATE_UPDATE_PERIOD) { last_rate_update = now; update_rates(&self->rates[0], &self->totals, since_rate_update); update_rates(&self->rates[1], &self->totals, since_rate_update); update_rates(&self->rates[2], &self->totals, since_rate_update); } /* if we dont have anything in our local queue we need to hijack the main one */ if (private_queue.head == NULL) { /* hijack the queue - copy the queue state into our private copy * and then reset the queue state to empty. So the formerly * shared queue is now private. We only do this if necessary. */ if (!queue_hijack(main_queue, &private_queue, &GLOBAL.pool.lock)) { /* nothing to do, so sleep a while and redo the loop */ worker_wait_millisec(config->polling_interval_millisec); continue; } } RELAY_ATOMIC_INCREMENT(self->counters.received_count, private_queue.count); /* ok, so we should have something in our queue to process */ if (private_queue.head == NULL) { WARN("Empty private queue"); break; } ssize_t wrote = 0; if (!process_queue(self, sck, &private_queue, &spill_queue, &wrote)) { if (!RELAY_ATOMIC_READ(self->base.stopping)) { WARN("Closing forwarding socket"); close(sck->socket); sck = NULL; connected_dec(); } } accumulate_and_clear_stats(&self->counters, &self->recents, &self->totals); } if (control_is(RELAY_STOPPING)) { SAY("Socket worker stopping, trying forwarding flush"); stats_count_t old_sent = self->totals.sent_count; stats_count_t old_spilled = self->totals.spilled_count; stats_count_t old_dropped = self->totals.dropped_count; if (sck) { ssize_t wrote = 0; if (!process_queue(self, sck, &private_queue, &spill_queue, &wrote)) { WARN_ERRNO("Forwarding flush failed"); } accumulate_and_clear_stats(&self->counters, &self->recents, &self->totals); SAY("Forwarding flush forwarded %zd bytes in %llu events, spilled %llu events, dropped %llu events ", wrote, (unsigned long long) (self->totals.sent_count - old_sent), (unsigned long long) (self->totals.spilled_count - old_spilled), (unsigned long long) (self->totals.dropped_count - old_dropped)); } else { WARN("No forwarding socket to flush to"); } SAY("Socket worker spilling any remaining events to disk"); stats_count_t spilled = spill_all(self, &private_queue, &spill_queue); SAY("Socket worker spilled %llu events to disk", (unsigned long long) spilled); } else { accumulate_and_clear_stats(&self->counters, &self->recents, &self->totals); } SAY("worker[%s] in its lifetime received %lu sent %lu spilled %lu dropped %lu", (sck ? sck->to_string : self->base.arg), (unsigned long) RELAY_ATOMIC_READ(self->totals.received_count), (unsigned long) RELAY_ATOMIC_READ(self->totals.sent_count), (unsigned long) RELAY_ATOMIC_READ(self->totals.spilled_count), (unsigned long) RELAY_ATOMIC_READ(self->totals.dropped_count)); if (sck) { close(sck->socket); connected_dec(); } /* we are done so shut down our "pet" disk worker, and then exit with a message */ RELAY_ATOMIC_OR(self->disk_writer->base.stopping, WORKER_STOPPING); join_err = pthread_join(self->disk_writer->base.tid, NULL); if (join_err) FATAL("shutting down disk_writer thread error: pthread error %d", join_err); free(self->disk_writer); return NULL; }
static int process_queue(socket_worker_t * self, relay_socket_t * sck, queue_t * private_queue, queue_t * spill_queue, ssize_t * wrote) { if (sck == NULL) { WARN("NULL forwarding socket"); return 0; } blob_t *cur_blob; struct timeval now; struct timeval send_start_time; struct timeval send_end_time; stats_count_t spilled = 0; const config_t *config = self->base.config; const uint64_t spill_microsec = 1000 * config->spill_millisec; const uint64_t grace_microsec = 1000 * config->spill_grace_millisec; const struct sockaddr *dest_addr = (const struct sockaddr *) &sck->sa.in; socklen_t addr_len = sck->addrlen; int in_grace_period = 0; struct timeval grace_period_start; int failed = 0; *wrote = 0; get_time(&send_start_time); cork(sck, 1); while (private_queue->head != NULL) { get_time(&now); /* While not all the socket backends are present, for a configured maximum time, * do not spill/drop. This is a bit crude, better rules/heuristics welcome. */ if (!connected_all()) { if (in_grace_period == 0) { in_grace_period = 1; get_time(&grace_period_start); SAY("Spill/drop grace period of %d millisec started", config->spill_grace_millisec); } if (elapsed_usec(&grace_period_start, &now) >= grace_microsec) { in_grace_period = 0; SAY("Spill/drop grace period of %d millisec expired", config->spill_grace_millisec); } } else { if (in_grace_period) { SAY("Spill/drop grace period of %d millisec canceled", config->spill_grace_millisec); } in_grace_period = 0; } if (in_grace_period == 0) { spilled += spill_by_age(self, config->spill_enabled, private_queue, spill_queue, spill_microsec, &now); } cur_blob = private_queue->head; if (!cur_blob) break; void *blob_data; ssize_t blob_size; if (sck->type == SOCK_DGRAM) { blob_size = BLOB_BUF_SIZE(cur_blob); blob_data = BLOB_BUF_addr(cur_blob); } else { /* sck->type == SOCK_STREAM */ blob_size = BLOB_DATA_MBR_SIZE(cur_blob); blob_data = BLOB_DATA_MBR_addr(cur_blob); } ssize_t blob_left = blob_size; ssize_t blob_sent = 0; int sendto_errno = 0; failed = 0; /* Keep sending while we have data left since a single sendto() * doesn't necessarily send all of it. This may eventually fail * if sendto() returns -1. */ while (!RELAY_ATOMIC_READ(self->base.stopping) && blob_left > 0) { const void *data = (const char *) blob_data + blob_sent; ssize_t sent; sendto_errno = 0; if (sck->type == SOCK_DGRAM) { sent = sendto(sck->socket, data, blob_left, MSG_NOSIGNAL, dest_addr, addr_len); } else { /* sck->type == SOCK_STREAM */ sent = sendto(sck->socket, data, blob_left, MSG_NOSIGNAL, NULL, 0); } sendto_errno = errno; if (0) { /* For debugging. */ peek_send(sck, data, blob_left, sent); } if (sent == -1) { WARN_ERRNO("sendto() tried sending %zd bytes to %s but sent none", blob_left, sck->to_string); RELAY_ATOMIC_INCREMENT(self->counters.error_count, 1); if (sendto_errno == EINTR) { /* sendto() got interrupted by a signal. Wait a while and retry. */ WARN("Interrupted, resuming"); worker_wait_millisec(config->sleep_after_disaster_millisec); continue; } failed = 1; break; /* stop sending from the hijacked queue */ } blob_sent += sent; blob_left -= sent; } if (blob_sent == blob_size) { RELAY_ATOMIC_INCREMENT(self->counters.sent_count, 1); } else if (blob_sent < blob_size) { /* Despite the send-loop above, we failed to send all the bytes. */ WARN("sendto() tried sending %zd bytes to %s but sent only %zd", blob_size, sck->to_string, blob_sent); RELAY_ATOMIC_INCREMENT(self->counters.partial_count, 1); failed = 1; } *wrote += blob_sent; if (failed) { /* We failed to send this packet. Exit the loop, and * right after the loop close the socket, and get out, * letting the main loop to reconnect. */ if ((sendto_errno == EAGAIN || sendto_errno == EWOULDBLOCK)) { /* Traffic jam. Wait a while, but still get out. */ WARN("Traffic jam"); worker_wait_millisec(config->sleep_after_disaster_millisec); } break; } else { queue_shift_nolock(private_queue); blob_destroy(cur_blob); } } cork(sck, 0); get_time(&send_end_time); if (spilled) { if (config->spill_enabled) { WARN("Wrote %lu items which were over spill threshold", (unsigned long) spilled); } else { WARN("Spill disabled: DROPPED %lu items which were over spill threshold", (unsigned long) spilled); } } /* this assumes end_time >= start_time */ uint64_t usec = elapsed_usec(&send_start_time, &send_end_time); RELAY_ATOMIC_INCREMENT(self->counters.send_elapsed_usec, usec); return failed == 0; }