static gboolean
log_writer_fd_dispatch(GSource *source,
GSourceFunc callback,
gpointer user_data)
{
LogWriterWatch *self = (LogWriterWatch *) source;
gint64 num_elements = log_queue_get_length(self->writer->queue);
if (self->pollfd.revents & (G_IO_HUP | G_IO_IN) && self->input_means_connection_broken)
{
msg_error("EOF occurred while idle",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_broken(self->writer, NC_CLOSE);
return FALSE;
}
else if (self->pollfd.revents & (G_IO_ERR) && num_elements == 0)
{
msg_error("POLLERR occurred while idle",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_broken(self->writer, NC_WRITE_ERROR);
}
else if (num_elements)
{
if (!log_writer_flush_log(self->writer, self->proto))
{
self->error_suspend = TRUE;
g_source_get_current_time(source, &self->error_suspend_target);
g_time_val_add(&self->error_suspend_target, self->writer->options->time_reopen * 1e6);
log_writer_broken(self->writer, NC_WRITE_ERROR);
if (self->writer->source == (GSource *) self)
{
msg_notice("Suspending write operation because of an I/O error",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
evt_tag_int("time_reopen", self->writer->options->time_reopen),
NULL);
}
return TRUE;
}
}
return TRUE;
}
static void
log_writer_io_check_eof(gpointer s)
{
LogWriter *self = (LogWriter *) s;
msg_error("EOF occurred while idle",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_broken(self, NC_CLOSE);
}
static void
log_writer_error_suspend_elapsed(gpointer s)
{
LogWriter *self = (LogWriter *) s;
self->suspended = FALSE;
msg_notice("Error suspend timeout has elapsed, attempting to write again",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_start_watches(self);
}
static void
log_writer_work_finished(gpointer s)
{
LogWriter *self = (LogWriter *) s;
main_loop_assert_main_thread();
self->flush_waiting_for_timeout = FALSE;
if (self->pending_proto_present)
{
/* pending proto is only set in the main thread, so no need to
* lock it before coming here. After we're syncing with the
* log_writer_reopen() call, quite possibly coming from a
* non-main thread. */
g_static_mutex_lock(&self->pending_proto_lock);
if (self->proto)
log_proto_free(self->proto);
self->proto = self->pending_proto;
self->pending_proto = NULL;
self->pending_proto_present = FALSE;
g_cond_signal(self->pending_proto_cond);
g_static_mutex_unlock(&self->pending_proto_lock);
}
if (!self->work_result)
{
log_writer_broken(self, NC_WRITE_ERROR);
if (self->proto)
{
log_writer_suspend(self);
msg_notice("Suspending write operation because of an I/O error",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
evt_tag_int("time_reopen", self->options->time_reopen),
NULL);
}
goto exit;
}
if ((self->super.flags & PIF_INITIALIZED) && self->proto)
{
/* reenable polling the source, but only if we're still initialized */
log_writer_start_watches(self);
}
exit:
log_pipe_unref(&self->super);
}
static void
log_writer_io_error(gpointer s)
{
LogWriter *self = (LogWriter *) s;
if (self->fd_watch.handler_out == NULL && self->fd_watch.handler_in == NULL)
{
msg_debug("POLLERR occurred while idle",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
log_writer_broken(self, NC_WRITE_ERROR);
return;
}
else
{
/* in case we have an error state but we also asked for read/write
* polling, the error should be handled by the I/O callback. But we
* need not call that explicitly as ivykis does that for us. */
}
log_writer_update_watches(self);
}
/* follow timer callback. Check if the file has new content, or deleted or
* moved. Ran every follow_freq seconds. */
static void
log_reader_io_follow_file(gpointer s)
{
LogReader *self = (LogReader *) s;
struct stat st, followed_st;
off_t pos = -1;
gint fd = log_proto_get_fd(self->proto);
msg_trace("Checking if the followed file has new lines",
evt_tag_str("follow_filename", self->follow_filename),
NULL);
if (fd >= 0)
{
pos = lseek(fd, 0, SEEK_CUR);
if (pos == (off_t) -1)
{
msg_error("Error invoking seek on followed file",
evt_tag_errno("error", errno),
NULL);
goto reschedule;
}
if (fstat(fd, &st) < 0)
{
if (errno == ESTALE)
{
msg_trace("log_reader_fd_check file moved ESTALE",
evt_tag_str("follow_filename", self->follow_filename),
NULL);
log_pipe_notify(self->control, &self->super.super, NC_FILE_MOVED, self);
return;
}
else
{
msg_error("Error invoking fstat() on followed file",
evt_tag_errno("error", errno),
NULL);
goto reschedule;
}
}
msg_trace("log_reader_fd_check",
evt_tag_int("pos", pos),
evt_tag_int("size", st.st_size),
NULL);
if (pos < st.st_size)
{
/* we have data to read */
log_reader_io_process_input(s);
return;
}
else if (pos == st.st_size)
{
/* we are at EOF */
log_pipe_notify(self->control, &self->super.super, NC_FILE_EOF, self);
}
else if (pos > st.st_size)
{
/* the last known position is larger than the current size of the file. it got truncated. Restart from the beginning. */
log_pipe_notify(self->control, &self->super.super, NC_FILE_MOVED, self);
/* we may be freed by the time the notification above returns */
return;
}
}
if (self->follow_filename)
{
if (stat(self->follow_filename, &followed_st) != -1)
{
if (fd < 0 || (st.st_ino != followed_st.st_ino && followed_st.st_size > 0))
{
msg_trace("log_reader_fd_check file moved eof",
evt_tag_int("pos", pos),
evt_tag_int("size", followed_st.st_size),
evt_tag_str("follow_filename", self->follow_filename),
NULL);
/* file was moved and we are at EOF, follow the new file */
log_pipe_notify(self->control, &self->super.super, NC_FILE_MOVED, self);
/* we may be freed by the time the notification above returns */
return;
}
}
else
{
msg_verbose("Follow mode file still does not exist",
evt_tag_str("filename", self->follow_filename),
NULL);
}
}
reschedule:
log_reader_update_watches(self);
}
static gboolean
log_writer_fd_prepare(GSource *source,
gint *timeout)
{
LogWriterWatch *self = (LogWriterWatch *) source;
gint64 num_elements = log_queue_get_length(self->writer->queue);
GTimeVal now;
GIOCondition proto_cond;
self->pollfd.events = G_IO_ERR;
self->pollfd.revents = 0;
g_source_get_current_time(source, &now);
if (log_proto_prepare(self->proto, &self->pollfd.fd, &proto_cond, timeout))
return TRUE;
/* recalculate buckets */
if (self->writer->options->throttle > 0)
{
gint64 diff;
gint new_buckets;
/* throttling is enabled, calculate new buckets */
if (self->last_throttle_check.tv_sec != 0)
{
diff = g_time_val_diff(&now, &self->last_throttle_check);
}
else
{
diff = 0;
self->last_throttle_check = now;
}
new_buckets = (self->writer->options->throttle * diff) / G_USEC_PER_SEC;
if (new_buckets)
{
/* if new_buckets is zero, we don't save the current time as
* last_throttle_check. The reason is that new_buckets could be
* rounded to zero when only a minimal interval passes between
* poll iterations.
*/
self->writer->throttle_buckets = MIN(self->writer->options->throttle, self->writer->throttle_buckets + new_buckets);
self->last_throttle_check = now;
}
}
if (G_UNLIKELY(self->error_suspend))
{
*timeout = g_time_val_diff(&self->error_suspend_target, &now) / 1000;
if (*timeout <= 0)
{
msg_notice("Error suspend timeout has elapsed, attempting to write again",
evt_tag_int("fd", log_proto_get_fd(self->proto)),
NULL);
self->error_suspend = FALSE;
*timeout = -1;
}
else
{
return FALSE;
}
}
if ((self->writer->options->flush_lines == 0 && (!log_writer_throttling(self->writer) && num_elements != 0)) ||
(self->writer->options->flush_lines > 0 && (!log_writer_throttling(self->writer) && num_elements >= self->writer->options->flush_lines)))
{
/* we need to flush our buffers */
self->pollfd.events |= proto_cond;
}
else if (num_elements && !log_writer_throttling(self->writer))
{
/* our buffer does not contain enough elements to flush, but we do not
* want to wait more than flush_timeout time */
if (!self->flush_waiting_for_timeout)
{
/* start waiting */
*timeout = self->writer->options->flush_timeout;
g_source_get_current_time(source, &self->flush_target);
g_time_val_add(&self->flush_target, *timeout * 1000);
self->flush_waiting_for_timeout = TRUE;
}
else
{
glong to = g_time_val_diff(&self->flush_target, &now) / 1000;
if (to <= 0)
{
/* timeout elapsed, start polling again */
if (self->writer->flags & LW_ALWAYS_WRITABLE)
return TRUE;
self->pollfd.events = proto_cond;
}
else
{
*timeout = to;
}
}
return FALSE;
}
else
{
if (num_elements && log_writer_throttling(self->writer))
{
/* we are unable to send because of throttling, make sure that we
* wake up when the rate limits lets us send at least 1 message */
*timeout = (1000 / self->writer->options->throttle) + 1;
msg_debug("Throttling output",
evt_tag_int("wait", *timeout),
NULL);
}
}
if (self->writer->flags & LW_DETECT_EOF && (self->pollfd.events & G_IO_IN) == 0)
{
self->pollfd.events |= G_IO_HUP | G_IO_IN;
self->input_means_connection_broken = TRUE;
}
else
{
self->input_means_connection_broken = FALSE;
}
self->flush_waiting_for_timeout = FALSE;
if ((self->pollfd.events & G_IO_OUT) && (self->writer->flags & LW_ALWAYS_WRITABLE))
{
self->pollfd.revents = G_IO_OUT;
return TRUE;
}
return FALSE;
}
static gboolean
log_reader_fd_check(GSource *source)
{
LogReaderWatch *self = (LogReaderWatch *) source;
if (!log_source_free_to_send(&self->reader->super))
return FALSE;
if (self->reader->options->follow_freq > 0)
{
struct stat st, followed_st;
off_t pos = -1;
gint fd = log_proto_get_fd(self->reader->proto);
/* FIXME: this is a _HUGE_ layering violation... */
if (fd >= 0)
{
pos = lseek(fd, 0, SEEK_CUR);
if (pos == (off_t) -1)
{
msg_error("Error invoking seek on followed file",
evt_tag_errno("error", errno),
NULL);
return FALSE;
}
if (fstat(fd, &st) < 0)
{
if (errno == ESTALE)
{
msg_trace("log_reader_fd_check file moved ESTALE",
evt_tag_str("follow_filename",self->reader->follow_filename),
NULL);
log_pipe_notify(self->reader->control, &self->reader->super.super, NC_FILE_MOVED, self);
return FALSE;
}
else
{
msg_error("Error invoking fstat() on followed file",
evt_tag_errno("error", errno),
NULL);
return FALSE;
}
}
msg_trace("log_reader_fd_check",
evt_tag_int("pos", pos),
evt_tag_int("size", st.st_size),
NULL);
if (pos < st.st_size)
{
return TRUE;
}
else if (pos == st.st_size)
{
log_pipe_notify(self->reader->control, &self->reader->super.super, NC_FILE_EOF, self);
}
else if (pos > st.st_size)
{
/* reopen the file */
log_pipe_notify(self->reader->control, &self->reader->super.super, NC_FILE_MOVED, self);
}
}
if (self->reader->follow_filename && stat(self->reader->follow_filename, &followed_st) != -1)
{
if (fd < 0 || (st.st_ino != followed_st.st_ino && followed_st.st_size > 0))
{
msg_trace("log_reader_fd_check file moved eof",
evt_tag_int("pos", pos),
evt_tag_int("size", followed_st.st_size),
evt_tag_str("follow_filename",self->reader->follow_filename),
NULL);
/* file was moved and we are at EOF, follow the new file */
log_pipe_notify(self->reader->control, &self->reader->super.super, NC_FILE_MOVED, self);
}
}
else if (self->reader->follow_filename)
{
GTimeVal now;
g_source_get_current_time(source, &now);
if (g_time_val_diff(&now, &self->last_follow_freq_check) > self->reader->options->follow_freq * 1000)
{
msg_verbose("Follow mode file still does not exist",
evt_tag_str("filename", self->reader->follow_filename),
NULL);
self->last_follow_freq_check = now;
}
}
return FALSE;
}
return !!(self->pollfd.revents & (G_IO_IN | G_IO_OUT | G_IO_ERR | G_IO_HUP));
}
