bcb4e51a409d94ae670de96afb8483a4f7855294Stephan Bosch/* Copyright (c) 2005-2018 Dovecot authors, see the included COPYING file */
aed2118ef7de81b1f7c4437991029cc043b23fa7Timo Sirainen/* Log a warning after 1 secs when we've been all the time busy writing the
aed2118ef7de81b1f7c4437991029cc043b23fa7Timo Sirainen log connection. */
aed2118ef7de81b1f7c4437991029cc043b23fa7Timo Sirainen#define LOG_WARN_PENDING_COUNT (1000 / MAX_MSECS_PER_CONNECTION)
211c638d81d382517d196ad47565e0d85012c927klemens/* If we keep being busy, log a warning every 60 seconds. */
aed2118ef7de81b1f7c4437991029cc043b23fa7Timo Sirainen#define LOG_WARN_PENDING_INTERVAL (60 * LOG_WARN_PENDING_COUNT)
a75d470c9223a75801418fcdda258885c36317e0Timo Sirainen HASH_TABLE(void *, struct log_client *) clients;
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainenstatic struct log_connection *log_connections = NULL;
4ee00532a265bdfb38539d811fcd12d51210ac35Timo Sirainenstatic ARRAY(struct log_connection *) logs_by_fd;
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainenstatic struct log_connection *last_pending_log;
f37939033c80f14b66868cc677179f9e54d729bdTimo Sirainenlog_connection_destroy(struct log_connection *log, bool shutting_down);
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen "[%u services too fast]", global_pending_count));
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen "[%u services too fast, last: %d/%d/%s]",
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen "[service too fast: %d/%d/%s]",
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainenstatic struct log_client *log_client_get(struct log_connection *log, pid_t pid)
a75d470c9223a75801418fcdda258885c36317e0Timo Sirainen client = hash_table_lookup(log->clients, POINTER_CAST(pid));
a75d470c9223a75801418fcdda258885c36317e0Timo Sirainen hash_table_insert(log->clients, POINTER_CAST(pid), client);
b5f3c378bcb0df052f8d46ace0945e8cc1d2140eTimo Sirainenstatic void log_client_free(struct log_connection *log,
a75d470c9223a75801418fcdda258885c36317e0Timo Sirainen hash_table_remove(log->clients, POINTER_CAST(pid));
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainenstatic void log_parse_option(struct log_connection *log,
b5f3c378bcb0df052f8d46ace0945e8cc1d2140eTimo Sirainen (void)net_addr2ip(failure->text + 3, &client->ip);
b5f3c378bcb0df052f8d46ace0945e8cc1d2140eTimo Sirainen else if (strncmp(failure->text, "prefix=", 7) == 0) {
9a795eb60306eede5efc7e8ec5d584457a49e32eTimo Sirainen i_set_failure_prefix("%s", global_log_prefix);
800fc30be46bc6f8380f6de04aea7c19ea839ddfTimo Sirainenclient_log_fatal(struct log_connection *log, struct log_client *client,
d4f004105cd7159aa9ade6b019eaecce9e94f382Timo Sirainen const char *line, const struct timeval *log_time,
d4f004105cd7159aa9ade6b019eaecce9e94f382Timo Sirainen failure_ctx.timestamp_usecs = log_time->tv_usec;
acba68a69cdd6f3f00faa18cccef356d95048e46Timo Sirainen client_log_ctx(log, &failure_ctx, log_time, prefix,
d4f004105cd7159aa9ade6b019eaecce9e94f382Timo Sirainenlog_parse_master_line(const char *line, const struct timeval *log_time,
d695286ee8796c701f1911fefeb9bcb878dd2b32Timo Sirainen if (p == NULL || (p2 = strchr(++p, ' ')) == NULL ||
d695286ee8796c701f1911fefeb9bcb878dd2b32Timo Sirainen str_to_uint(t_strcut(line, ' '), &service_fd) < 0) {
78fa3c578c14ee8a612f86cf73b6181c7f16463fTimo Sirainen i_error("Received invalid input from master: %s", line);
e48f289d2e5b2546a2c5dcc90f7ab624cc58cca2Stephan Bosch i_error("Received invalid pid from master: %s", pidstr);
d695286ee8796c701f1911fefeb9bcb878dd2b32Timo Sirainen if (service_fd >= count || logs[service_fd] == NULL) {
d695286ee8796c701f1911fefeb9bcb878dd2b32Timo Sirainen if (strcmp(cmd, "BYE") == 0 && service_fd < count) {
b636982bb629d23efba1e49c361e19237c435f19Timo Sirainen /* master is probably shutting down and we already
b636982bb629d23efba1e49c361e19237c435f19Timo Sirainen noticed the log fd closing */
d695286ee8796c701f1911fefeb9bcb878dd2b32Timo Sirainen i_error("Received master input for invalid service_fd %u: %s",
a75d470c9223a75801418fcdda258885c36317e0Timo Sirainen client = hash_table_lookup(log->clients, POINTER_CAST(pid));
78fa3c578c14ee8a612f86cf73b6181c7f16463fTimo Sirainen /* we haven't seen anything important from this client.
78fa3c578c14ee8a612f86cf73b6181c7f16463fTimo Sirainen it's not an error. */
b636982bb629d23efba1e49c361e19237c435f19Timo Sirainen client_log_fatal(log, client, cmd + 6, log_time, tm);
b636982bb629d23efba1e49c361e19237c435f19Timo Sirainen } else if (strncmp(cmd, "DEFAULT-FATAL ", 14) == 0) {
78fa3c578c14ee8a612f86cf73b6181c7f16463fTimo Sirainen /* If the client has logged a fatal/panic, don't log this
b636982bb629d23efba1e49c361e19237c435f19Timo Sirainen client_log_fatal(log, client, cmd + 14, log_time, tm);
b636982bb629d23efba1e49c361e19237c435f19Timo Sirainen i_error("Received unknown command from master: %s", cmd);
acba68a69cdd6f3f00faa18cccef356d95048e46Timo Sirainenlog_it(struct log_connection *log, const char *line,
d4f004105cd7159aa9ade6b019eaecce9e94f382Timo Sirainen const struct timeval *log_time, const struct tm *tm)
d4f004105cd7159aa9ade6b019eaecce9e94f382Timo Sirainen failure_ctx.timestamp_usecs = log_time->tv_usec;
b5f3c378bcb0df052f8d46ace0945e8cc1d2140eTimo Sirainen prefix = client != NULL && client->prefix != NULL ?
acba68a69cdd6f3f00faa18cccef356d95048e46Timo Sirainen client_log_ctx(log, &failure_ctx, log_time, prefix, failure.text);
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainenstatic int log_connection_handshake(struct log_connection *log)
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen /* we're reading from a FIFO, so we're assuming that we're getting a
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen full handshake packet immediately. if not, treat it as an error
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen message that we want to log. */
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen i_error("read(log %s) failed: %s", log->default_prefix,
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainen /* this isn't a handshake */
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainen if (handshake.log_magic != MASTER_LOG_MAGIC) {
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainen /* this isn't a handshake */
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainen if (handshake.prefix_len > size - sizeof(handshake)) {
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainen log->default_prefix = i_strndup(data + sizeof(handshake),
0694891cdf35a905ba67b027d28c1657ede2b9c1Timo Sirainen i_stream_skip(log->input, sizeof(handshake) + handshake.prefix_len);
b5f3c378bcb0df052f8d46ace0945e8cc1d2140eTimo Sirainen if (strcmp(log->default_prefix, MASTER_LOG_PREFIX_NAME) == 0) {
3e8558a3a8e12b012e43976ead883bb5cc00ada4Timo Sirainen if (log->listen_fd != MASTER_LISTEN_FD_FIRST) {
3e8558a3a8e12b012e43976ead883bb5cc00ada4Timo Sirainen i_error("Received master prefix in handshake "
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainenstatic void log_connection_input(struct log_connection *log)
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen /* come back here even if we read something else besides a
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen handshake. the first few lines could be coming from e.g.
0f27d0c9330143a8b08f6660d1dbe1cc921c209eTimo Sirainen libc before the proper handshake line is sent. */
19c587fe07581d654721efb724ccc7fa8513abd6Timo Sirainen while ((ret = i_stream_read(log->input)) > 0 || ret == -2) {
19c587fe07581d654721efb724ccc7fa8513abd6Timo Sirainen /* get new timestamps for every read() */
19c587fe07581d654721efb724ccc7fa8513abd6Timo Sirainen while ((line = i_stream_next_line(log->input)) != NULL)
ffafd76c96f018523f23601bc57200ec013c84a4Timo Sirainen if (timeval_diff_msecs(&ioloop_timeval, &start_timeval) > MAX_MSECS_PER_CONNECTION) {
da3aebb67683adc7399de1fea5ca4218f9c746d3Timo Sirainen i_error("read(log %s) failed: %m", log->default_prefix);
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen if (log->pending_count == LOG_WARN_PENDING_COUNT ||
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen (log->pending_count % LOG_WARN_PENDING_INTERVAL) == 0) {
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen i_warning("Log connection fd %d listen_fd %d prefix '%s' is sending input faster than we can write",
f2880c3c3de56ec757ffc393363bb863efd7bcbeTimo Sirainen log->fd, log->listen_fd, log->default_prefix);
e34d170f8f0e084bd94bfbc1a7085ece67e508dfTimo Sirainenvoid log_connection_create(struct log_error_buffer *errorbuf,
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainen log->io = io_add(fd, IO_READ, log_connection_input, log);
e93184a9055c2530366dfe617e07199603c399ddMartti Rannanjärvi log->input = i_stream_create_fd(fd, PIPE_BUF);
f6849394b03f483abe2172bfc553be5c2439ea17Timo Sirainen log->default_prefix = i_strdup_printf("listen_fd %d", listen_fd);
678d0463849ba777106eb7875f27db07a5d8e3dfTimo Sirainen hash_table_create_direct(&log->clients, default_pool, 0);
f37939033c80f14b66868cc677179f9e54d729bdTimo Sirainenlog_connection_destroy(struct log_connection *log, bool shutting_down)
f37939033c80f14b66868cc677179f9e54d729bdTimo Sirainen while (hash_table_iterate(iter, log->clients, &key, &client)) {
f37939033c80f14b66868cc677179f9e54d729bdTimo Sirainen i_warning("Shutting down logging for '%s' with %u clients",
78fa3c578c14ee8a612f86cf73b6181c7f16463fTimo Sirainen i_error("close(log connection fd) failed: %m");
9da1a079c12108658d58876cd8d157418b3b518cTimo Sirainen master_service_client_connection_destroyed(master_service);
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainen /* normally we don't exit until all log connections are gone,
d176f84ce5ca2073f4dfbafb457b9c74f6bf0d76Timo Sirainen but we could get here when we're being killed by a signal */