From e413f4ee9cd298baab701df31ab4c1cb91c7c4b6 Mon Sep 17 00:00:00 2001 From: Vsevolod Stakhov Date: Tue, 22 Dec 2009 01:32:18 +0300 Subject: [PATCH] * Introduce new logging system: - independent and customizeable buffering - line buffering - errors handling support - custom (ip based) debug - append function name automaticaly (based on __FUNCTION__) - add some logic to logs system --- CMakeLists.txt | 3 + src/binlog.c | 54 ++--- src/buffer.c | 22 +- src/buffer.h | 1 + src/cfg_file.h | 5 +- src/cfg_file.l | 2 + src/cfg_file.y | 17 ++ src/cfg_utils.c | 8 +- src/classifiers/winnow.c | 2 +- src/controller.c | 42 ++-- src/evdns/CMakeLists.txt | 1 + src/evdns/evdns.c | 2 +- src/events.c | 8 +- src/expressions.c | 84 ++++---- src/filter.c | 23 ++- src/fuzzy_storage.c | 34 ++-- src/html.c | 6 +- src/json/CMakeLists.txt | 1 + src/lmtp.c | 35 +++- src/lmtp_proto.c | 43 ++-- src/logger.c | 417 ++++++++++++++++++++++++++++++++++++++ src/logger.h | 87 ++++++++ src/lua/CMakeLists.txt | 1 + src/lua/lua_classifier.c | 4 +- src/lua/lua_common.c | 16 +- src/lua/lua_config.c | 8 +- src/lua/lua_task.c | 6 +- src/main.c | 142 +++++-------- src/main.h | 7 +- src/map.c | 51 +++-- src/message.c | 28 +-- src/perl.c | 4 +- src/plugins/chartable.c | 4 +- src/plugins/emails.c | 8 +- src/plugins/fuzzy_check.c | 16 +- src/plugins/regexp.c | 76 +++---- src/plugins/spf.c | 4 +- src/plugins/surbl.c | 65 +++--- src/protocol.c | 64 +++--- src/settings.c | 14 +- src/spf.c | 46 ++--- src/statfile.c | 72 +++---- src/statfile_sync.c | 20 +- src/symbols_cache.c | 28 +-- src/tokenizers/osb.c | 2 - src/upstream.c | 10 - src/url.c | 22 +- src/util.c | 211 ++----------------- src/util.h | 8 - src/worker.c | 26 +-- utils/url_extracter.c | 3 - 51 files changed, 1092 insertions(+), 771 deletions(-) create mode 100644 src/logger.c create mode 100644 src/logger.h diff --git a/CMakeLists.txt b/CMakeLists.txt index cc652ee3b..445716c80 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -358,6 +358,7 @@ SET(RSPAMDSRC src/modules.c src/html.c src/lmtp.c src/lmtp_proto.c + src/logger.c src/main.c src/map.c src/memcached.c @@ -413,6 +414,8 @@ SET(TESTDEPENDS src/mem_pool.c src/util.c src/radix.c src/fuzzy.c + src/map.c + src/logger.c src/memcached.c src/message.c src/html.c diff --git a/src/binlog.c b/src/binlog.c index 830c650fe..8ff8112b0 100644 --- a/src/binlog.c +++ b/src/binlog.c @@ -48,7 +48,7 @@ binlog_write_header (struct rspamd_binlog *log) lock_file (log->fd, FALSE); if (write (log->fd, &header, sizeof (struct rspamd_binlog_header)) == -1) { - msg_warn ("binlog_write_header: cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } @@ -63,7 +63,7 @@ binlog_write_header (struct rspamd_binlog *log) if (write (log->fd, log->metaindex, sizeof (struct rspamd_binlog_metaindex)) == -1) { g_free (log->metaindex); - msg_warn ("binlog_write_header: cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); unlock_file (log->fd, FALSE); return FALSE; } @@ -73,7 +73,7 @@ binlog_write_header (struct rspamd_binlog *log) bzero (log->cur_idx, sizeof (struct rspamd_index_block)); if (write (log->fd, log->cur_idx, sizeof (struct rspamd_index_block)) == -1) { g_free (log->cur_idx); - msg_warn ("binlog_write_header: cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); unlock_file (log->fd, FALSE); return FALSE; } @@ -89,14 +89,14 @@ binlog_check_file (struct rspamd_binlog *log) static char valid_magic[] = VALID_MAGIC, valid_version[] = VALID_VERSION; if (read (log->fd, &log->header, sizeof (struct rspamd_binlog_header)) != sizeof (struct rspamd_binlog_header)) { - msg_warn ("binlog_check_file: cannot read file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot read file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } /* Now check all fields */ if (memcmp (&log->header.magic, valid_magic, sizeof (valid_magic)) != 0 || memcmp (&log->header.version, valid_version, sizeof (valid_version)) != 0) { - msg_warn ("binlog_check_file: cannot validate file %s"); + msg_warn ("cannot validate file %s"); return FALSE; } /* Now mmap metaindex and current index */ @@ -104,7 +104,7 @@ binlog_check_file (struct rspamd_binlog *log) log->metaindex = g_malloc (sizeof (struct rspamd_binlog_metaindex)); } if ((read (log->fd, log->metaindex, sizeof (struct rspamd_binlog_metaindex))) != sizeof (struct rspamd_binlog_metaindex)) { - msg_warn ("binlog_check file: cannot read metaindex of file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot read metaindex of file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } /* Current index */ @@ -112,11 +112,11 @@ binlog_check_file (struct rspamd_binlog *log) log->cur_idx = g_malloc (sizeof (struct rspamd_index_block)); } if (lseek (log->fd, log->metaindex->indexes[log->metaindex->last_index], SEEK_SET) == -1) { - msg_info ("binlog_check_file: cannot seek in file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot seek in file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } if ((read (log->fd, log->cur_idx, sizeof (struct rspamd_index_block))) != sizeof (struct rspamd_index_block)) { - msg_warn ("binlog_check_file: cannot read index in file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot read index in file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } @@ -131,7 +131,7 @@ static gboolean binlog_create (struct rspamd_binlog *log) { if ((log->fd = open (log->filename, O_RDWR | O_TRUNC | O_CREAT, S_IWUSR | S_IRUSR)) == -1) { - msg_info ("binlog_create: cannot create file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_info ("cannot create file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } @@ -142,7 +142,7 @@ static gboolean binlog_open_real (struct rspamd_binlog *log) { if ((log->fd = open (log->filename, O_RDWR)) == -1) { - msg_info ("binlog_open: cannot open file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_info ("cannot open file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } @@ -173,7 +173,7 @@ binlog_open (memory_pool_t *pool, const char *path, time_t rotate_time, int rota if (stat (new->filename, &st) == -1) { /* Check errno to check whether we should create this file */ if (errno != ENOENT) { - msg_err ("binlog_open: cannot stat file: %s, error %s", new->filename, strerror (errno)); + msg_err ("cannot stat file: %s, error %s", new->filename, strerror (errno)); return NULL; } else { @@ -219,7 +219,7 @@ binlog_tree_callback (gpointer key, gpointer value, gpointer data) elt.value = node->value; if (write (log->fd, &elt, sizeof (elt)) == -1) { - msg_info ("write_binlog_tree: cannot write token to file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot write token to file: %s, error: %s", log->filename, strerror (errno)); return TRUE; } @@ -238,7 +238,7 @@ write_binlog_tree (struct rspamd_binlog *log, GTree *nodes) /* Seek to end of file */ if ((seek = lseek (log->fd, 0, SEEK_END)) == -1) { unlock_file (log->fd, FALSE); - msg_info ("binlog_insert: cannot seek in file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot seek in file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } @@ -253,13 +253,13 @@ write_binlog_tree (struct rspamd_binlog *log, GTree *nodes) idx->len = g_tree_nnodes (nodes) * sizeof (struct rspamd_binlog_element); if (lseek (log->fd, log->metaindex->indexes[log->metaindex->last_index], SEEK_SET) == -1) { unlock_file (log->fd, FALSE); - msg_info ("binlog_insert: cannot seek in file: %s, error: %s, seek: %L, op: insert index", log->filename, + msg_info ("cannot seek in file: %s, error: %s, seek: %L, op: insert index", log->filename, strerror (errno), log->metaindex->indexes[log->metaindex->last_index]); return FALSE; } if (write (log->fd, log->cur_idx, sizeof (struct rspamd_index_block)) == -1) { unlock_file (log->fd, FALSE); - msg_info ("binlog_insert: cannot write index to file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot write index to file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } log->cur_idx->last_index ++; @@ -279,13 +279,13 @@ create_new_metaindex_block (struct rspamd_binlog *log) /* Seek to end of file */ if ((seek = lseek (log->fd, 0, SEEK_END)) == -1) { unlock_file (log->fd, FALSE); - msg_info ("create_new_metaindex_block: cannot seek in file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot seek in file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } if (write (log->fd, log->cur_idx, sizeof (struct rspamd_index_block)) == -1) { unlock_file (log->fd, FALSE); g_free (log->cur_idx); - msg_warn ("create_new_metaindex_block: cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot write file %s, error %d, %s", log->filename, errno, strerror (errno)); return FALSE; } /* Offset to metaindex */ @@ -293,12 +293,12 @@ create_new_metaindex_block (struct rspamd_binlog *log) /* Overwrite all metaindexes */ if (lseek (log->fd, sizeof (struct rspamd_binlog_header), SEEK_SET) == -1) { unlock_file (log->fd, FALSE); - msg_info ("create_new_metaindex_block: cannot seek in file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot seek in file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } if (write (log->fd, log->metaindex, sizeof (struct rspamd_binlog_metaindex)) == -1) { unlock_file (log->fd, FALSE); - msg_info ("create_new_metaindex_block: cannot write metaindex in file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot write metaindex in file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } bzero (log->cur_idx, sizeof (struct rspamd_index_block)); @@ -339,7 +339,7 @@ rotate_binlog (struct rspamd_binlog *log) backup_name = g_strdup_printf ("%s.%s", log->filename, BACKUP_SUFFIX); if (stat (backup_name, &st) != -1) { - msg_info ("rotate_binlog: replace old %s", backup_name); + msg_info ("replace old %s", backup_name); unlink (backup_name); } @@ -360,7 +360,7 @@ binlog_insert (struct rspamd_binlog *log, GTree *nodes) off_t seek; if (!log || !log->metaindex || !log->cur_idx || !nodes) { - msg_info ("binlog_insert: improperly opened binlog: %s", log->filename); + msg_info ("improperly opened binlog: %s", log->filename); return FALSE; } @@ -380,7 +380,7 @@ binlog_insert (struct rspamd_binlog *log, GTree *nodes) if (log->metaindex->last_index < METAINDEX_LEN) { /* Create new index block */ if ((seek = lseek (log->fd, 0, SEEK_END)) == -1) { - msg_info ("binlog_insert: cannot seek in file: %s, error: %s", log->filename, strerror (errno)); + msg_info ("cannot seek in file: %s, error: %s", log->filename, strerror (errno)); return FALSE; } if (!create_new_metaindex_block (log)) { @@ -406,7 +406,7 @@ binlog_sync (struct rspamd_binlog *log, uint64_t from_rev, uint64_t *from_time, gboolean idx_mapped = FALSE, res = TRUE, is_first = FALSE; if (!log || !log->metaindex || !log->cur_idx) { - msg_info ("binlog_sync: improperly opened binlog: %s", log->filename); + msg_info ("improperly opened binlog: %s", log->filename); return FALSE; } @@ -437,13 +437,13 @@ binlog_sync (struct rspamd_binlog *log, uint64_t from_rev, uint64_t *from_time, idx_mapped = TRUE; if (lseek (log->fd, log->metaindex->indexes[metaindex_num], SEEK_SET) == -1) { unlock_file (log->fd, FALSE); - msg_warn ("binlog_sync: cannot seek file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot seek file %s, error %d, %s", log->filename, errno, strerror (errno)); res = FALSE; goto end; } if ((read (log->fd, idxb, sizeof (struct rspamd_index_block))) != sizeof (struct rspamd_index_block)) { unlock_file (log->fd, FALSE); - msg_warn ("binlog_sync: cannot read index from file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot read index from file %s, error %d, %s", log->filename, errno, strerror (errno)); res = FALSE; goto end; } @@ -467,14 +467,14 @@ binlog_sync (struct rspamd_binlog *log, uint64_t from_rev, uint64_t *from_time, (*rep)->len = idx->len; /* Read result */ if (lseek (log->fd, idx->seek, SEEK_SET) == -1) { - msg_warn ("binlog_sync: cannot seek file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot seek file %s, error %d, %s", log->filename, errno, strerror (errno)); res = FALSE; goto end; } (*rep)->data = g_malloc (idx->len); if ((read (log->fd, (*rep)->data, idx->len)) != idx->len) { - msg_warn ("binlog_sync: cannot read file %s, error %d, %s", log->filename, errno, strerror (errno)); + msg_warn ("cannot read file %s, error %d, %s", log->filename, errno, strerror (errno)); res = FALSE; goto end; } diff --git a/src/buffer.c b/src/buffer.c index ac0c43e21..1749cb624 100644 --- a/src/buffer.c +++ b/src/buffer.c @@ -70,7 +70,7 @@ write_buffers (int fd, rspamd_io_dispatcher_t * d, gboolean is_delayed) buf->pos += r; if (BUFREMAIN (buf) != 0) { /* Continue with this buffer */ - msg_debug ("write_buffers: wrote %z bytes of %z", r, buf->data->len); + debug_ip (d->peer_addr, "wrote %z bytes of %z", r, buf->data->len); continue; } } @@ -83,7 +83,7 @@ write_buffers (int fd, rspamd_io_dispatcher_t * d, gboolean is_delayed) } } else if (r == -1 && errno == EAGAIN) { - msg_debug ("write_buffers: partially write data, retry"); + debug_ip (d->peer_addr, "partially write data, retry"); /* Wait for other event */ event_del (d->ev); event_set (d->ev, fd, EV_WRITE, dispatcher_cb, (void *)d); @@ -98,11 +98,11 @@ write_buffers (int fd, rspamd_io_dispatcher_t * d, gboolean is_delayed) g_list_free (d->out_buffers); d->out_buffers = NULL; - msg_debug ("write_buffers: all buffers were written successfully"); + debug_ip (d->peer_addr, "all buffers were written successfully"); if (is_delayed && d->write_callback) { if (!d->write_callback (d->user_data)) { - msg_debug ("write_buffers: callback set wanna_die flag, terminating"); + debug_ip (d->peer_addr, "callback set wanna_die flag, terminating"); return FALSE; } } @@ -178,14 +178,14 @@ read_buffers (int fd, rspamd_io_dispatcher_t * d, gboolean skip_read) } } else if (r == -1 && errno == EAGAIN) { - msg_debug ("read_buffers: partially read data, retry"); + debug_ip (d->peer_addr, "partially read data, retry"); return; } else { *pos += r; *len += r; } - msg_debug ("read_buffers: read %z characters, policy is %s, watermark is: %z", r, + debug_ip (d->peer_addr, "read %z characters, policy is %s, watermark is: %z", r, d->policy == BUFFER_LINE ? "LINE" : "CHARACTER", d->nchars); } @@ -218,7 +218,7 @@ read_buffers (int fd, rspamd_io_dispatcher_t * d, gboolean skip_read) *pos = b + *len; r = 0; if (d->policy != saved_policy) { - msg_debug ("read_buffers: policy changed during callback, restart buffer's processing"); + debug_ip (d->peer_addr, "policy changed during callback, restart buffer's processing"); read_buffers (fd, d, TRUE); return; } @@ -247,7 +247,7 @@ read_buffers (int fd, rspamd_io_dispatcher_t * d, gboolean skip_read) *len -= r; *pos = b + *len; if (d->policy != saved_policy) { - msg_debug ("read_buffers: policy changed during callback, restart buffer's processing"); + debug_ip (d->peer_addr, "policy changed during callback, restart buffer's processing"); read_buffers (fd, d, TRUE); return; } @@ -265,7 +265,7 @@ dispatcher_cb (int fd, short what, void *arg) rspamd_io_dispatcher_t *d = (rspamd_io_dispatcher_t *) arg; GError *err; - msg_debug ("dispatcher_cb: in dispatcher callback, what: %d, fd: %d", (int)what, fd); + debug_ip (d->peer_addr, "in dispatcher callback, what: %d, fd: %d", (int)what, fd); switch (what) { case EV_TIMEOUT: @@ -375,7 +375,7 @@ rspamd_set_dispatcher_policy (rspamd_io_dispatcher_t * d, enum io_policy policy, } } - msg_debug ("rspamd_set_dispatcher_policy: new input length watermark is %uz", d->nchars); + debug_ip (d->peer_addr, "new input length watermark is %uz", d->nchars); } gboolean @@ -402,7 +402,7 @@ rspamd_dispatcher_write (rspamd_io_dispatcher_t * d, void *data, size_t len, gbo d->out_buffers = g_list_prepend (d->out_buffers, newbuf); if (!delayed) { - msg_debug ("rspamd_dispatcher_write: plan write event"); + debug_ip (d->peer_addr, "plan write event"); return write_buffers (d->fd, d, FALSE); } return TRUE; diff --git a/src/buffer.h b/src/buffer.h index d3410ebb8..04845814a 100644 --- a/src/buffer.h +++ b/src/buffer.h @@ -39,6 +39,7 @@ typedef struct rspamd_io_dispatcher_s { enum io_policy policy; /**< IO policy */ size_t nchars; /**< how many chars to read */ int fd; /**< descriptor */ + uint32_t peer_addr; /**< address of peer for debugging */ gboolean wanna_die; /**< if dispatcher should be stopped */ dispatcher_read_callback_t read_callback; /**< read callback */ dispatcher_write_callback_t write_callback; /**< write callback */ diff --git a/src/cfg_file.h b/src/cfg_file.h index 16b59c45f..5b6dd9511 100644 --- a/src/cfg_file.h +++ b/src/cfg_file.h @@ -227,8 +227,9 @@ struct config_file { int log_facility; /**< log facility in case of syslog */ int log_level; /**< log level trigger */ char *log_file; /**< path to logfile in case of file logging */ - int log_fd; /**< log descriptor in case of file logging */ - FILE *logf; + gboolean log_buffered; /**< whether logging is buffered */ + uint32_t log_buf_size; /**< length of log buffer */ + char *debug_ip_map; /**< turn on debugging for specified ip addresses */ gboolean log_urls; /**< whether we should log URLs */ size_t max_statfile_size; /**< maximum size for statfile */ diff --git a/src/cfg_file.l b/src/cfg_file.l index 5eea28ba3..a985fb610 100644 --- a/src/cfg_file.l +++ b/src/cfg_file.l @@ -100,6 +100,8 @@ WARNING return LOG_LEVEL_WARNING; ERROR return LOG_LEVEL_ERROR; log_facility return LOG_FACILITY; log_file return LOG_FILENAME; +log_buffer return LOG_BUFFER; +debug_ip return DEBUG_IP; profile_file return PROFILE_FILE; statfile_pool_size return STATFILE_POOL_SIZE; diff --git a/src/cfg_file.y b/src/cfg_file.y index 91c40a734..8c7f232b1 100644 --- a/src/cfg_file.y +++ b/src/cfg_file.y @@ -60,6 +60,7 @@ struct rspamd_view *cur_view = NULL; %token VIEW IP FROM SYMBOLS CLIENT_IP %token AUTOLEARN MIN_MARK MAX_MARK MAXFILES MAXCORE %token SETTINGS USER_SETTINGS DOMAIN_SETTINGS SYMBOL PATH SKIP_CHECK GROW_FACTOR +%token LOG_BUFFER DEBUG_IP %type STRING %type VARIABLE @@ -583,6 +584,8 @@ loggingcmd: | loggingfacility | loggingfile | loggingurls + | loggingbuffer + | loggingdebugip ; loggingtype: @@ -678,6 +681,20 @@ loggingurls: } ; +loggingbuffer: + LOG_BUFFER EQSIGN NUMBER + | LOG_BUFFER EQSIGN SIZELIMIT { + cfg->log_buf_size = $3; + cfg->log_buffered = TRUE; + } + ; + +loggingdebugip: + DEBUG_IP EQSIGN QUOTEDSTRING { + cfg->debug_ip_map = $3; + } + ; + classifier: CLASSIFIER OBRACE classifierbody EBRACE { if (cur_classifier == NULL || cur_classifier->classifier == NULL) { diff --git a/src/cfg_utils.c b/src/cfg_utils.c index 865c81f7f..a5d842a68 100644 --- a/src/cfg_utils.c +++ b/src/cfg_utils.c @@ -89,7 +89,7 @@ parse_host_port (const char *str, struct in_addr *ina, uint16_t *port) /* Try to call gethostbyname */ hent = gethostbyname (tokens[0]); if (hent == NULL) { - msg_warn ("parse_host_port: cannot resolve %s", tokens[0]); + msg_warn ("cannot resolve %s", tokens[0]); goto err; } else { @@ -102,12 +102,12 @@ parse_host_port (const char *str, struct in_addr *ina, uint16_t *port) errno = 0; port_parsed = strtoul (tokens[1], &err_str, 10); if (*err_str != '\0' || errno != 0) { - msg_warn ("parse_host_port: cannot parse port: %s, at symbol %c, error: %s", tokens[1], *err_str, strerror (errno)); + msg_warn ("cannot parse port: %s, at symbol %c, error: %s", tokens[1], *err_str, strerror (errno)); goto err; } if (port_parsed > G_MAXUINT16) { errno = ERANGE; - msg_warn ("parse_host_port: cannot parse port: %s, error: %s", tokens[1], *err_str, strerror (errno)); + msg_warn ("cannot parse port: %s, error: %s", tokens[1], *err_str, strerror (errno)); goto err; } *port = port_parsed; @@ -448,7 +448,7 @@ parse_filters_str (struct config_file *cfg, const char *str) if (strcasecmp (modules[i].name, *p) == 0) { cur = memory_pool_alloc (cfg->cfg_pool, sizeof (struct filter)); cur->type = C_FILTER; - msg_debug ("parse_filters_str: found C filter %s", *p); + msg_debug ("found C filter %s", *p); cur->func_name = memory_pool_strdup (cfg->cfg_pool, *p); cur->module = &modules[i]; cfg->filters = g_list_prepend (cfg->filters, cur); diff --git a/src/classifiers/winnow.c b/src/classifiers/winnow.c index 34e3dc209..522d3f4d5 100644 --- a/src/classifiers/winnow.c +++ b/src/classifiers/winnow.c @@ -156,7 +156,7 @@ winnow_classify (struct classifier_ctx *ctx, statfile_pool_t * pool, GTree * inp st = cur->data; if ((data.file = statfile_pool_is_open (pool, st->path)) == NULL) { if ((data.file = statfile_pool_open (pool, st->path, st->size, FALSE)) == NULL) { - msg_warn ("winnow_classify: cannot open %s, skip it", st->path); + msg_warn ("cannot open %s, skip it", st->path); cur = g_list_next (cur); continue; } diff --git a/src/controller.c b/src/controller.c index 6176fd0e6..b0aeca65a 100644 --- a/src/controller.c +++ b/src/controller.c @@ -135,7 +135,7 @@ free_session (void *ud) struct mime_part *p; struct controller_session *session = ud; - msg_debug ("free_session: freeing session %p", session); + msg_debug ("freeing session %p", session); while ((part = g_list_first (session->parts))) { session->parts = g_list_remove_link (session->parts, part); @@ -244,34 +244,34 @@ process_sync_command (struct controller_session *session, char **args) arg = *args; if (!arg || *arg == '\0') { - msg_info ("process_sync_command: bad arguments to sync command, need symbol"); + msg_info ("bad arguments to sync command, need symbol"); return FALSE; } symbol = arg; arg = *(args + 1); if (!arg || *arg == '\0') { - msg_info ("process_sync_command: bad arguments to sync command, need revision"); + msg_info ("bad arguments to sync command, need revision"); return FALSE; } rev = strtoull (arg, &err_str, 10); if (err_str && *err_str != 0) { - msg_info ("process_sync_command: bad arguments to sync commanc: %s", arg); + msg_info ("bad arguments to sync commanc: %s", arg); return FALSE; } arg = *(args + 2); if (!arg || *arg == '\0') { - msg_info ("process_sync_command: bad arguments to sync command, need time"); + msg_info ("bad arguments to sync command, need time"); return FALSE; } time = strtoull (arg, &err_str, 10); if (err_str && *err_str != 0) { - msg_info ("process_sync_command: bad arguments to sync commanc: %s", arg); + msg_info ("bad arguments to sync commanc: %s", arg); return FALSE; } ccf = g_hash_table_lookup (session->cfg->classifiers_symbols, symbol); if (ccf == NULL) { - msg_info ("process_sync_command: bad symbol: %s", symbol); + msg_info ("bad symbol: %s", symbol); return FALSE; } @@ -285,13 +285,13 @@ process_sync_command (struct controller_session *session, char **args) cur = g_list_next (cur); } if (st == NULL) { - msg_info ("process_sync_command: bad symbol: %s", symbol); + msg_info ("bad symbol: %s", symbol); return FALSE; } binlog = get_binlog_by_statfile (st); if (binlog == NULL) { - msg_info ("process_sync_command: cannot open binlog: %s", symbol); + msg_info ("cannot open binlog: %s", symbol); return FALSE; } @@ -392,7 +392,7 @@ process_command (struct controller_command *cmd, char **cmd_args, struct control case COMMAND_PASSWORD: arg = *cmd_args; if (!arg || *arg == '\0') { - msg_debug ("process_command: empty password passed"); + msg_debug ("empty password passed"); r = snprintf (out_buf, sizeof (out_buf), "password command requires one argument" CRLF); rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE); return; @@ -463,21 +463,21 @@ process_command (struct controller_command *cmd, char **cmd_args, struct control if (check_auth (cmd, session)) { arg = *cmd_args; if (!arg || *arg == '\0') { - msg_debug ("process_command: no statfile specified in learn command"); + msg_debug ("no statfile specified in learn command"); r = snprintf (out_buf, sizeof (out_buf), "learn command requires at least two arguments: stat filename and its size" CRLF); rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE); return; } arg = *(cmd_args + 1); if (arg == NULL || *arg == '\0') { - msg_debug ("process_command: no statfile size specified in learn command"); + msg_debug ("no statfile size specified in learn command"); r = snprintf (out_buf, sizeof (out_buf), "learn command requires at least two arguments: stat filename and its size" CRLF); rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE); return; } size = strtoul (arg, &err_str, 10); if (err_str && *err_str != '\0') { - msg_debug ("process_command: statfile size is invalid: %s", arg); + msg_debug ("statfile size is invalid: %s", arg); r = snprintf (out_buf, sizeof (out_buf), "learn size is invalid" CRLF); rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE); return; @@ -608,7 +608,7 @@ controller_read_socket (f_str_t * in, void *arg) break; case 0: if (!process_custom_command (cmd, ¶ms[1], session)) { - msg_debug ("Unknown command: '%s'", cmd); + msg_debug ("'%s'", cmd); i = snprintf (out_buf, sizeof (out_buf), "Unknown command" CRLF); if (!rspamd_dispatcher_write (session->dispatcher, out_buf, i, FALSE, FALSE)) { return FALSE; @@ -616,7 +616,7 @@ controller_read_socket (f_str_t * in, void *arg) } break; default: - msg_debug ("Ambigious command: '%s'", cmd); + msg_debug ("'%s'", cmd); i = snprintf (out_buf, sizeof (out_buf), "Ambigious command" CRLF); if (!rspamd_dispatcher_write (session->dispatcher, out_buf, i, FALSE, FALSE)) { return FALSE; @@ -644,7 +644,7 @@ controller_read_socket (f_str_t * in, void *arg) r = process_message (task); if (r == -1) { - msg_warn ("read_socket: processing of message failed"); + msg_warn ("processing of message failed"); free_task (task, FALSE); session->state = STATE_REPLY; r = snprintf (out_buf, sizeof (out_buf), "cannot process message" CRLF); @@ -713,7 +713,7 @@ controller_read_socket (f_str_t * in, void *arg) rspamd_dispatcher_pause (session->dispatcher); break; default: - msg_debug ("controller_read_socket: unknown state while reading %d", session->state); + msg_debug ("unknown state while reading %d", session->state); break; } @@ -747,7 +747,7 @@ controller_err_socket (GError * err, void *arg) struct controller_session *session = (struct controller_session *)arg; if (err->code != EOF) { - msg_info ("controller_err_socket: abnormally closing control connection, error: %s", err->message); + msg_info ("abnormally closing control connection, error: %s", err->message); } /* Free buffers */ @@ -765,13 +765,13 @@ accept_socket (int fd, short what, void *arg) int nfd; if ((nfd = accept_from_socket (fd, (struct sockaddr *)&ss, &addrlen)) == -1) { - msg_warn ("accept_socket: accept failed: %s", strerror (errno)); + msg_warn ("accept failed: %s", strerror (errno)); return; } new_session = g_malloc (sizeof (struct controller_session)); if (new_session == NULL) { - msg_err ("accept_socket: cannot allocate memory for task, %s", strerror (errno)); + msg_err ("cannot allocate memory for task, %s", strerror (errno)); return; } bzero (new_session, sizeof (struct controller_session)); @@ -818,7 +818,7 @@ start_controller (struct rspamd_worker *worker) /* Start statfile synchronization */ if (!start_statfile_sync (worker->srv->statfile_pool, worker->srv->cfg)) { - msg_info ("start_controller: cannot start statfile synchronization, statfiles would not be synchronized"); + msg_info ("cannot start statfile synchronization, statfiles would not be synchronized"); } /* Init command completion */ diff --git a/src/evdns/CMakeLists.txt b/src/evdns/CMakeLists.txt index 798ece9cc..338da91a9 100644 --- a/src/evdns/CMakeLists.txt +++ b/src/evdns/CMakeLists.txt @@ -2,3 +2,4 @@ SET(EVDNSSRC evdns.c) ADD_LIBRARY(rspamd_evdns STATIC ${EVDNSSRC}) +SET_TARGET_PROPERTIES(rspamd_evdns PROPERTIES COMPILE_FLAGS "-DRSPAMD_LIB") diff --git a/src/evdns/evdns.c b/src/evdns/evdns.c index 4a8a7b650..e399a14a0 100644 --- a/src/evdns/evdns.c +++ b/src/evdns/evdns.c @@ -2307,7 +2307,7 @@ out2: CLOSE_SOCKET(ns->socket); out1: g_free(ns); - msg_warn("Unable to add nameserver %s: error %d", debug_ntop(address), err); + msg_warn("error %d", debug_ntop(address), err); return err; } diff --git a/src/events.c b/src/events.c index 1299980e1..f91e3e847 100644 --- a/src/events.c +++ b/src/events.c @@ -51,7 +51,7 @@ register_async_event (struct rspamd_async_session *session, event_finalizer_t fi GList *cur; if (session == NULL) { - msg_info ("register_async_event: session is NULL"); + msg_info ("session is NULL"); return; } @@ -83,7 +83,7 @@ remove_forced_event (struct rspamd_async_session *session, event_finalizer_t fin GList *cur; if (session == NULL) { - msg_info ("remove_forced_event: session is NULL"); + msg_info ("session is NULL"); return; } @@ -113,7 +113,7 @@ remove_normal_event (struct rspamd_async_session *session, event_finalizer_t fin GList *cur; if (session == NULL) { - msg_info ("remove_forced_event: session is NULL"); + msg_info ("session is NULL"); return; } @@ -138,7 +138,7 @@ destroy_session (struct rspamd_async_session *session) GList *cur, *tmp; if (session == NULL) { - msg_info ("destroy_session: session is NULL"); + msg_info ("session is NULL"); return FALSE; } diff --git a/src/expressions.c b/src/expressions.c index aeae08054..9d0b05f12 100644 --- a/src/expressions.c +++ b/src/expressions.c @@ -318,7 +318,7 @@ parse_expression (memory_pool_t * pool, char *line) return NULL; } - msg_debug ("parse_expression: parsing expression {{ %s }}", line); + msg_debug ("parsing expression {{ %s }}", line); function_stack = g_queue_new (); p = line; @@ -409,7 +409,7 @@ parse_expression (memory_pool_t * pool, char *line) str = memory_pool_alloc (pool, p - c + 2); g_strlcpy (str, c - 1, (p - c + 2)); g_strstrip (str); - msg_debug ("parse_expression: found regexp: %s", str); + msg_debug ("found regexp: %s", str); if (strlen (str) > 0) { insert_expression (pool, &expr, EXPR_REGEXP, 0, str); } @@ -514,7 +514,7 @@ parse_expression (memory_pool_t * pool, char *line) g_queue_free (function_stack); if (state != SKIP_SPACES) { /* In fact we got bad expression */ - msg_warn ("parse_expression: expression \"%s\" is invalid", line); + msg_warn ("expression \"%s\" is invalid", line); return NULL; } /* Pop everything from stack */ @@ -546,7 +546,7 @@ parse_regexp (memory_pool_t * pool, char *line, gboolean raw_mode) line++; } if (line == '\0') { - msg_warn ("parse_regexp: got empty regexp"); + msg_warn ("got empty regexp"); return NULL; } /* First try to find header name */ @@ -585,7 +585,7 @@ parse_regexp (memory_pool_t * pool, char *line, gboolean raw_mode) } else { /* We got header name earlier but have not found // expression, so it is invalid regexp */ - msg_warn ("parse_regexp: got no header name (eg. header=) but without corresponding regexp, %s", src); + msg_warn ("got no header name (eg. header=) but without corresponding regexp, %s", src); return NULL; } /* Find end */ @@ -594,7 +594,7 @@ parse_regexp (memory_pool_t * pool, char *line, gboolean raw_mode) end++; } if (end == begin || *end != '/') { - msg_warn ("parse_regexp: no trailing / in regexp %s", src); + msg_warn ("no trailing / in regexp %s", src); return NULL; } /* Parse flags */ @@ -693,7 +693,7 @@ parse_regexp (memory_pool_t * pool, char *line, gboolean raw_mode) if (result->regexp == NULL || err != NULL) { *end = '/'; - msg_warn ("parse_regexp: could not read regexp: %s while reading regexp %s", err->message, src); + msg_warn ("could not read regexp: %s while reading regexp %s", err->message, src); return NULL; } if ((regexp_flags & G_REGEX_RAW) != 0) { @@ -706,7 +706,7 @@ parse_regexp (memory_pool_t * pool, char *line, gboolean raw_mode) *end = '/'; if (result->raw_regexp == NULL || err != NULL) { - msg_warn ("parse_regexp: could not read raw regexp: %s while reading regexp %s", err->message, src); + msg_warn ("could not read raw regexp: %s while reading regexp %s", err->message, src); return NULL; } @@ -724,7 +724,7 @@ call_expression_function (struct expression_function * func, struct worker_task selected = bsearch (&key, list_ptr, functions_number, sizeof (struct _fl), fl_cmp); if (selected == NULL) { - msg_warn ("call_expression_function: call to undefined function %s", key.name); + msg_warn ("call to undefined function %s", key.name); return FALSE; } @@ -740,7 +740,7 @@ get_function_arg (struct expression *expr, struct worker_task *task, gboolean wa struct expression *it; if (expr == NULL) { - msg_warn ("get_function_arg: NULL expression passed"); + msg_warn ("NULL expression passed"); return NULL; } if (expr->next == NULL) { @@ -755,7 +755,7 @@ get_function_arg (struct expression *expr, struct worker_task *task, gboolean wa res->data = GSIZE_TO_POINTER (cur); } else { - msg_warn ("get_function_arg: cannot parse argument: it contains operator or bool expression that is not wanted"); + msg_warn ("cannot parse argument: it contains operator or bool expression that is not wanted"); return NULL; } return res; @@ -775,12 +775,12 @@ get_function_arg (struct expression *expr, struct worker_task *task, gboolean wa } else if (it->type == EXPR_FUNCTION) { cur = (gsize) call_expression_function ((struct expression_function *)it->content.operand, task); - msg_debug ("get_function_arg: function %s returned %s", ((struct expression_function *)it->content.operand)->name, cur ? "true" : "false"); + debug_task ("function %s returned %s", ((struct expression_function *)it->content.operand)->name, cur ? "true" : "false"); } else if (it->type == EXPR_OPERATION) { if (g_queue_is_empty (stack)) { /* Queue has no operands for operation, exiting */ - msg_debug ("get_function_arg: invalid expression"); + debug_task ("invalid expression"); g_queue_free (stack); return NULL; } @@ -817,7 +817,7 @@ get_function_arg (struct expression *expr, struct worker_task *task, gboolean wa return res; } - msg_warn ("get_function_arg: invalid expression argument"); + msg_warn ("invalid expression argument"); return NULL; } @@ -854,7 +854,7 @@ rspamd_compare_encoding (struct worker_task *task, GList * args, void *unused) arg = get_function_arg (args->data, task, TRUE); if (arg->type == EXPRESSION_ARGUMENT_BOOL) { - msg_warn ("rspamd_compare_encoding: invalid argument to function is passed"); + msg_warn ("invalid argument to function is passed"); return FALSE; } @@ -874,7 +874,7 @@ rspamd_header_exists (struct worker_task * task, GList * args, void *unused) arg = get_function_arg (args->data, task, TRUE); if (!arg || arg->type == EXPRESSION_ARGUMENT_BOOL) { - msg_warn ("rspamd_header_exists: invalid argument to function is passed"); + msg_warn ("invalid argument to function is passed"); return FALSE; } @@ -901,7 +901,7 @@ rspamd_parts_distance (struct worker_task * task, GList * args, void *unused) struct expression_argument *arg; if (args == NULL) { - msg_debug ("rspamd_parts_distance: no threshold is specified, assume it 100"); + debug_task ("no threshold is specified, assume it 100"); threshold = 100; } else { @@ -909,7 +909,7 @@ rspamd_parts_distance (struct worker_task * task, GList * args, void *unused) arg = get_function_arg (args->data, task, TRUE); threshold = strtoul ((char *)arg->data, NULL, 10); if (errno != 0) { - msg_info ("rspamd_parts_distance: bad numeric value for threshold \"%s\", assume it 100", (char *)args->data); + msg_info ("bad numeric value for threshold \"%s\", assume it 100", (char *)args->data); threshold = 100; } } @@ -919,7 +919,7 @@ rspamd_parts_distance (struct worker_task * task, GList * args, void *unused) p1 = cur->data; cur = g_list_next (cur); if (cur == NULL) { - msg_info ("rspamd_parts_distance: bad parts list"); + msg_info ("bad parts list"); return FALSE; } p2 = cur->data; @@ -928,7 +928,7 @@ rspamd_parts_distance (struct worker_task * task, GList * args, void *unused) } } else { - msg_debug ("rspamd_parts_distance: message has too many text parts, so do not try to compare them with each other"); + debug_task ("message has too many text parts, so do not try to compare them with each other"); return FALSE; } @@ -947,14 +947,14 @@ rspamd_content_type_compare_param (struct worker_task * task, GList * args, void int r; if (args == NULL) { - msg_warn ("rspamd_content_type_compare_param: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } arg = get_function_arg (args->data, task, TRUE); param_name = arg->data; args = g_list_next (args); if (args == NULL) { - msg_warn ("rspamd_content_type_compare_param: too few params to function"); + msg_warn ("too few params to function"); return FALSE; } arg = get_function_arg (args->data, task, TRUE); @@ -973,7 +973,7 @@ rspamd_content_type_compare_param (struct worker_task * task, GList * args, void if ((re = re_cache_check (param_pattern)) == NULL) { re = parse_regexp (task->cfg->cfg_pool, param_pattern, task->cfg->raw_mode); if (re == NULL) { - msg_warn ("rspamd_content_type_compare_param: cannot compile regexp for function"); + msg_warn ("cannot compile regexp for function"); return FALSE; } re_cache_add (param_pattern, re); @@ -1011,7 +1011,7 @@ rspamd_content_type_has_param (struct worker_task * task, GList * args, void *un const GMimeContentType *ct; if (args == NULL) { - msg_warn ("rspamd_content_type_compare_param: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } arg = get_function_arg (args->data, task, TRUE); @@ -1021,7 +1021,7 @@ rspamd_content_type_has_param (struct worker_task * task, GList * args, void *un ct = g_mime_object_get_content_type (part); g_object_unref (part); - msg_debug ("rspamd_content_type_has_param: checking %s param", param_name); + debug_task ("checking %s param", param_name); if ((param_data = g_mime_content_type_get_parameter (ct, param_name)) == NULL) { return FALSE; @@ -1051,7 +1051,7 @@ rspamd_content_type_is_subtype (struct worker_task *task, GList * args, void *un int r; if (args == NULL) { - msg_warn ("rspamd_content_type_compare_param: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -1071,7 +1071,7 @@ rspamd_content_type_is_subtype (struct worker_task *task, GList * args, void *un if ((re = re_cache_check (param_pattern)) == NULL) { re = parse_regexp (task->cfg->cfg_pool, param_pattern, task->cfg->raw_mode); if (re == NULL) { - msg_warn ("rspamd_content_type_compare_param: cannot compile regexp for function"); + msg_warn ("cannot compile regexp for function"); return FALSE; } re_cache_add (param_pattern, re); @@ -1109,7 +1109,7 @@ rspamd_content_type_is_type (struct worker_task * task, GList * args, void *unus int r; if (args == NULL) { - msg_warn ("rspamd_content_type_compare_param: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -1130,7 +1130,7 @@ rspamd_content_type_is_type (struct worker_task * task, GList * args, void *unus if ((re = re_cache_check (param_pattern)) == NULL) { re = parse_regexp (task->cfg->cfg_pool, param_pattern, task->cfg->raw_mode); if (re == NULL) { - msg_warn ("rspamd_content_type_compare_param: cannot compile regexp for function"); + msg_warn ("cannot compile regexp for function"); return FALSE; } re_cache_add (param_pattern, re); @@ -1177,7 +1177,7 @@ rspamd_recipients_distance (struct worker_task *task, GList * args, void *unused int num, i, j, hits = 0, total = 0; if (args == NULL) { - msg_warn ("rspamd_content_type_compare_param: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -1185,7 +1185,7 @@ rspamd_recipients_distance (struct worker_task *task, GList * args, void *unused errno = 0; threshold = strtod ((char *)arg->data, NULL); if (errno != 0) { - msg_warn ("rspamd_recipients_distance: invalid numeric value '%s': %s", (char *)arg->data, strerror (errno)); + msg_warn ("invalid numeric value '%s': %s", (char *)arg->data, strerror (errno)); return FALSE; } @@ -1313,7 +1313,7 @@ compare_subtype (struct worker_task *task, const localContentType * ct, char *su if ((re = re_cache_check (subtype)) == NULL) { re = parse_regexp (task->cfg->cfg_pool, subtype, task->cfg->raw_mode); if (re == NULL) { - msg_warn ("compare_subtype: cannot compile regexp for function"); + msg_warn ("cannot compile regexp for function"); return FALSE; } re_cache_add (subtype, re); @@ -1380,7 +1380,7 @@ common_has_content_part (struct worker_task * task, char *param_type, char *para if ((re = re_cache_check (param_type)) == NULL) { re = parse_regexp (task->cfg->cfg_pool, param_type, task->cfg->raw_mode); if (re == NULL) { - msg_warn ("rspamd_has_content_part: cannot compile regexp for function"); + msg_warn ("cannot compile regexp for function"); cur = g_list_next (cur); continue; } @@ -1446,7 +1446,7 @@ rspamd_has_content_part (struct worker_task * task, GList * args, void *unused) struct expression_argument *arg; if (args == NULL) { - msg_warn ("rspamd_has_content_part: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -1469,7 +1469,7 @@ rspamd_has_content_part_len (struct worker_task * task, GList * args, void *unus struct expression_argument *arg; if (args == NULL) { - msg_warn ("rspamd_has_content_part_len: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -1485,7 +1485,7 @@ rspamd_has_content_part_len (struct worker_task * task, GList * args, void *unus errno = 0; min = strtoul (arg->data, NULL, 10); if (errno != 0) { - msg_warn ("rspamd_has_content_part_len: invalid numeric value '%s': %s", (char *)arg->data, strerror (errno)); + msg_warn ("invalid numeric value '%s': %s", (char *)arg->data, strerror (errno)); return FALSE; } args = args->next; @@ -1493,7 +1493,7 @@ rspamd_has_content_part_len (struct worker_task * task, GList * args, void *unus arg = get_function_arg (args->data, task, TRUE); max = strtoul (arg->data, NULL, 10); if (errno != 0) { - msg_warn ("rspamd_has_content_part_len: invalid numeric value '%s': %s", (char *)arg->data, strerror (errno)); + msg_warn ("invalid numeric value '%s': %s", (char *)arg->data, strerror (errno)); return FALSE; } } @@ -1511,7 +1511,7 @@ rspamd_compare_transfer_encoding (struct worker_task * task, GList * args, void struct expression_argument *arg; if (args == NULL) { - msg_warn ("rspamd_compare_transfer_encoding: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -1522,7 +1522,7 @@ rspamd_compare_transfer_encoding (struct worker_task * task, GList * args, void #else if (enc_req == GMIME_CONTENT_ENCODING_DEFAULT) { #endif - msg_warn ("rspamd_compare_transfer_encoding: bad encoding type: %s", (char *)arg->data); + msg_warn ("bad encoding type: %s", (char *)arg->data); return FALSE; } @@ -1531,7 +1531,7 @@ rspamd_compare_transfer_encoding (struct worker_task * task, GList * args, void if (GMIME_IS_PART (part)) { part_enc = g_mime_part_get_encoding (GMIME_PART (part)); - msg_debug ("rspamd_compare_transfer_encoding: got encoding in part: %d and compare with %d", (int)part_enc, (int)enc_req); + debug_task ("got encoding in part: %d and compare with %d", (int)part_enc, (int)enc_req); g_object_unref (part); return part_enc == enc_req; @@ -1601,14 +1601,14 @@ rspamd_has_html_tag (struct worker_task * task, GList * args, void *unused) struct html_callback_data cd; if (args == NULL) { - msg_warn ("rspamd_has_html_tag: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } arg = get_function_arg (args->data, task, TRUE); tag = get_tag_by_name (arg->data); if (tag == NULL) { - msg_warn ("rspamd_has_html_tag: unknown tag type passed as argument: %s", (char *)arg->data); + msg_warn ("unknown tag type passed as argument: %s", (char *)arg->data); return FALSE; } diff --git a/src/filter.c b/src/filter.c index 0734bcf56..0b1ecf583 100644 --- a/src/filter.c +++ b/src/filter.c @@ -124,6 +124,7 @@ consolidation_callback (gpointer key, gpointer value, gpointer arg) double *factor, fs, grow = 1; struct symbol *s = (struct symbol *)value; struct consolidation_callback_data *data = (struct consolidation_callback_data *)arg; + struct worker_task *task = data->task; if (data->count > 0) { grow = 1. + (data->task->cfg->grow_factor - 1.) * data->count; @@ -141,7 +142,7 @@ consolidation_callback (gpointer key, gpointer value, gpointer arg) else { factor = g_hash_table_lookup (data->task->worker->srv->cfg->factors, key); if (factor == NULL) { - msg_debug ("consolidation_callback: got %.2f score for metric %s, factor: 1", s->score, (char *)key); + debug_task ("got %.2f score for metric %s, factor: 1", s->score, (char *)key); data->score += s->score; } else { @@ -152,7 +153,7 @@ consolidation_callback (gpointer key, gpointer value, gpointer arg) else { data->score += *factor * s->score; } - msg_debug ("consolidation_callback: got %.2f score for metric %s, factor: %.2f", s->score, (char *)key, *factor); + debug_task ("got %.2f score for metric %s, factor: %.2f", s->score, (char *)key, *factor); } } } @@ -195,7 +196,7 @@ call_filter_by_name (struct worker_task *task, const char *name, enum filter_typ c_module->filter (task); } else { - msg_debug ("call_filter_by_name: %s is not a C module", name); + debug_task ("%s is not a C module", name); } break; case PERL_FILTER: @@ -205,12 +206,12 @@ call_filter_by_name (struct worker_task *task, const char *name, enum filter_typ #elif defined(WITH_LUA) lua_call_filter (name, task); #else - msg_err ("call_filter_by_name: trying to call perl function while perl support is disabled %s", name); + msg_err ("trying to call perl function while perl support is disabled %s", name); #endif break; } - msg_debug ("call_filter_by_name: filter name: %s, result: %d", name, (int)res); + debug_task ("filter name: %s, result: %d", name, (int)res); } static void @@ -233,7 +234,7 @@ metric_process_callback_common (gpointer key, gpointer value, void *data, gboole else { metric_res->score = factor_consolidation_func (task, metric_res->metric->name, NULL); } - msg_debug ("process_metric_callback: got result %.2f from consolidation function for metric %s", metric_res->score, metric_res->metric->name); + debug_task ("got result %.2f from consolidation function for metric %s", metric_res->score, metric_res->metric->name); } static void @@ -313,14 +314,14 @@ process_filters (struct worker_task *task) if (check_skip (task->cfg->views, task)) { task->is_skipped = TRUE; task->state = WRITE_REPLY; - msg_info ("process_filters: disable check for message id <%s>, view wants spam", task->message_id); + msg_info ("disable check for message id <%s>, view wants spam", task->message_id); return 1; } /* Check want spam setting */ if (check_want_spam (task)) { task->is_skipped = TRUE; task->state = WRITE_REPLY; - msg_info ("process_filters: disable check for message id <%s>, user wants spam", task->message_id); + msg_info ("disable check for message id <%s>, user wants spam", task->message_id); return 1; } @@ -445,7 +446,7 @@ check_autolearn (struct statfile_autolearn_params *params, struct worker_task *t /* For ham messages */ return TRUE; } - msg_debug ("check_autolearn: metric %s has no results", metric_name); + debug_task ("metric %s has no results", metric_name); return FALSE; } else { @@ -478,7 +479,7 @@ process_autolearn (struct statfile *st, struct worker_task *task, GTree * tokens if (check_autolearn (st->autolearn, task)) { if (tokens) { - msg_info ("process_autolearn: message with id <%s> autolearned statfile '%s'", task->message_id, filename); + msg_info ("message with id <%s> autolearned statfile '%s'", task->message_id, filename); /* Get or create statfile */ statfile = get_statfile_by_symbol (task->worker->srv->statfile_pool, ctx->cfg, @@ -548,7 +549,7 @@ classifiers_callback (gpointer value, void *arg) c.len = text_part->content->len; /* Tree would be freed at task pool freeing */ if (!cl->tokenizer->tokenize_func (cl->tokenizer, task->task_pool, &c, &tokens)) { - msg_info ("statfiles_callback: cannot tokenize input"); + msg_info ("cannot tokenize input"); return; } cur = g_list_next (cur); diff --git a/src/fuzzy_storage.c b/src/fuzzy_storage.c index 74ad90694..e05a479f6 100644 --- a/src/fuzzy_storage.c +++ b/src/fuzzy_storage.c @@ -102,7 +102,7 @@ sync_cache (struct rspamd_worker *wrk) return; } - msg_info ("sync_cache: syncing fuzzy hash storage"); + msg_info ("syncing fuzzy hash storage"); filename = g_hash_table_lookup (wrk->cf->params, "hashfile"); if (filename == NULL) { return; @@ -123,7 +123,7 @@ sync_cache (struct rspamd_worker *wrk) } if ((fd = open (filename, O_WRONLY | O_TRUNC | O_CREAT, S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH)) == -1) { - msg_err ("sync_cache: cannot create hash file %s: %s", filename, strerror (errno)); + msg_err ("cannot create hash file %s: %s", filename, strerror (errno)); return; } @@ -144,7 +144,7 @@ sync_cache (struct rspamd_worker *wrk) continue; } if (write (fd, node, sizeof (struct rspamd_fuzzy_node)) == -1) { - msg_err ("sync_cache: cannot write file %s: %s", filename, strerror (errno)); + msg_err ("cannot write file %s: %s", filename, strerror (errno)); } cur = g_list_next (cur); } @@ -207,7 +207,7 @@ read_hashes_file (struct rspamd_worker *wrk) } if ((fd = open (filename, O_RDONLY)) == -1) { - msg_err ("read_hashes_file: cannot open hash file %s: %s", filename, strerror (errno)); + msg_err ("cannot open hash file %s: %s", filename, strerror (errno)); return FALSE; } @@ -229,10 +229,10 @@ read_hashes_file (struct rspamd_worker *wrk) close (fd); if (r > 0) { - msg_warn ("read_hashes_file: ignore garbadge at the end of file, length of garbadge: %d", r); + msg_warn ("ignore garbadge at the end of file, length of garbadge: %d", r); } else if (r == -1) { - msg_err ("read_hashes_file: cannot open read file %s: %s", filename, strerror (errno)); + msg_err ("cannot open read file %s: %s", filename, strerror (errno)); return FALSE; } @@ -259,12 +259,12 @@ process_check_command (struct fuzzy_cmd *cmd) while (cur) { h = cur->data; if ((prob = fuzzy_compare_hashes (&h->h, &s)) > LEV_LIMIT) { - msg_info ("process_check_command: fuzzy hash was found, probability %d%%", prob); + msg_info ("fuzzy hash was found, probability %d%%", prob); return TRUE; } cur = g_list_next (cur); } - msg_debug ("process_check_command: fuzzy hash was NOT found, prob is %d%%", prob); + msg_debug ("fuzzy hash was NOT found, prob is %d%%", prob); return FALSE; } @@ -285,7 +285,7 @@ process_write_command (struct fuzzy_cmd *cmd) g_queue_push_head (hashes[cmd->blocksize % BUCKETS], h); bloom_add (bf, cmd->hash); mods++; - msg_info ("process_write_command: fuzzy hash was successfully added"); + msg_info ("fuzzy hash was successfully added"); return TRUE; } @@ -315,7 +315,7 @@ process_delete_command (struct fuzzy_cmd *cmd) cur = g_list_next (cur); g_queue_delete_link (hashes[cmd->blocksize % BUCKETS], tmp); bloom_del (bf, cmd->hash); - msg_info ("process_delete_command: fuzzy hash was successfully deleted"); + msg_info ("fuzzy hash was successfully deleted"); res = TRUE; mods++; continue; @@ -330,12 +330,12 @@ process_delete_command (struct fuzzy_cmd *cmd) do { \ if (process_##x##_command (&session->cmd)) { \ if (sendto (session->fd, "OK" CRLF, sizeof ("OK" CRLF) - 1, 0, (struct sockaddr *)&session->sa, session->salen) == -1) { \ - msg_err ("process_fuzzy_command: error while writing reply: %s", strerror (errno)); \ + msg_err ("error while writing reply: %s", strerror (errno)); \ } \ } \ else { \ if (sendto (session->fd, "ERR" CRLF, sizeof ("ERR" CRLF) - 1, 0, (struct sockaddr *)&session->sa, session->salen) == -1) { \ - msg_err ("process_fuzzy_command: error while writing reply: %s", strerror (errno)); \ + msg_err ("error while writing reply: %s", strerror (errno)); \ } \ } \ } while(0) @@ -355,7 +355,7 @@ process_fuzzy_command (struct fuzzy_session *session) break; default: if (sendto (session->fd, "ERR" CRLF, sizeof ("ERR" CRLF) - 1, 0, (struct sockaddr *)&session->sa, session->salen) == -1) { - msg_err ("process_fuzzy_command: error while writing reply: %s", strerror (errno)); + msg_err ("error while writing reply: %s", strerror (errno)); } break; } @@ -383,7 +383,7 @@ accept_fuzzy_socket (int fd, short what, void *arg) /* Got some data */ if (what == EV_READ) { if ((r = recvfrom (fd, session.pos, sizeof (struct fuzzy_cmd), MSG_WAITALL, (struct sockaddr *)&session.sa, &session.salen)) == -1) { - msg_err ("fuzzy_io_callback: got error while reading from socket: %d, %s", errno, strerror (errno)); + msg_err ("got error while reading from socket: %d, %s", errno, strerror (errno)); return; } else if (r == sizeof (struct fuzzy_cmd)) { @@ -391,7 +391,7 @@ accept_fuzzy_socket (int fd, short what, void *arg) process_fuzzy_command (&session); } else { - msg_err ("fuzzy_io_callback: got incomplete data while reading from socket: %d, %s", errno, strerror (errno)); + msg_err ("got incomplete data while reading from socket: %d, %s", errno, strerror (errno)); return; } } @@ -439,7 +439,7 @@ start_fuzzy_storage (struct rspamd_worker *worker) bf = bloom_create (20000000L, DEFAULT_BLOOM_HASHES); /* Try to read hashes from file */ if (!read_hashes_file (worker)) { - msg_err ("read_hashes_file: cannot read hashes file, it can be created after save procedure"); + msg_err ("cannot read hashes file, it can be created after save procedure"); } /* Timer event */ evtimer_set (&tev, sync_callback, worker); @@ -452,7 +452,7 @@ start_fuzzy_storage (struct rspamd_worker *worker) while ((worker->cf->listen_sock = make_udp_socket (&worker->cf->bind_addr, worker->cf->bind_port, TRUE, TRUE)) == -1) { sleep (1); if (++retries > MAX_RETRIES) { - msg_err ("start_fuzzy_storage: cannot bind to socket, exiting"); + msg_err ("cannot bind to socket, exiting"); exit (0); } } diff --git a/src/html.c b/src/html.c index b77e21bf1..654366799 100644 --- a/src/html.c +++ b/src/html.c @@ -757,7 +757,7 @@ add_html_node (struct worker_task *task, memory_pool_t * pool, struct mime_text_ else { new = construct_html_node (pool, tag_text); if (new == NULL) { - msg_debug ("add_html_node: cannot construct HTML node for text '%s'", tag_text); + debug_task ("cannot construct HTML node for text '%s'", tag_text); return -1; } data = new->data; @@ -766,12 +766,12 @@ add_html_node (struct worker_task *task, memory_pool_t * pool, struct mime_text_ } if (data->flags & FL_CLOSING) { if (!*cur_level) { - msg_debug ("add_html_node: bad parent node"); + debug_task ("bad parent node"); return FALSE; } g_node_append (*cur_level, new); if (!check_balance (new, cur_level)) { - msg_debug ("add_html_node: mark part as unbalanced as it has not pairable closing tags"); + debug_task ("mark part as unbalanced as it has not pairable closing tags"); part->is_balanced = FALSE; } } diff --git a/src/json/CMakeLists.txt b/src/json/CMakeLists.txt index e0f33c502..1f61d55a3 100644 --- a/src/json/CMakeLists.txt +++ b/src/json/CMakeLists.txt @@ -7,3 +7,4 @@ SET(JSONSRC dump.c value.c) ADD_LIBRARY(rspamd_json STATIC ${JSONSRC}) +SET_TARGET_PROPERTIES(rspamd_json PROPERTIES COMPILE_FLAGS "-DRSPAMD_LIB") diff --git a/src/lmtp.c b/src/lmtp.c index e07971f5e..636681c07 100644 --- a/src/lmtp.c +++ b/src/lmtp.c @@ -94,9 +94,10 @@ free_lmtp_task (struct rspamd_lmtp_proto *lmtp, gboolean is_soft) { GList *part; struct mime_part *p; + struct worker_task *task = lmtp->task; if (lmtp) { - msg_debug ("free_lmtp_task: free pointer %p", lmtp->task); + debug_task ("free pointer %p", lmtp->task); if (lmtp->task->memc_ctx) { memc_close_ctx (lmtp->task->memc_ctx); } @@ -137,7 +138,7 @@ lmtp_read_socket (f_str_t * in, void *arg) case READ_COMMAND: case READ_HEADER: if (read_lmtp_input_line (lmtp, in) != 0) { - msg_info ("read_lmtp_socket: closing lmtp connection due to protocol error"); + msg_info ("closing lmtp connection due to protocol error"); lmtp->task->state = CLOSING_CONNECTION; } /* Task was read, recall read handler once more with new state to process message and write reply */ @@ -165,7 +166,7 @@ lmtp_read_socket (f_str_t * in, void *arg) } break; default: - msg_debug ("lmtp_read_socket: invalid state while reading from socket %d", lmtp->task->state); + debug_task ("invalid state while reading from socket %d", lmtp->task->state); break; } @@ -179,6 +180,7 @@ static gboolean lmtp_write_socket (void *arg) { struct rspamd_lmtp_proto *lmtp = (struct rspamd_lmtp_proto *)arg; + struct worker_task *task = lmtp->task; switch (lmtp->task->state) { case WRITE_REPLY: @@ -194,12 +196,12 @@ lmtp_write_socket (void *arg) lmtp->task->state = CLOSING_CONNECTION; break; case CLOSING_CONNECTION: - msg_debug ("lmtp_write_socket: normally closing connection"); + debug_task ("normally closing connection"); free_lmtp_task (lmtp, TRUE); return FALSE; break; default: - msg_debug ("lmtp_write_socket: invalid state while writing to socket %d", lmtp->task->state); + debug_task ("invalid state while writing to socket %d", lmtp->task->state); break; } @@ -213,7 +215,7 @@ static void lmtp_err_socket (GError * err, void *arg) { struct rspamd_lmtp_proto *lmtp = (struct rspamd_lmtp_proto *)arg; - msg_info ("lmtp_err_socket: abnormally closing connection, error: %s", err->message); + msg_info ("abnormally closing connection, error: %s", err->message); /* Free buffers */ free_lmtp_task (lmtp, FALSE); } @@ -226,21 +228,31 @@ accept_socket (int fd, short what, void *arg) { struct rspamd_worker *worker = (struct rspamd_worker *)arg; struct sockaddr_storage ss; + struct sockaddr_in *sin; struct worker_task *new_task; struct rspamd_lmtp_proto *lmtp; socklen_t addrlen = sizeof (ss); int nfd; if ((nfd = accept_from_socket (fd, (struct sockaddr *)&ss, &addrlen)) == -1) { - msg_warn ("accept_socket: accept failed: %s", strerror (errno)); + msg_warn ("accept failed: %s", strerror (errno)); return; } lmtp = g_malloc (sizeof (struct rspamd_lmtp_proto)); - new_task = g_malloc (sizeof (struct worker_task)); - bzero (new_task, sizeof (struct worker_task)); - new_task->worker = worker; - new_task->state = READ_COMMAND; + + new_task = construct_task (worker); + + if (ss.ss_family == AF_UNIX) { + msg_info ("accepted connection from unix socket"); + new_task->client_addr.s_addr = INADDR_NONE; + } + else if (ss.ss_family == AF_INET) { + sin = (struct sockaddr_in *)&ss; + msg_info ("accepted connection from %s port %d", inet_ntoa (sin->sin_addr), ntohs (sin->sin_port)); + memcpy (&new_task->client_addr, &sin->sin_addr, sizeof (struct in_addr)); + } + new_task->sock = nfd; new_task->cfg = worker->srv->cfg; new_task->task_pool = memory_pool_new (memory_pool_get_size ()); @@ -254,6 +266,7 @@ accept_socket (int fd, short what, void *arg) /* Set up dispatcher */ new_task->dispatcher = rspamd_create_dispatcher (nfd, BUFFER_LINE, lmtp_read_socket, lmtp_write_socket, lmtp_err_socket, &io_tv, (void *)lmtp); + new_task->dispatcher->peer_addr = new_task->client_addr.s_addr; rspamd_dispatcher_write (lmtp->task->dispatcher, greetingbuf, strlen (greetingbuf), FALSE, FALSE); } diff --git a/src/lmtp_proto.c b/src/lmtp_proto.c index 2c0ffa9d4..20d02e4f9 100644 --- a/src/lmtp_proto.c +++ b/src/lmtp_proto.c @@ -114,7 +114,7 @@ read_lmtp_input_line (struct rspamd_lmtp_proto *lmtp, f_str_t * line) case LMTP_READ_LHLO: /* Search LHLO line */ if ((i = fstrstri (line, &lhlo_command)) == -1) { - msg_info ("read_lmtp_input_line: LHLO expected but not found"); + msg_info ("LHLO expected but not found"); out_lmtp_reply (lmtp->task, LMTP_BAD_CMD, "5.0.0", "Need LHLO here"); return -1; } @@ -137,7 +137,7 @@ read_lmtp_input_line (struct rspamd_lmtp_proto *lmtp, f_str_t * line) case LMTP_READ_FROM: /* Search MAIL FROM: line */ if ((i = fstrstri (line, &mail_command)) == -1) { - msg_info ("read_lmtp_input_line: MAIL expected but not found"); + msg_info ("MAIL expected but not found"); out_lmtp_reply (lmtp->task, LMTP_BAD_CMD, "5.0.0", "Need MAIL here"); return -1; } @@ -155,7 +155,7 @@ read_lmtp_input_line (struct rspamd_lmtp_proto *lmtp, f_str_t * line) case LMTP_READ_RCPT: /* Search RCPT_TO: line */ if ((i = fstrstri (line, &rcpt_command)) == -1) { - msg_info ("read_lmtp_input_line: RCPT expected but not found"); + msg_info ("RCPT expected but not found"); out_lmtp_reply (lmtp->task, LMTP_NO_RCPT, "5.5.4", "Need RCPT here"); return -1; } @@ -167,7 +167,7 @@ read_lmtp_input_line (struct rspamd_lmtp_proto *lmtp, f_str_t * line) rcpt = extract_mail (lmtp->task->task_pool, &fstr); if (*rcpt == '<' && *(rcpt + 1) == '>') { /* Invalid or empty rcpt not allowed */ - msg_info ("read_lmtp_input_line: bad recipient"); + msg_info ("bad recipient"); out_lmtp_reply (lmtp->task, LMTP_NO_RCPT, "5.5.4", "Bad recipient"); return -1; } @@ -181,7 +181,7 @@ read_lmtp_input_line (struct rspamd_lmtp_proto *lmtp, f_str_t * line) case LMTP_READ_DATA: /* Search DATA line */ if ((i = fstrstri (line, &data_command)) == -1) { - msg_info ("read_lmtp_input_line: DATA expected but not found"); + msg_info ("DATA expected but not found"); out_lmtp_reply (lmtp->task, LMTP_BAD_CMD, "5.0.0", "Need DATA here"); return -1; } @@ -321,7 +321,7 @@ mta_read_socket (f_str_t * in, void *arg) switch (cd->state) { case LMTP_WANT_GREETING: if (!parse_mta_str (in, cd)) { - msg_warn ("mta_read_socket: got bad greeting"); + msg_warn ("got bad greeting"); close_mta_connection (cd, FALSE); return FALSE; } @@ -340,7 +340,7 @@ mta_read_socket (f_str_t * in, void *arg) break; case LMTP_WANT_MAIL: if (!parse_mta_str (in, cd)) { - msg_warn ("mta_read_socket: got bad helo"); + msg_warn ("got bad helo"); close_mta_connection (cd, FALSE); return FALSE; } @@ -350,7 +350,7 @@ mta_read_socket (f_str_t * in, void *arg) break; case LMTP_WANT_RCPT: if (!parse_mta_str (in, cd)) { - msg_warn ("mta_read_socket: got bad mail from"); + msg_warn ("got bad mail from"); close_mta_connection (cd, FALSE); return FALSE; } @@ -366,7 +366,7 @@ mta_read_socket (f_str_t * in, void *arg) break; case LMTP_WANT_DATA: if (!parse_mta_str (in, cd)) { - msg_warn ("mta_read_socket: got bad rcpt"); + msg_warn ("got bad rcpt"); close_mta_connection (cd, FALSE); return FALSE; } @@ -376,7 +376,7 @@ mta_read_socket (f_str_t * in, void *arg) break; case LMTP_WANT_DOT: if (!parse_mta_str (in, cd)) { - msg_warn ("mta_read_socket: got bad data"); + msg_warn ("got bad data"); close_mta_connection (cd, FALSE); return FALSE; } @@ -389,7 +389,7 @@ mta_read_socket (f_str_t * in, void *arg) cd->state = LMTP_WANT_CLOSING; case LMTP_WANT_CLOSING: if (!parse_mta_str (in, cd)) { - msg_warn ("mta_read_socket: message not delivered"); + msg_warn ("message not delivered"); close_mta_connection (cd, FALSE); return FALSE; } @@ -407,7 +407,7 @@ static void mta_err_socket (GError * err, void *arg) { struct mta_callback_data *cd = (struct mta_callback_data *)arg; - msg_info ("mta_err_socket: abnormaly terminating connection with MTA"); + msg_info ("abnormaly terminating connection with MTA"); close_mta_connection (cd, FALSE); } @@ -429,7 +429,7 @@ lmtp_deliver_mta (struct worker_task *task) sock = make_tcp_socket (&task->cfg->deliver_addr, task->cfg->deliver_port, FALSE, TRUE); } if (sock == -1) { - msg_warn ("lmtp_deliver_mta: cannot create socket for %s, %s", task->cfg->deliver_host, strerror (errno)); + msg_warn ("cannot create socket for %s, %s", task->cfg->deliver_host, strerror (errno)); } cd = memory_pool_alloc (task->task_pool, sizeof (struct mta_callback_data)); @@ -537,13 +537,13 @@ lmtp_deliver_lda (struct worker_task *task) /* Format arguments in shell style */ if (!g_shell_parse_argv (args, &argc, &argv, NULL)) { - msg_info ("lmtp_deliver_lda: cannot parse arguments"); + msg_info ("cannot parse arguments"); return -1; } if (pipe (p) == -1) { g_strfreev (argv); - msg_info ("lmtp_deliver_lda: cannot open pipe: %s", strerror (errno)); + msg_info ("cannot open pipe: %s", strerror (errno)); return -1; } @@ -551,13 +551,13 @@ lmtp_deliver_lda (struct worker_task *task) #ifdef HAVE_VFORK if ((cpid = vfork ()) == -1) { g_strfreev (argv); - msg_info ("lmtp_deliver_lda: cannot fork: %s", strerror (errno)); + msg_info ("cannot fork: %s", strerror (errno)); return -1; } #else if ((cpid = fork ()) == -1) { g_strfreev (argv); - msg_info ("lmtp_deliver_lda: cannot fork: %s", strerror (errno)); + msg_info ("cannot fork: %s", strerror (errno)); return -1; } #endif @@ -580,7 +580,7 @@ lmtp_deliver_lda (struct worker_task *task) if (g_mime_object_write_to_stream ((GMimeObject *) task->message, stream) == -1) { g_strfreev (argv); - msg_info ("lmtp_deliver_lda: cannot write stream to lda"); + msg_info ("cannot write stream to lda"); return -1; } @@ -600,7 +600,7 @@ lmtp_deliver_lda (struct worker_task *task) #endif if (rc == -1) { g_strfreev (argv); - msg_info ("lmtp_deliver_lda: lda returned error code"); + msg_info ("lda returned error code"); return -1; } else if (WIFEXITED (rc)) { @@ -611,7 +611,7 @@ lmtp_deliver_lda (struct worker_task *task) } else { g_strfreev (argv); - msg_info ("lmtp_deliver_lda: lda returned error code %d", ecode); + msg_info ("lda returned error code %d", ecode); return -1; } } @@ -637,8 +637,9 @@ int write_lmtp_reply (struct rspamd_lmtp_proto *lmtp) { int r; + struct worker_task *task = lmtp->task; - msg_debug ("write_lmtp_reply: writing reply to client"); + debug_task ("writing reply to client"); if (lmtp->task->error_code != 0) { out_lmtp_reply (lmtp->task, lmtp->task->error_code, "", lmtp->task->last_error); } diff --git a/src/logger.c b/src/logger.c new file mode 100644 index 000000000..0d8daa75f --- /dev/null +++ b/src/logger.c @@ -0,0 +1,417 @@ +/* + * Copyright (c) 2009, Rambler media + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are met: + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * * Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in the + * documentation and/or other materials provided with the distribution. + * + * THIS SOFTWARE IS PROVIDED BY Rambler media ''AS IS'' AND ANY + * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED + * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE + * DISCLAIMED. IN NO EVENT SHALL Rambler BE LIABLE FOR ANY + * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES + * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; + * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND + * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT + * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS + * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + */ + + +#include "config.h" +#include "logger.h" +#include "util.h" +#include "main.h" +#include "map.h" + + +#ifdef RSPAMD_MAIN +sig_atomic_t do_reopen_log = 0; +#endif + +rspamd_logger_t *rspamd_log; + +static const char lf_chr = '\n'; + +static void +syslog_log_function (const gchar * log_domain, const gchar *function, + GLogLevelFlags log_level, const gchar * message, + gboolean forced, gpointer arg); +static void +file_log_function (const gchar * log_domain, const gchar *function, + GLogLevelFlags log_level, const gchar * message, + gboolean forced, gpointer arg); + +static void +direct_write_log_line (void *data, int count, gboolean is_iov) +{ + char errmsg[128]; + struct iovec *iov; + const char *line; + int r; + + if (rspamd_log->enabled) { + if (is_iov) { + iov = (struct iovec *)data; + r = writev (rspamd_log->fd, iov, count); + } + else { + line = (const char *)data; + r = write (rspamd_log->fd, line, count); + } + if (r == -1) { + /* We cannot write message to file, so we need to detect error and make decision */ + r = rspamd_snprintf (errmsg, sizeof (errmsg), "direct_write_log_line: cannot write log line: %s", strerror (errno)); + if (errno == EBADF || errno == EIO || errno == EINTR) { + /* Descriptor is somehow invalid, try to restart */ + reopen_log (); + if (write (rspamd_log->fd, errmsg, r) != -1) { + /* Try again */ + direct_write_log_line (data, count, is_iov); + } + } + else if (errno == EFAULT || errno == EINVAL || errno == EFBIG || errno == ENOSPC) { + /* Rare case */ + (void)write (rspamd_log->fd, errmsg, r); + } + else if (errno == EPIPE) { + /* We write to some pipe and it disappears, disable logging */ + rspamd_log->enabled = FALSE; + } + } + } +} + +/* Logging utility functions */ +int +open_log (void) +{ + + rspamd_log->enabled = TRUE; + + switch (rspamd_log->cfg->log_type) { + case RSPAMD_LOG_CONSOLE: + /* Do nothing with console */ + return 0; + case RSPAMD_LOG_SYSLOG: + openlog ("rspamd", LOG_NDELAY | LOG_PID, rspamd_log->cfg->log_facility); + return 0; + case RSPAMD_LOG_FILE: + rspamd_log->fd = open (rspamd_log->cfg->log_file, O_CREAT | O_WRONLY | O_APPEND, S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH); + if (rspamd_log->fd == -1) { + fprintf (stderr, "open_log: cannot open desired log file: %s, %s", rspamd_log->cfg->log_file, strerror (errno)); + return -1; + } + return 0; + } + return -1; +} + +void +close_log (void) +{ + flush_log_buf (); + + switch (rspamd_log->type) { + case RSPAMD_LOG_CONSOLE: + /* Do nothing special */ + break; + case RSPAMD_LOG_SYSLOG: + closelog (); + break; + case RSPAMD_LOG_FILE: + if (rspamd_log->enabled) { + if (fsync (rspamd_log->fd) == -1) { + msg_err ("error syncing log file: %s", strerror (errno)); + } + close (rspamd_log->fd); + } + break; + } + + rspamd_log->enabled = FALSE; +} + +void +rspamd_set_logger (enum rspamd_log_type type, struct config_file *cfg) +{ + char **strvec, *p, *err; + int num, i, k; + struct in_addr addr; + uint32_t mask = 0xFFFFFFFF; + + if (rspamd_log == NULL) { + rspamd_log = g_malloc (sizeof (rspamd_logger_t)); + bzero (rspamd_log, sizeof (rspamd_logger_t)); + } + + rspamd_log->type = type; + rspamd_log->pid = getpid (); + + switch (type) { + case RSPAMD_LOG_CONSOLE: + rspamd_log->log_func = file_log_function; + rspamd_log->fd = STDERR_FILENO; + break; + case RSPAMD_LOG_SYSLOG: + rspamd_log->log_func = syslog_log_function; + break; + case RSPAMD_LOG_FILE: + rspamd_log->log_func = file_log_function; + break; + } + + rspamd_log->cfg = cfg; + /* Set up buffer */ + if (cfg->log_buffered) { + if (cfg->log_buf_size != 0) { + rspamd_log->io_buf.size = cfg->log_buf_size; + } + else { + rspamd_log->io_buf.size = BUFSIZ; + } + rspamd_log->is_buffered = TRUE; + rspamd_log->io_buf.buf = g_malloc (rspamd_log->io_buf.size); + } + /* Set up conditional logging */ + if (cfg->debug_ip_map != NULL) { + /* Try to add it as map first of all */ + rspamd_log->debug_ip = radix_tree_create (); + if (!add_map (cfg->debug_ip_map, read_radix_list, fin_radix_list, (void **)&rspamd_log->debug_ip)) { + /* Try to parse it as list */ + strvec = g_strsplit (cfg->debug_ip_map, ",; ", 0); + num = g_strv_length (strvec); + + for (i = 0; i < num; i++) { + g_strstrip (strvec[i]); + + if ((p = strchr (strvec[i], '/')) != NULL) { + /* Try to extract mask */ + *p = '\0'; + p ++; + errno = 0; + k = strtoul (p, &err, 10); + if (errno != 0 || *err != '\0' || k > 32) { + continue; + } + } + else { + k = 32; + } + if (inet_aton (strvec[i], &addr)) { + /* Check ip */ + mask = mask << (32 - k); + radix32tree_insert (rspamd_log->debug_ip, ntohl (addr.s_addr), mask, 1); + } + } + g_strfreev (strvec); + } + } +} + +int +reopen_log (void) +{ +#ifdef RSPAMD_MAIN + do_reopen_log = 0; +#endif + close_log (); + return open_log (); +} + +void +update_log_pid (void) +{ + rspamd_log->pid = getpid (); +} + +void +flush_log_buf (void) +{ + if (rspamd_log->is_buffered && (rspamd_log->type == RSPAMD_LOG_CONSOLE || rspamd_log->type == RSPAMD_LOG_FILE)) { + direct_write_log_line (rspamd_log->io_buf.buf, rspamd_log->io_buf.used, FALSE); + rspamd_log->io_buf.used = 0; + } +} + + +void +rspamd_common_log_function (GLogLevelFlags log_level, const char *function, const char *fmt, ...) +{ + static char logbuf[BUFSIZ]; + va_list vp; + u_char *end; + + if (log_level <= rspamd_log->cfg->log_level) { + va_start (vp, fmt); + end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); + *end = '\0'; + va_end (vp); + rspamd_log->log_func (NULL, function, log_level, logbuf, FALSE, rspamd_log->cfg); + } +} + + +/* Fill buffer with message (limits must be checked BEFORE this call) */ +static void +fill_buffer (const struct iovec *iov, int iovcnt) +{ + int i; + + for (i = 0; i < iovcnt; i ++) { + memcpy (rspamd_log->io_buf.buf + rspamd_log->io_buf.used, iov[i].iov_base, iov[i].iov_len); + rspamd_log->io_buf.used += iov[i].iov_len; + } + +} + +/* Write message to buffer or to file */ +static void +file_log_helper (const struct iovec *iov, int iovcnt) +{ + size_t len = 0; + int i; + + if (! rspamd_log->is_buffered) { + /* Write string directly */ + direct_write_log_line ((void *)iov, iovcnt, TRUE); + } + else { + /* Calculate total length */ + for (i = 0; i < iovcnt; i ++) { + len += iov[i].iov_len; + } + /* Fill buffer */ + if (rspamd_log->io_buf.size < len) { + /* Buffer is too small to hold this string, so write it dirrectly */ + flush_log_buf (); + direct_write_log_line ((void *)iov, iovcnt, TRUE); + } + else if (rspamd_log->io_buf.used + len >= rspamd_log->io_buf.size) { + /* Buffer is full, try to write it dirrectly */ + flush_log_buf (); + fill_buffer (iov, iovcnt); + } + else { + /* Copy incoming string to buffer */ + fill_buffer (iov, iovcnt); + } + } +} + +static void +syslog_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg) +{ + struct config_file *cfg = (struct config_file *)arg; +#ifdef RSPAMD_MAIN + if (do_reopen_log) { + reopen_log (); + } +#endif + if (! rspamd_log->enabled) { + return; + } + if (function == NULL) { + if (forced || log_level <= cfg->log_level) { + if (forced || log_level >= G_LOG_LEVEL_DEBUG) { + syslog (LOG_DEBUG, "%s", message); + } + else if (log_level >= G_LOG_LEVEL_INFO) { + syslog (LOG_INFO, "%s", message); + } + else if (log_level >= G_LOG_LEVEL_WARNING) { + syslog (LOG_WARNING, "%s", message); + } + else if (log_level >= G_LOG_LEVEL_CRITICAL) { + syslog (LOG_ERR, "%s", message); + } + } + } + else { + if (forced || log_level <= cfg->log_level) { + if (log_level >= G_LOG_LEVEL_DEBUG) { + syslog (LOG_DEBUG, "%s: %s", function, message); + } + else if (log_level >= G_LOG_LEVEL_INFO) { + syslog (LOG_INFO, "%s: %s", function, message); + } + else if (log_level >= G_LOG_LEVEL_WARNING) { + syslog (LOG_WARNING, "%s: %s", function, message); + } + else if (log_level >= G_LOG_LEVEL_CRITICAL) { + syslog (LOG_ERR, "%s: %s", function, message); + } + } + } +} + +static void +file_log_function (const gchar * log_domain, const gchar *function, GLogLevelFlags log_level, const gchar * message, gboolean forced, gpointer arg) +{ + char tmpbuf[256], timebuf[32]; + time_t now; + struct tm *tms; + struct iovec iov[3]; + int r; + + if (! rspamd_log->enabled) { + return; + } +#ifdef RSPAMD_MAIN + if (do_reopen_log) { + reopen_log (); + } +#endif + + if (forced || log_level <= rspamd_log->cfg->log_level) { + now = time (NULL); + tms = localtime (&now); + + strftime (timebuf, sizeof (timebuf), "%b %d %H:%M:%S", tms); + if (function == NULL) { + r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P: %s rspamd ", rspamd_log->pid, timebuf); + } + else { + r = rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P: %s rspamd %s: ", rspamd_log->pid, timebuf, function); + } + iov[0].iov_base = tmpbuf; + iov[0].iov_len = r; + iov[1].iov_base = (void *)message; + iov[1].iov_len = strlen (message); + iov[2].iov_base = (void *)&lf_chr; + iov[2].iov_len = 1; + + file_log_helper (iov, 3); + } +} + +void +rspamd_conditional_debug (uint32_t addr, const char *function, const char *fmt, ...) +{ + static char logbuf[BUFSIZ]; + va_list vp; + u_char *end; + + if (rspamd_log->cfg->log_level >= G_LOG_LEVEL_DEBUG || + (rspamd_log->debug_ip != NULL && radix32tree_find (rspamd_log->debug_ip, ntohl (addr)) != RADIX_NO_VALUE)) { + + va_start (vp, fmt); + end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); + *end = '\0'; + va_end (vp); + rspamd_log->log_func (NULL, function, G_LOG_LEVEL_DEBUG, logbuf, TRUE, rspamd_log->cfg); + } +} + +void +rspamd_glib_log_function (const gchar *log_domain, GLogLevelFlags log_level, const gchar *message, gpointer arg) +{ + if (rspamd_log->enabled) { + rspamd_log->log_func (log_domain, NULL, log_level, message, FALSE, rspamd_log->cfg); + } +} diff --git a/src/logger.h b/src/logger.h new file mode 100644 index 000000000..e86901cfc --- /dev/null +++ b/src/logger.h @@ -0,0 +1,87 @@ +#ifndef RSPAMD_LOGGER_H +#define RSPAMD_LOGGER_H + +#include "config.h" +#include "cfg_file.h" +#include "radix.h" + +typedef void (*rspamd_log_func_t)(const gchar * log_domain, const gchar *function, + GLogLevelFlags log_level, const gchar * message, + gboolean forced, gpointer arg); + +typedef struct rspamd_logger_s { + rspamd_log_func_t log_func; + struct config_file *cfg; + struct { + uint32_t size; + uint32_t used; + u_char *buf; + } io_buf; + int fd; + gboolean is_buffered; + gboolean enabled; + enum rspamd_log_type type; + pid_t pid; + radix_tree_t *debug_ip; +} rspamd_logger_t; + +/** + * Init logger + */ +void rspamd_set_logger (enum rspamd_log_type type, struct config_file *cfg); +/** + * Open log file or initialize other structures + */ +int open_log (void); +/** + * Close log file or destroy other structures + */ +void close_log (void); +/** + * Close and open log again + */ +int reopen_log (void); +/** + * Set log pid + */ +void update_log_pid (void); + +/** + * Flush log buffer for some types of logging + */ +void flush_log_buf (void); +/** + * Log function that is compatible for glib messages + */ +void rspamd_glib_log_function (const gchar *log_domain, GLogLevelFlags log_level, const gchar *message, gpointer arg); + +/** + * Function with variable number of arguments support + */ +void rspamd_common_log_function (GLogLevelFlags log_level, const char *function, const char *fmt, ...); + +/** + * Conditional debug function + */ +void rspamd_conditional_debug (uint32_t addr, const char *function, const char *fmt, ...) ; + + +/* Typical functions */ + +/* Logging in postfix style */ +#if (defined(RSPAMD_MAIN) || defined(RSPAMD_LIB)) +#define msg_err(args...) rspamd_common_log_function(G_LOG_LEVEL_CRITICAL, __FUNCTION__, ##args) +#define msg_warn(args...) rspamd_common_log_function(G_LOG_LEVEL_WARNING, __FUNCTION__, ##args) +#define msg_info(args...) rspamd_common_log_function(G_LOG_LEVEL_INFO, __FUNCTION__, ##args) +#define msg_debug(args...) rspamd_common_log_function(G_LOG_LEVEL_DEBUG, __FUNCTION__, ##args) +#define debug_task(args...) rspamd_conditional_debug(task->from_addr.s_addr, __FUNCTION__, ##args) +#define debug_ip(ip, args...) rspamd_conditional_debug((ip), __FUNCTION__, ##args) +#else +#define msg_err(args...) fprintf(stderr, ##args) +#define msg_warn(args...) fprintf(stderr, ##args) +#define msg_info(args...) fprintf(stderr, ##args) +#define msg_debug(args...) fprintf(stderr, ##args) +#define debug_task(args...) fprintf(stderr, ##args) +#endif + +#endif diff --git a/src/lua/CMakeLists.txt b/src/lua/CMakeLists.txt index 298b81025..d0ac4f826 100644 --- a/src/lua/CMakeLists.txt +++ b/src/lua/CMakeLists.txt @@ -7,3 +7,4 @@ SET(LUASRC lua_common.c ADD_LIBRARY(rspamd_lua STATIC ${LUASRC}) TARGET_LINK_LIBRARIES(rspamd_lua ${LUALIB}) +SET_TARGET_PROPERTIES(rspamd_lua PROPERTIES COMPILE_FLAGS "-DRSPAMD_LIB") diff --git a/src/lua/lua_classifier.c b/src/lua/lua_classifier.c index ed6cdee42..86378c5e5 100644 --- a/src/lua/lua_classifier.c +++ b/src/lua/lua_classifier.c @@ -90,7 +90,7 @@ call_classifier_pre_callbacks (struct classifier_config *ccf, struct worker_task *ptask = task; if (lua_pcall (cd->L, 2, 1, 0) != 0) { - msg_warn ("call_classifier_pre_callbacks: error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); + msg_warn ("error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); } else { if (lua_istable (cd->L, 1)) { @@ -138,7 +138,7 @@ call_classifier_post_callbacks (struct classifier_config *ccf, struct worker_tas lua_pushnumber (cd->L, out); if (lua_pcall (cd->L, 3, 1, 0) != 0) { - msg_warn ("call_classifier_pre_callbacks: error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); + msg_warn ("error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); } else { if (lua_isnumber (cd->L, 1)) { diff --git a/src/lua/lua_common.c b/src/lua/lua_common.c index 1ad61aaf0..1d2f46c3a 100644 --- a/src/lua/lua_common.c +++ b/src/lua/lua_common.c @@ -214,7 +214,7 @@ init_lua_filters (struct config_file *cfg) module = cur->data; if (module->path) { if (luaL_loadfile (L, module->path) != 0) { - msg_info ("lua_init_filters: load of %s failed: %s", module->path, lua_tostring (L, -1)); + msg_info ("load of %s failed: %s", module->path, lua_tostring (L, -1)); cur = g_list_next (cur); continue; } @@ -226,7 +226,7 @@ init_lua_filters (struct config_file *cfg) lua_setglobal (L, "rspamd_config"); /* do the call (1 arguments, 1 result) */ if (lua_pcall (L, 0, LUA_MULTRET, 0) != 0) { - msg_info ("lua_init_filters: init of %s failed: %s", module->path, lua_tostring (L, -1)); + msg_info ("init of %s failed: %s", module->path, lua_tostring (L, -1)); } } cur = g_list_next (cur); @@ -247,12 +247,12 @@ lua_call_filter (const char *function, struct worker_task *task) *ptask = task; if (lua_pcall (L, 1, 1, 0) != 0) { - msg_info ("lua_call_filter: call to %s failed", function); + msg_info ("call to %s failed", function); } /* retrieve result */ if (!lua_isnumber (L, -1)) { - msg_info ("lua_call_filter: function %s must return a number", function); + msg_info ("function %s must return a number", function); } result = lua_tonumber (L, -1); lua_pop (L, 1); /* pop returned value */ @@ -270,12 +270,12 @@ lua_call_chain_filter (const char *function, struct worker_task *task, int *mark lua_pushnumber (L, marks[i]); } if (lua_pcall (L, number, 1, 0) != 0) { - msg_info ("lua_init_filters: call to %s failed", function); + msg_info ("call to %s failed", function); } /* retrieve result */ if (!lua_isnumber (L, -1)) { - msg_info ("lua_call_header_filter: function %s must return a number", function); + msg_info ("function %s must return a number", function); } result = lua_tonumber (L, -1); lua_pop (L, 1); /* pop returned value */ @@ -303,12 +303,12 @@ lua_consolidation_callback (gpointer key, gpointer value, gpointer arg) lua_pushstring (L, (const char *)key); lua_pushnumber (L, s->score); if (lua_pcall (L, 2, 1, 0) != 0) { - msg_info ("lua_consolidation_callback: call to %s failed", data->func); + msg_info ("call to %s failed", data->func); } /* retrieve result */ if (!lua_isnumber (L, -1)) { - msg_info ("lua_consolidation_callback: function %s must return a number", data->func); + msg_info ("function %s must return a number", data->func); } res = lua_tonumber (L, -1); lua_pop (L, 1); /* pop returned value */ diff --git a/src/lua/lua_config.c b/src/lua/lua_config.c index fa23134a9..bbbab4a53 100644 --- a/src/lua/lua_config.c +++ b/src/lua/lua_config.c @@ -301,7 +301,7 @@ lua_config_function_callback (struct worker_task *task, GList *args, void *user_ } if (lua_pcall (cd->L, i, 1, 0) != 0) { - msg_warn ("lua_metric_symbol_callback: error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); + msg_warn ("error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); } else { if (lua_isboolean (cd->L, 1)) { @@ -345,7 +345,7 @@ lua_config_add_radix_map (lua_State *L) r = g_malloc (sizeof (radix_tree_t *)); *r = radix_tree_create (); if (!add_map (map_line, read_radix_list, fin_radix_list, (void **)r)) { - msg_warn ("add_radix_map: invalid radix map %s", map_line); + msg_warn ("invalid radix map %s", map_line); radix_tree_free (*r); g_free (r); lua_pushnil (L); @@ -375,7 +375,7 @@ lua_config_add_hash_map (lua_State *L) r = g_malloc (sizeof (GHashTable *)); *r = g_hash_table_new (rspamd_strcase_hash, rspamd_strcase_equal); if (!add_map (map_line, read_host_list, fin_host_list, (void **)r)) { - msg_warn ("add_radix_map: invalid hash map %s", map_line); + msg_warn ("invalid hash map %s", map_line); g_hash_table_destroy (*r); g_free (r); lua_pushnil (L); @@ -408,7 +408,7 @@ lua_metric_symbol_callback (struct worker_task *task, gpointer ud) *ptask = task; if (lua_pcall (cd->L, 1, 1, 0) != 0) { - msg_warn ("lua_metric_symbol_callback: error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); + msg_warn ("error running function %s: %s", cd->name, lua_tostring (cd->L, -1)); } } diff --git a/src/lua/lua_task.c b/src/lua/lua_task.c index cfacf3f2f..dec415f9b 100644 --- a/src/lua/lua_task.c +++ b/src/lua/lua_task.c @@ -284,7 +284,7 @@ lua_dns_callback (int result, char type, int count, int ttl, void *addresses, vo } if (lua_pcall (cd->L, 4, 0, 0) != 0) { - msg_info ("lua_dns_callback: call to %s failed: %s", cd->callback, lua_tostring (cd->L, -1)); + msg_info ("call to %s failed: %s", cd->callback, lua_tostring (cd->L, -1)); } cd->task->save.saved--; @@ -310,7 +310,7 @@ lua_task_resolve_dns_a (lua_State * L) cd->to_resolve = memory_pool_strdup (task->task_pool, luaL_checkstring (L, 2)); cd->callback = memory_pool_strdup (task->task_pool, luaL_checkstring (L, 3)); if (!cd->to_resolve || !cd->callback) { - msg_info ("lua_task_resolve_dns_a: invalid parameters passed to function"); + msg_info ("invalid parameters passed to function"); return 0; } if (evdns_resolve_ipv4 (cd->to_resolve, DNS_QUERY_NO_SEARCH, lua_dns_callback, (void *)cd) == 0) { @@ -336,7 +336,7 @@ lua_task_resolve_dns_ptr (lua_State * L) cd->callback = memory_pool_strdup (task->task_pool, luaL_checkstring (L, 3)); ina = memory_pool_alloc (task->task_pool, sizeof (struct in_addr)); if (!cd->to_resolve || !cd->callback || !inet_aton (cd->to_resolve, ina)) { - msg_info ("lua_task_resolve_dns_a: invalid parameters passed to function"); + msg_info ("invalid parameters passed to function"); return 0; } if (evdns_resolve_reverse (ina, DNS_QUERY_NO_SEARCH, lua_dns_callback, (void *)cd) == 0) { diff --git a/src/main.c b/src/main.c index fa861b86f..ee0a1ae56 100644 --- a/src/main.c +++ b/src/main.c @@ -140,11 +140,11 @@ print_signals_info () while ((inf = g_queue_pop_head (signals_info))) { if (inf->si_signo == SIGCHLD) { - msg_info ("main: got SIGCHLD from child: %P; reason: '%s'", + msg_info ("got SIGCHLD from child: %P; reason: '%s'", inf->si_pid, chldsigcode (inf->si_code)); } else { - msg_info ("main: got signal: '%s'; received from pid: %P; uid: %l", + msg_info ("got signal: '%s'; received from pid: %P; uid: %l", g_strsignal (inf->si_signo), inf->si_pid, (long int)inf->si_uid); } g_free (inf); @@ -222,26 +222,26 @@ drop_priv (struct config_file *cfg) if (geteuid () == 0 && cfg->rspamd_user) { pwd = getpwnam (cfg->rspamd_user); if (pwd == NULL) { - msg_err ("drop_priv: user specified does not exists (%s), aborting", strerror (errno)); + msg_err ("user specified does not exists (%s), aborting", strerror (errno)); exit (-errno); } if (cfg->rspamd_group) { grp = getgrnam (cfg->rspamd_group); if (grp == NULL) { - msg_err ("drop_priv: group specified does not exists (%s), aborting", strerror (errno)); + msg_err ("group specified does not exists (%s), aborting", strerror (errno)); exit (-errno); } if (setgid (grp->gr_gid) == -1) { - msg_err ("drop_priv: cannot setgid to %d (%s), aborting", (int)grp->gr_gid, strerror (errno)); + msg_err ("cannot setgid to %d (%s), aborting", (int)grp->gr_gid, strerror (errno)); exit (-errno); } if (initgroups (cfg->rspamd_user, grp->gr_gid) == -1) { - msg_err ("drop_priv: initgroups failed (%s), aborting", strerror (errno)); + msg_err ("initgroups failed (%s), aborting", strerror (errno)); exit (-errno); } } if (setuid (pwd->pw_uid) == -1) { - msg_err ("drop_priv: cannot setuid to %d (%s), aborting", (int)pwd->pw_uid, strerror (errno)); + msg_err ("cannot setuid to %d (%s), aborting", (int)pwd->pw_uid, strerror (errno)); exit (-errno); } } @@ -250,52 +250,15 @@ drop_priv (struct config_file *cfg) static void config_logger (struct rspamd_main *rspamd, gboolean is_fatal) { - switch (rspamd->cfg->log_type) { - case RSPAMD_LOG_CONSOLE: - if (!rspamd->cfg->no_fork) { - if (is_fatal) { - fprintf (stderr, "Cannot log to console while daemonized, disable logging\n"); - } - rspamd->cfg->log_fd = -1; - rspamd->cfg->logf = NULL; - } - else { - rspamd->cfg->logf = stderr; - rspamd->cfg->log_fd = STDERR_FILENO; - } - rspamd_set_logger (file_log_function, rspamd->cfg); - g_log_set_default_handler (file_log_function, rspamd->cfg); - break; - case RSPAMD_LOG_FILE: - if (rspamd->cfg->log_file == NULL || open_log (rspamd->cfg) == -1) { - if (is_fatal) { - fprintf (stderr, "Fatal error, cannot open logfile, exiting\n"); - exit (EXIT_FAILURE); - } - else { - msg_err ("config_logger: cannot log to file, logfile unaccessable"); - } - } - else { - rspamd_set_logger (file_log_function, rspamd->cfg); - g_log_set_default_handler (file_log_function, rspamd->cfg); - } - break; - case RSPAMD_LOG_SYSLOG: - if (open_log (rspamd->cfg) == -1) { - if (is_fatal) { - fprintf (stderr, "Fatal error, cannot open syslog facility, exiting\n"); - exit (EXIT_FAILURE); - } - else { - msg_err ("config_logger: cannot log to syslog"); - } + rspamd_set_logger (rspamd->cfg->log_type, rspamd->cfg); + if (open_log () == -1) { + if (is_fatal) { + fprintf (stderr, "Fatal error, cannot open logfile, exiting\n"); + exit (EXIT_FAILURE); } else { - rspamd_set_logger (syslog_log_function, rspamd->cfg); - g_log_set_default_handler (syslog_log_function, rspamd->cfg); + msg_err ("cannot log to file, logfile unaccessable"); } - break; } } @@ -314,25 +277,26 @@ reread_config (struct rspamd_main *rspamd) cfg_file = memory_pool_strdup (tmp_cfg->cfg_pool, rspamd->cfg->cfg_name); f = fopen (rspamd->cfg->cfg_name, "r"); if (f == NULL) { - msg_warn ("reread_config: cannot open file: %s", rspamd->cfg->cfg_name); + msg_warn ("cannot open file: %s", rspamd->cfg->cfg_name); } else { yyin = f; yyrestart (yyin); if (yyparse () != 0 || yynerrs > 0) { - msg_warn ("reread_config: yyparse: cannot parse config file, %d errors", yynerrs); + msg_warn ("yyparse: cannot parse config file, %d errors", yynerrs); fclose (f); } else { - msg_debug ("reread_config: replacing config"); + msg_debug ("replacing config"); free_config (rspamd->cfg); - close_log (rspamd->cfg); + close_log (); g_free (rspamd->cfg); rspamd->cfg = tmp_cfg; rspamd->cfg->cfg_name = cfg_file; config_logger (rspamd, FALSE); - msg_info ("reread_config: config rereaded successfully"); + open_log (); + msg_info ("config rereaded successfully"); } } } @@ -348,7 +312,7 @@ set_worker_limits (struct worker_conf *cf) rlmt.rlim_max = (rlim_t) cf->rlimit_nofile; if (setrlimit(RLIMIT_NOFILE, &rlmt) == -1) { - msg_warn ("set_worker_limits: cannot set files rlimit: %d, %s", cf->rlimit_nofile, strerror (errno)); + msg_warn ("cannot set files rlimit: %d, %s", cf->rlimit_nofile, strerror (errno)); } } @@ -357,7 +321,7 @@ set_worker_limits (struct worker_conf *cf) rlmt.rlim_max = (rlim_t) cf->rlimit_maxcore; if (setrlimit(RLIMIT_CORE, &rlmt) == -1) { - msg_warn ("set_worker_limits: cannot set max core rlimit: %d, %s", cf->rlimit_maxcore, strerror (errno)); + msg_warn ("cannot set max core rlimit: %d, %s", cf->rlimit_maxcore, strerror (errno)); } } @@ -379,6 +343,8 @@ fork_worker (struct rspamd_main *rspamd, struct worker_conf *cf) cur->pending = FALSE; switch (cur->pid) { case 0: + /* Update pid for logging */ + update_log_pid (); /* Drop privilleges */ drop_priv (cfg); /* Set limits */ @@ -387,32 +353,32 @@ fork_worker (struct rspamd_main *rspamd, struct worker_conf *cf) case TYPE_CONTROLLER: setproctitle ("controller process"); pidfile_close (rspamd->pfh); - msg_info ("fork_worker: starting controller process %P", getpid ()); + msg_info ("starting controller process %P", getpid ()); start_controller (cur); break; case TYPE_LMTP: setproctitle ("lmtp process"); pidfile_close (rspamd->pfh); - msg_info ("fork_worker: starting lmtp process %P", getpid ()); + msg_info ("starting lmtp process %P", getpid ()); start_lmtp_worker (cur); break; case TYPE_FUZZY: setproctitle ("fuzzy storage"); pidfile_close (rspamd->pfh); - msg_info ("fork_worker: starting fuzzy storage process %P", getpid ()); + msg_info ("starting fuzzy storage process %P", getpid ()); start_fuzzy_storage (cur); break; case TYPE_WORKER: default: setproctitle ("worker process"); pidfile_close (rspamd->pfh); - msg_info ("fork_worker: starting worker process %P", getpid ()); + msg_info ("starting worker process %P", getpid ()); start_worker (cur); break; } break; case -1: - msg_err ("fork_worker: cannot fork main process. %s", strerror (errno)); + msg_err ("cannot fork main process. %s", strerror (errno)); pidfile_remove (rspamd->pfh); exit (-errno); break; @@ -472,19 +438,19 @@ create_listen_socket (struct in_addr *addr, int port, int family, char *path) /* Create listen socket */ if (family == AF_INET) { if ((listen_sock = make_tcp_socket (addr, port, TRUE, TRUE)) == -1) { - msg_err ("create_listen_socket: cannot create tcp listen socket. %s", strerror (errno)); + msg_err ("cannot create tcp listen socket. %s", strerror (errno)); } } else { un_addr = (struct sockaddr_un *)alloca (sizeof (struct sockaddr_un)); if (!un_addr || (listen_sock = make_unix_socket (path, un_addr, TRUE)) == -1) { - msg_err ("create_listen_socket: cannot create unix listen socket. %s", strerror (errno)); + msg_err ("cannot create unix listen socket. %s", strerror (errno)); } } if (listen_sock != -1) { if (listen (listen_sock, -1) == -1) { - msg_err ("start_lmtp: cannot listen on socket. %s", strerror (errno)); + msg_err ("cannot listen on socket. %s", strerror (errno)); } } @@ -561,7 +527,7 @@ kill_old_workers (gpointer key, gpointer value, gpointer unused) struct rspamd_worker *w = value; kill (w->pid, SIGUSR2); - msg_info ("rspamd_restart: send signal to worker %P", w->pid); + msg_info ("send signal to worker %P", w->pid); } static gboolean @@ -572,7 +538,7 @@ wait_for_workers (gpointer key, gpointer value, gpointer unused) waitpid (w->pid, &res, 0); - msg_debug ("main(cleaning): %s process %P terminated", get_process_type (w->type), w->pid); + msg_debug ("%s process %P terminated", get_process_type (w->type), w->pid); g_free (w); return TRUE; @@ -643,10 +609,8 @@ main (int argc, char **argv, char **env) #endif /* First set logger to console logger */ - cfg->log_fd = STDERR_FILENO; - cfg->logf = stderr; - rspamd_set_logger (file_log_function, rspamd->cfg); - g_log_set_default_handler (file_log_function, cfg); + rspamd_set_logger (RSPAMD_LOG_CONSOLE, rspamd->cfg); + g_log_set_default_handler (rspamd_glib_log_function, cfg); #ifndef HAVE_SETPROCTITLE init_title (argc, argv, environ); @@ -654,13 +618,13 @@ main (int argc, char **argv, char **env) f = fopen (rspamd->cfg->cfg_name, "r"); if (f == NULL) { - msg_err ("main: cannot open file: %s", rspamd->cfg->cfg_name); + msg_err ("cannot open file: %s", rspamd->cfg->cfg_name); return EBADF; } yyin = f; if (yyparse () != 0 || yynerrs > 0) { - msg_err ("main: cannot parse config file, %d errors", yynerrs); + msg_err ("cannot parse config file, %d errors", yynerrs); return EBADF; } @@ -738,16 +702,16 @@ main (int argc, char **argv, char **env) config_logger (rspamd, TRUE); - msg_info ("main: rspamd " RVERSION " is starting"); + msg_info ("rspamd " RVERSION " is starting"); rspamd->cfg->cfg_name = memory_pool_strdup (rspamd->cfg->cfg_pool, rspamd->cfg->cfg_name); /* Strictly set temp dir */ if (!rspamd->cfg->temp_dir) { - msg_warn ("main: tempdir is not set, trying to use $TMPDIR"); + msg_warn ("tempdir is not set, trying to use $TMPDIR"); rspamd->cfg->temp_dir = memory_pool_strdup (rspamd->cfg->cfg_pool, getenv ("TMPDIR")); if (!rspamd->cfg->temp_dir) { - msg_warn ("main: $TMPDIR is empty too, using /tmp as default"); + msg_warn ("$TMPDIR is empty too, using /tmp as default"); rspamd->cfg->temp_dir = memory_pool_strdup (rspamd->cfg->cfg_pool, "/tmp"); } } @@ -763,7 +727,7 @@ main (int argc, char **argv, char **env) init_signals (&signals, sig_handler); if (write_pid (rspamd) == -1) { - msg_err ("main: cannot write pid file %s", rspamd->cfg->pid_file); + msg_err ("cannot write pid file %s", rspamd->cfg->pid_file); exit (-errno); } @@ -797,7 +761,7 @@ main (int argc, char **argv, char **env) PERL_SYS_INIT3 (&argc, &argv, &env); perl_interpreter = perl_alloc (); if (perl_interpreter == NULL) { - msg_err ("main: cannot allocate perl interpreter, %s", strerror (errno)); + msg_err ("cannot allocate perl interpreter, %s", strerror (errno)); exit (-errno); } @@ -819,25 +783,27 @@ main (int argc, char **argv, char **env) l = g_list_next (l); } + flush_log_buf (); + rspamd->workers = g_hash_table_new (g_direct_hash, g_direct_equal); spawn_workers (rspamd, TRUE); /* Signal processing cycle */ for (;;) { - msg_debug ("main: calling sigsuspend"); + msg_debug ("calling sigsuspend"); sigemptyset (&signals.sa_mask); sigsuspend (&signals.sa_mask); #ifdef HAVE_SA_SIGINFO print_signals_info (); #endif if (do_terminate) { - msg_debug ("main: catch termination signal, waiting for childs"); + msg_debug ("catch termination signal, waiting for childs"); pass_signal_worker (rspamd->workers, SIGTERM); break; } if (child_dead) { child_dead = 0; - msg_debug ("main: catch SIGCHLD signal, finding terminated worker"); + msg_debug ("catch SIGCHLD signal, finding terminated worker"); /* Remove dead child form childs list */ wrk = waitpid (0, &res, 0); if ((cur = g_hash_table_lookup (rspamd->workers, GSIZE_TO_POINTER (wrk))) != NULL) { @@ -848,14 +814,14 @@ main (int argc, char **argv, char **env) if (WIFEXITED (res) && WEXITSTATUS (res) == 0) { /* Normal worker termination, do not fork one more */ - msg_info ("main: %s process %P terminated normally", get_process_type (cur->type), cur->pid); + msg_info ("%s process %P terminated normally", get_process_type (cur->type), cur->pid); } else { if (WIFSIGNALED (res)) { - msg_warn ("main: %s process %P terminated abnormally by signal: %d", get_process_type (cur->type), cur->pid, WTERMSIG (res)); + msg_warn ("%s process %P terminated abnormally by signal: %d", get_process_type (cur->type), cur->pid, WTERMSIG (res)); } else { - msg_warn ("main: %s process %P terminated abnormally", get_process_type (cur->type), cur->pid); + msg_warn ("%s process %P terminated abnormally", get_process_type (cur->type), cur->pid); } /* Fork another worker in replace of dead one */ delay_fork (cur->cf); @@ -864,14 +830,14 @@ main (int argc, char **argv, char **env) g_free (cur); } else { - msg_err ("main: got SIGCHLD, but pid %P is not found in workers hash table, something goes wrong", wrk); + msg_err ("got SIGCHLD, but pid %P is not found in workers hash table, something goes wrong", wrk); } } if (do_restart) { do_restart = 0; do_reopen_log = 1; - msg_info ("main: rspamd " RVERSION " is restarting"); + msg_info ("rspamd " RVERSION " is restarting"); g_hash_table_foreach (rspamd->workers, kill_old_workers, NULL); spawn_workers (rspamd, FALSE); @@ -885,7 +851,9 @@ main (int argc, char **argv, char **env) /* Wait for workers termination */ g_hash_table_foreach_remove (rspamd->workers, wait_for_workers, NULL); - msg_info ("main: terminating..."); + msg_info ("terminating..."); + + close_log (); free_config (rspamd->cfg); g_free (rspamd->cfg); diff --git a/src/main.h b/src/main.h index 8aea5a661..ed7d2c80c 100644 --- a/src/main.h +++ b/src/main.h @@ -18,6 +18,7 @@ #include "hash.h" #include "events.h" #include "util.h" +#include "logger.h" /* Default values */ #define FIXED_CONFIG_FILE ETC_PREFIX "/rspamd.conf" @@ -28,12 +29,6 @@ /* 60 seconds for worker's IO */ #define WORKER_IO_TIMEOUT 60 -/* Logging in postfix style */ -#define msg_err(args...) rspamd_log_function(G_LOG_LEVEL_CRITICAL, ##args) -#define msg_warn(args...) rspamd_log_function(G_LOG_LEVEL_WARNING, ##args) -#define msg_info(args...) rspamd_log_function(G_LOG_LEVEL_INFO, ##args) -#define msg_debug(args...) rspamd_log_function(G_LOG_LEVEL_DEBUG, ##args) - #ifdef CRLF #undef CRLF #undef CR diff --git a/src/map.c b/src/map.c index 31a0569d9..8ff0eab3c 100644 --- a/src/map.c +++ b/src/map.c @@ -69,7 +69,7 @@ connect_http (struct rspamd_map *map, struct http_map_data *data, gboolean is_as int sock; if ((sock = make_tcp_socket (&data->addr, data->port, FALSE, is_async)) == -1) { - msg_info ("connect_http: cannot connect to http server %s: %d, %s", data->host, errno, strerror (errno)); + msg_info ("cannot connect to http server %s: %d, %s", data->host, errno, strerror (errno)); return -1; } @@ -90,7 +90,7 @@ write_http_request (struct rspamd_map *map, struct http_map_data *data, int sock r += snprintf (outbuf + r, sizeof (outbuf) - r, CRLF); if (write (sock, outbuf, r) == -1) { - msg_err ("write_http_request: failed to write request: %d, %s", errno, strerror (errno)); + msg_err ("failed to write request: %d, %s", errno, strerror (errno)); } } @@ -113,7 +113,7 @@ parse_http_reply (u_char * chunk, size_t len, struct http_reply *reply) /* Try to parse HTTP reply code */ reply->code = strtoul (++p, (char **)&err_str, 10); if (*err_str != ' ') { - msg_info ("parse_http_reply: error while reading HTTP status code: %s", p); + msg_info ("error while reading HTTP status code: %s", p); return NULL; } /* Now skip to end of status string */ @@ -239,7 +239,7 @@ read_http_chunked (u_char * buf, size_t len, struct rspamd_map *map, struct http return TRUE; } else { - msg_info ("read_http_chunked: invalid chunked reply: %*s", len, buf); + msg_info ("invalid chunked reply: %*s", len, buf); return FALSE; } } @@ -292,7 +292,7 @@ read_http_common (struct rspamd_map *map, struct http_map_data *data, struct htt } if (reply->parser_state == 6) { if (reply->code != 200 && reply->code != 304) { - msg_err ("read_http: got error reply from server %s, %d", data->host, reply->code); + msg_err ("got error reply from server %s, %d", data->host, reply->code); return FALSE; } else if (reply->code == 304) { @@ -331,7 +331,7 @@ read_http_sync (struct rspamd_map *map, struct http_map_data *data) struct http_reply *repl; if (map->read_callback == NULL || map->fin_callback == NULL) { - msg_err ("read_map_file: bad callback for reading map file"); + msg_err ("bad callback for reading map file"); return; } @@ -371,12 +371,12 @@ read_map_file (struct rspamd_map *map, struct file_map_data *data) int fd, rlen; if (map->read_callback == NULL || map->fin_callback == NULL) { - msg_err ("read_map_file: bad callback for reading map file"); + msg_err ("bad callback for reading map file"); return; } if ((fd = open (data->filename, O_RDONLY)) == -1) { - msg_warn ("read_map_file: cannot open file '%s': %s", data->filename, strerror (errno)); + msg_warn ("cannot open file '%s': %s", data->filename, strerror (errno)); return; } @@ -423,7 +423,7 @@ add_map (const char *map_line, map_cb_t read_callback, map_fin_cb_t fin_callback def = map_line + sizeof ("file://") - 1; } else { - msg_debug ("add_map: invalid map fetching protocol: %s", map_line); + msg_debug ("invalid map fetching protocol: %s", map_line); return FALSE; } /* Constant pool */ @@ -439,7 +439,7 @@ add_map (const char *map_line, map_cb_t read_callback, map_fin_cb_t fin_callback /* Now check for each proto separately */ if (proto == PROTO_FILE) { if ((fd = open (def, O_RDONLY)) == -1) { - msg_warn ("add_map: cannot open file '%s': %s", def, strerror (errno)); + msg_warn ("cannot open file '%s': %s", def, strerror (errno)); return FALSE; } fdata = memory_pool_alloc0 (map_pool, sizeof (struct file_map_data)); @@ -458,7 +458,7 @@ add_map (const char *map_line, map_cb_t read_callback, map_fin_cb_t fin_callback portbuf[i++] = *p++; } if (*p != '/') { - msg_info ("add_map: bad http map definition: %s", def); + msg_info ("bad http map definition: %s", def); return FALSE; } portbuf[i] = '\0'; @@ -469,7 +469,7 @@ add_map (const char *map_line, map_cb_t read_callback, map_fin_cb_t fin_callback hdata->port = 80; /* Now separate host from path */ if ((p = strchr (def, '/')) == NULL) { - msg_info ("add_map: bad http map definition: %s", def); + msg_info ("bad http map definition: %s", def); return FALSE; } hostend = p; @@ -483,7 +483,7 @@ add_map (const char *map_line, map_cb_t read_callback, map_fin_cb_t fin_callback /* Resolve using dns */ hent = gethostbyname (hdata->host); if (hent == NULL) { - msg_info ("add_map: cannot resolve: %s", hdata->host); + msg_info ("cannot resolve: %s", hdata->host); return FALSE; } else { @@ -492,7 +492,7 @@ add_map (const char *map_line, map_cb_t read_callback, map_fin_cb_t fin_callback } /* Now try to connect */ if ((s = make_tcp_socket (&hdata->addr, hdata->port, FALSE, FALSE)) == -1) { - msg_info ("add_map: cannot connect to http server %s: %d, %s", hdata->host, errno, strerror (errno)); + msg_info ("cannot connect to http server %s: %d, %s", hdata->host, errno, strerror (errno)); return FALSE; } close (s); @@ -602,29 +602,28 @@ radix_tree_insert_helper (gpointer st, gconstpointer key, gpointer value) errno = 0; k = strtoul (ipnet, &err_str, 10); if (errno != 0) { - msg_warn ("radix_tree_insert_helper: invalid netmask, error detected on symbol: %s, erorr: %s", err_str, strerror (errno)); + msg_warn ("invalid netmask, error detected on symbol: %s, erorr: %s", err_str, strerror (errno)); k = 32; } else if (k > 32 || k < 0) { - msg_warn ("radix_tree_insert_helper: invalid netmask value: %d", k); + msg_warn ("invalid netmask value: %d", k); k = 32; } - k = 32 - k; - mask = mask << k; + mask = mask << (32 - k); } if (inet_aton (token, &ina) == 0) { - msg_err ("radix_tree_insert_helper: invalid ip address: %s", token); + msg_err ("invalid ip address: %s", token); return; } ip = ntohl ((uint32_t) ina.s_addr); k = radix32tree_insert (tree, ip, mask, 1); if (k == -1) { - msg_warn ("radix_tree_insert_helper: cannot insert ip to tree: %s, mask %X", inet_ntoa (ina), mask); + msg_warn ("cannot insert ip to tree: %s, mask %X", inet_ntoa (ina), mask); } else if (k == 1) { - msg_warn ("add_ip_radix: ip %s, mask %X, value already exists", inet_ntoa (ina), mask); + msg_warn ("ip %s, mask %X, value already exists", inet_ntoa (ina), mask); } cur++; } @@ -729,7 +728,7 @@ http_async_callback (int fd, short what, void *ud) event_add (&cbd->ev, &cbd->tv); } else { - msg_err ("http_async_callback: bad state when got write readiness"); + msg_err ("bad state when got write readiness"); free_http_cbdata (cbd); return; } @@ -740,7 +739,7 @@ http_async_callback (int fd, short what, void *ud) /* Handle Not-Modified in a special way */ if (cbd->reply->code == 304) { cbd->data->last_checked = time (NULL); - msg_info ("http_async_callback: data is not modified for server %s", cbd->data->host); + msg_info ("data is not modified for server %s", cbd->data->host); } else if (cbd->cbdata.cur_data != NULL) { cbd->map->fin_callback (cbd->map->pool, &cbd->cbdata); @@ -749,7 +748,7 @@ http_async_callback (int fd, short what, void *ud) } if (cbd->state == 1 && cbd->reply->code == 200) { /* Write to log that data is modified */ - msg_info ("http_async_callback: rereading map data from %s", cbd->data->host); + msg_info ("rereading map data from %s", cbd->data->host); } free_http_cbdata (cbd); @@ -757,13 +756,13 @@ http_async_callback (int fd, short what, void *ud) } else if (cbd->state == 1) { /* Write to log that data is modified */ - msg_info ("http_async_callback: rereading map data from %s", cbd->data->host); + msg_info ("rereading map data from %s", cbd->data->host); } cbd->state = 2; } } else { - msg_err ("http_async_callback: connection with http server terminated incorrectly"); + msg_err ("connection with http server terminated incorrectly"); free_http_cbdata (cbd); } } diff --git a/src/message.c b/src/message.c index 597eb3a82..225125bcc 100644 --- a/src/message.c +++ b/src/message.c @@ -490,7 +490,7 @@ convert_text_to_utf (struct worker_task *task, GByteArray * part_content, GMimeC res_str = g_convert_with_fallback (part_content->data, part_content->len, "UTF-8", charset, NULL, &read_bytes, &write_bytes, &err); if (res_str == NULL) { - msg_warn ("convert_text_to_utf: cannot convert from %s to utf8: %s", charset, err ? err->message : "unknown problem"); + msg_warn ("cannot convert from %s to utf8: %s", charset, err ? err->message : "unknown problem"); text_part->is_raw = TRUE; return part_content; } @@ -510,7 +510,7 @@ process_text_part (struct worker_task *task, GByteArray * part_content, GMimeCon struct mime_text_part *text_part; if (g_mime_content_type_is_type (type, "text", "html") || g_mime_content_type_is_type (type, "text", "xhtml")) { - msg_debug ("mime_foreach_callback: got urls from text/html part"); + debug_task ("got urls from text/html part"); text_part = memory_pool_alloc0 (task->task_pool, sizeof (struct mime_text_part)); text_part->is_html = TRUE; @@ -548,7 +548,7 @@ process_text_part (struct worker_task *task, GByteArray * part_content, GMimeCon task->text_parts = g_list_prepend (task->text_parts, text_part); } else if (g_mime_content_type_is_type (type, "text", "plain")) { - msg_debug ("mime_foreach_callback: got urls from text/plain part"); + debug_task ("got urls from text/plain part"); text_part = memory_pool_alloc0 (task->task_pool, sizeof (struct mime_text_part)); text_part->is_html = FALSE; @@ -608,7 +608,7 @@ mime_foreach_callback (GMimeObject * part, gpointer user_data) #endif } else { - msg_err ("mime_foreach_callback: endless recursion detected: %d", task->parser_recursion); + msg_err ("endless recursion detected: %d", task->parser_recursion); return; } g_object_unref (message); @@ -631,7 +631,7 @@ mime_foreach_callback (GMimeObject * part, gpointer user_data) g_mime_multipart_foreach ((GMimeMultipart *) part, mime_foreach_callback, task); } else { - msg_err ("mime_foreach_callback: endless recursion detected: %d", task->parser_recursion); + msg_err ("endless recursion detected: %d", task->parser_recursion); return; } } @@ -643,7 +643,7 @@ mime_foreach_callback (GMimeObject * part, gpointer user_data) type = (GMimeContentType *) g_mime_part_get_content_type (GMIME_PART (part)); #endif if (type == NULL) { - msg_warn ("mime_foreach_callback: type of part is unknown, assume text/plain"); + msg_warn ("type of part is unknown, assume text/plain"); type = g_mime_content_type_new ("text", "plain"); memory_pool_add_destructor (task->task_pool, (pool_destruct_func) g_mime_content_type_destroy, type); } @@ -657,18 +657,18 @@ mime_foreach_callback (GMimeObject * part, gpointer user_data) mime_part = memory_pool_alloc (task->task_pool, sizeof (struct mime_part)); mime_part->type = type; mime_part->content = part_content; - msg_debug ("mime_foreach_callback: found part with content-type: %s/%s", type->type, type->subtype); + debug_task ("found part with content-type: %s/%s", type->type, type->subtype); task->parts = g_list_prepend (task->parts, mime_part); /* Skip empty parts */ process_text_part (task, part_content, type, (part_content->len <= 0)); } else { - msg_warn ("mime_foreach_callback: write to stream failed: %d, %s", errno, strerror (errno)); + msg_warn ("write to stream failed: %d, %s", errno, strerror (errno)); } g_object_unref (wrapper); } else { - msg_warn ("mime_foreach_callback: cannot get wrapper for mime part, type of part: %s/%s", type->type, type->subtype); + msg_warn ("cannot get wrapper for mime part, type of part: %s/%s", type->type, type->subtype); } } else { @@ -681,7 +681,7 @@ destroy_message (void *pointer) { GMimeMessage *msg = pointer; - msg_debug ("destroy_message: freeing pointer %p", msg); + msg_debug ("freeing pointer %p", msg); g_object_unref (msg); } @@ -711,7 +711,7 @@ process_message (struct worker_task *task) if (task->is_mime) { - msg_debug ("process_message: construct mime parser from string length %ld", (long int)task->msg->len); + debug_task ("construct mime parser from string length %ld", (long int)task->msg->len); /* create a new parser object to parse the stream */ parser = g_mime_parser_new_with_stream (stream); g_object_unref (stream); @@ -720,7 +720,7 @@ process_message (struct worker_task *task) message = g_mime_parser_construct_message (parser); if (message == NULL) { - msg_warn ("process_message: cannot construct mime from stream"); + msg_warn ("cannot construct mime from stream"); return -1; } @@ -734,7 +734,7 @@ process_message (struct worker_task *task) g_mime_message_foreach_part (message, mime_foreach_callback, task); #endif - msg_debug ("process_message: found %d parts in message", task->parts_count); + debug_task ("found %d parts in message", task->parts_count); if (task->queue_id == NULL) { task->queue_id = (char *)g_mime_message_get_message_id (task->message); } @@ -948,7 +948,7 @@ multipart_iterate (GMimeObject * part, gpointer user_data) g_mime_multipart_foreach (GMIME_MULTIPART (part), multipart_iterate, data); } else { - msg_info ("multipart_iterate: maximum recurse limit is over, stop recursing, %d", data->rec); + msg_info ("maximum recurse limit is over, stop recursing, %d", data->rec); data->try_search = FALSE; } } diff --git a/src/perl.c b/src/perl.c index 2849289b6..74dca3d84 100644 --- a/src/perl.c +++ b/src/perl.c @@ -116,7 +116,7 @@ perl_call_header_filter (const char *function, struct worker_task *task) SPAGAIN; result = POPi; - msg_debug ("header_filter: call of %s with returned mark %d\n", function, result); + debug_task ("call of %s with returned mark %d\n", function, result); PUTBACK; FREETMPS; @@ -155,7 +155,7 @@ perl_call_chain_filter (const char *function, struct worker_task *task, int *mar SPAGAIN; result = POPi; - msg_debug ("chain_filter: call of %s returned mark %d\n", function, result); + debug_task ("call of %s returned mark %d\n", function, result); PUTBACK; FREETMPS; diff --git a/src/plugins/chartable.c b/src/plugins/chartable.c index d311da740..ceedc1325 100644 --- a/src/plugins/chartable.c +++ b/src/plugins/chartable.c @@ -91,7 +91,7 @@ chartable_module_config (struct config_file *cfg) errno = 0; chartable_module_ctx->threshold = strtod (value, NULL); if (errno != 0) { - msg_warn ("chartable_module_config: invalid numeric value '%s': %s", value, strerror (errno)); + msg_warn ("invalid numeric value '%s': %s", value, strerror (errno)); chartable_module_ctx->threshold = DEFAULT_THRESHOLD; } } @@ -101,7 +101,7 @@ chartable_module_config (struct config_file *cfg) metric = g_hash_table_lookup (cfg->metrics, chartable_module_ctx->metric); if (metric == NULL) { - msg_err ("chartable_module_config: cannot find metric definition %s", chartable_module_ctx->metric); + msg_err ("cannot find metric definition %s", chartable_module_ctx->metric); return FALSE; } diff --git a/src/plugins/emails.c b/src/plugins/emails.c index a58e8d7c6..88ea34b8b 100644 --- a/src/plugins/emails.c +++ b/src/plugins/emails.c @@ -109,7 +109,7 @@ emails_module_config (struct config_file *cfg) metric = g_hash_table_lookup (cfg->metrics, email_module_ctx->metric); if (metric == NULL) { - msg_err ("emails_module_config: cannot find metric definition %s", email_module_ctx->metric); + msg_err ("cannot find metric definition %s", email_module_ctx->metric); return FALSE; } @@ -166,10 +166,10 @@ extract_emails (struct worker_task *task) } } else if (err != NULL) { - msg_debug ("extract_emails: error matching regexp: %s", err->message); + debug_task ("error matching regexp: %s", err->message); } else { - msg_debug ("extract_emails: cannot find url pattern in given string"); + debug_task ("cannot find url pattern in given string"); } g_match_info_free (info); @@ -212,7 +212,7 @@ emails_command_handler (struct worker_task *task) outbuf[r++] = '\n'; rspamd_dispatcher_write (task->dispatcher, outbuf, r, FALSE, FALSE); - msg_info ("process_message: msg ok, id: <%s>, %d emails extracted", task->message_id, num); + msg_info ("msg ok, id: <%s>, %d emails extracted", task->message_id, num); return 0; } diff --git a/src/plugins/fuzzy_check.c b/src/plugins/fuzzy_check.c index ef139b3a1..2ac7475bf 100644 --- a/src/plugins/fuzzy_check.c +++ b/src/plugins/fuzzy_check.c @@ -124,7 +124,7 @@ parse_servers_string (char *str) /* Resolve using dns */ hent = gethostbyname (name); if (hent == NULL) { - msg_info ("parse_servers_string: cannot resolve: %s", name); + msg_info ("cannot resolve: %s", name); continue; } else { @@ -190,7 +190,7 @@ fuzzy_check_module_config (struct config_file *cfg) metric = g_hash_table_lookup (cfg->metrics, fuzzy_module_ctx->metric); if (metric == NULL) { - msg_err ("fuzzy_module_config: cannot find metric definition %s", fuzzy_module_ctx->metric); + msg_err ("cannot find metric definition %s", fuzzy_module_ctx->metric); return FALSE; } @@ -265,7 +265,7 @@ fuzzy_io_callback (int fd, short what, void *arg) return; err: - msg_err ("fuzzy_io_callback: got error on IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno)); + msg_err ("got error on IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno)); ok: close (fd); remove_normal_event (session->task->s, fuzzy_io_fin, session); @@ -314,7 +314,7 @@ fuzzy_learn_callback (int fd, short what, void *arg) return; err: - msg_err ("fuzzy_learn_callback: got error in IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno)); + msg_err ("got error in IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno)); ok: close (fd); remove_normal_event (session->session->s, fuzzy_learn_fin, session); @@ -342,7 +342,7 @@ fuzzy_symbol_callback (struct worker_task *task, void *unused) DEFAULT_UPSTREAM_ERROR_TIME, DEFAULT_UPSTREAM_DEAD_TIME, DEFAULT_UPSTREAM_MAXERRORS, part->fuzzy->hash_pipe, sizeof (part->fuzzy->hash_pipe)); if (selected) { if ((sock = make_udp_socket (&selected->addr, selected->port, FALSE, TRUE)) == -1) { - msg_warn ("fuzzy_symbol_callback: cannot connect to %s, %d, %s", selected->name, errno, strerror (errno)); + msg_warn ("cannot connect to %s, %d, %s", selected->name, errno, strerror (errno)); } else { session = memory_pool_alloc (task->task_pool, sizeof (struct fuzzy_client_session)); @@ -387,7 +387,7 @@ fuzzy_process_handler (struct controller_session *session, f_str_t * in) saved = memory_pool_alloc0 (session->session_pool, sizeof (int)); r = process_message (task); if (r == -1) { - msg_warn ("read_socket: processing of message failed"); + msg_warn ("processing of message failed"); free_task (task, FALSE); session->state = STATE_REPLY; r = snprintf (out_buf, sizeof (out_buf), "cannot process message" CRLF); @@ -409,7 +409,7 @@ fuzzy_process_handler (struct controller_session *session, f_str_t * in) DEFAULT_UPSTREAM_ERROR_TIME, DEFAULT_UPSTREAM_DEAD_TIME, DEFAULT_UPSTREAM_MAXERRORS, part->fuzzy->hash_pipe, sizeof (part->fuzzy->hash_pipe)); if (selected) { if ((sock = make_udp_socket (&selected->addr, selected->port, FALSE, TRUE)) == -1) { - msg_warn ("fuzzy_symbol_callback: cannot connect to %s, %d, %s", selected->name, errno, strerror (errno)); + msg_warn ("cannot connect to %s, %d, %s", selected->name, errno, strerror (errno)); session->state = STATE_REPLY; r = snprintf (out_buf, sizeof (out_buf), "no hashes written" CRLF); rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE); @@ -461,7 +461,7 @@ fuzzy_controller_handler (char **args, struct controller_session *session, int c arg = *args; if (!arg || *arg == '\0') { - msg_info ("fuzzy_controller_handler: empty content length"); + msg_info ("empty content length"); r = snprintf (out_buf, sizeof (out_buf), "fuzzy command requires length as argument" CRLF); rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE); session->state = STATE_REPLY; diff --git a/src/plugins/regexp.c b/src/plugins/regexp.c index 00169bb6d..70945b19c 100644 --- a/src/plugins/regexp.c +++ b/src/plugins/regexp.c @@ -94,7 +94,7 @@ read_regexp_expression (memory_pool_t * pool, struct regexp_module_item *chain, e = parse_expression (regexp_module_ctx->regexp_pool, line); if (e == NULL) { - msg_warn ("read_regexp_expression: %s = \"%s\" is invalid regexp expression", symbol, line); + msg_warn ("%s = \"%s\" is invalid regexp expression", symbol, line); return FALSE; } chain->expr = e; @@ -103,7 +103,7 @@ read_regexp_expression (memory_pool_t * pool, struct regexp_module_item *chain, if (cur->type == EXPR_REGEXP) { cur->content.operand = parse_regexp (pool, cur->content.operand, cfg->raw_mode); if (cur->content.operand == NULL) { - msg_warn ("read_regexp_expression: cannot parse regexp, skip expression %s = \"%s\"", symbol, line); + msg_warn ("cannot parse regexp, skip expression %s = \"%s\"", symbol, line); return FALSE; } cur->type = EXPR_REGEXP_PARSED; @@ -137,11 +137,11 @@ parse_autolearn_param (const char *param, const char *value, struct config_file } } else { - msg_warn ("parse_autolearn_param: cannot extract statfile name from %s", p); + msg_warn ("cannot extract statfile name from %s", p); } } else { - msg_warn ("parse_autolearn_param: cannot extract symbol name from %s", p); + msg_warn ("cannot extract symbol name from %s", p); } } @@ -173,7 +173,7 @@ regexp_module_config (struct config_file *cfg) metric = g_hash_table_lookup (cfg->metrics, regexp_module_ctx->metric); if (metric == NULL) { - msg_err ("regexp_module_config: cannot find metric definition %s", regexp_module_ctx->metric); + msg_err ("cannot find metric definition %s", regexp_module_ctx->metric); return FALSE; } @@ -288,12 +288,12 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * if (re == NULL) { - msg_info ("process_regexp: invalid regexp passed"); + msg_info ("invalid regexp passed"); return 0; } if ((r = task_cache_check (task, re)) != -1) { - msg_debug ("process_regexp: regexp /%s/ is found in cache, result: %d", re->regexp_text, r); + debug_task ("regexp /%s/ is found in cache, result: %d", re->regexp_text, r); return r == 1; } @@ -311,15 +311,15 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * switch (re->type) { case REGEXP_NONE: - msg_warn ("process_regexp: bad error detected: /%s/ has invalid regexp type", re->regexp_text); + msg_warn ("bad error detected: /%s/ has invalid regexp type", re->regexp_text); return 0; case REGEXP_HEADER: if (re->header == NULL) { - msg_info ("process_regexp: header regexp without header name: '%s'", re->regexp_text); + msg_info ("header regexp without header name: '%s'", re->regexp_text); task_cache_add (task, re, 0); return 0; } - msg_debug ("process_regexp: checking header regexp: %s = /%s/", re->header, re->regexp_text); + debug_task ("checking header regexp: %s = /%s/", re->header, re->regexp_text); headerlist = message_get_header (task->task_pool, task->message, re->header); if (headerlist == NULL) { task_cache_add (task, re, 0); @@ -328,13 +328,13 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * else { memory_pool_add_destructor (task->task_pool, (pool_destruct_func) g_list_free, headerlist); if (re->regexp == NULL) { - msg_debug ("process_regexp: regexp contains only header and it is found %s", re->header); + debug_task ("regexp contains only header and it is found %s", re->header); task_cache_add (task, re, 1); return 1; } cur = headerlist; while (cur) { - msg_debug ("process_regexp: found header \"%s\" with value \"%s\"", re->header, (char *)cur->data); + debug_task ("found header \"%s\" with value \"%s\"", re->header, (char *)cur->data); if (cur->data && g_regex_match (re->regexp, cur->data, 0, NULL) == TRUE) { task_cache_add (task, re, 1); return 1; @@ -346,7 +346,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * } break; case REGEXP_MIME: - msg_debug ("process_regexp: checking mime regexp: /%s/", re->regexp_text); + debug_task ("checking mime regexp: /%s/", re->regexp_text); cur = g_list_first (task->text_parts); while (cur) { part = (struct mime_text_part *)cur->data; @@ -370,7 +370,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * task_cache_add (task, re, 0); return 0; case REGEXP_MESSAGE: - msg_debug ("process_regexp: checking message regexp: /%s/", re->regexp_text); + debug_task ("checking message regexp: /%s/", re->regexp_text); if (g_regex_match_full (re->raw_regexp, task->msg->begin, task->msg->len, 0, 0, NULL, NULL) == TRUE) { task_cache_add (task, re, 1); return 1; @@ -378,7 +378,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * task_cache_add (task, re, 0); return 0; case REGEXP_URL: - msg_debug ("process_regexp: checking url regexp: /%s/", re->regexp_text); + debug_task ("checking url regexp: /%s/", re->regexp_text); cur = g_list_first (task->text_parts); while (cur) { part = (struct mime_text_part *)cur->data; @@ -410,9 +410,9 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * } return 0; case REGEXP_RAW_HEADER: - msg_debug ("process_regexp: checking for raw header: %s with regexp: /%s/", re->header, re->regexp_text); + debug_task ("checking for raw header: %s with regexp: /%s/", re->header, re->regexp_text); if (task->raw_headers == NULL) { - msg_debug ("process_regexp: cannot check for raw header in message, no headers found"); + debug_task ("cannot check for raw header in message, no headers found"); task_cache_add (task, re, 0); return 0; } @@ -444,7 +444,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * /* Temporary null terminate this part of string */ t = *c; *c = '\0'; - msg_debug ("process_regexp: found raw header \"%s\" with value \"%s\"", re->header, headerv); + debug_task ("found raw header \"%s\" with value \"%s\"", re->header, headerv); if (g_regex_match (re->raw_regexp, headerv, 0, NULL) == TRUE) { *c = t; task_cache_add (task, re, 1); @@ -454,7 +454,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char * task_cache_add (task, re, 0); return 0; default: - msg_warn ("process_regexp: bad error detected: %p is not a valid regexp object", re); + msg_warn ("bad error detected: %p is not a valid regexp object", re); } /* Not reached */ @@ -480,7 +480,7 @@ optimize_regexp_expression (struct expression **e, GQueue * stack, gboolean res) /* If this operation is just ! just inverse res and check for further operators */ if (it->content.operation == '!') { if (is_nearest) { - msg_debug ("optimize_regexp_expression: found '!' operator, inversing result"); + msg_debug ("found '!' operator, inversing result"); res = !res; *e = it; } @@ -493,12 +493,12 @@ optimize_regexp_expression (struct expression **e, GQueue * stack, gboolean res) /* Check whether we found corresponding operator for this operand */ if (skip_level <= 0) { if (it->content.operation == '|' && res == TRUE) { - msg_debug ("optimize_regexp_expression: found '|' and previous expression is true"); + msg_debug ("found '|' and previous expression is true"); *e = it; ret = TRUE; } else if (it->content.operation == '&' && res == FALSE) { - msg_debug ("optimize_regexp_expression: found '&' and previous expression is false"); + msg_debug ("found '&' and previous expression is false"); *e = it; ret = TRUE; } @@ -532,7 +532,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_ if (it->type == EXPR_REGEXP_PARSED) { /* Find corresponding symbol */ cur = process_regexp ((struct rspamd_regexp *)it->content.operand, task, additional); - msg_debug ("process_regexp_expression: regexp %s found", cur ? "is" : "is not"); + debug_task ("regexp %s found", cur ? "is" : "is not"); if (try_optimize) { try_optimize = optimize_regexp_expression (&it, stack, cur); } @@ -542,7 +542,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_ } else if (it->type == EXPR_FUNCTION) { cur = (gsize) call_expression_function ((struct expression_function *)it->content.operand, task); - msg_debug ("process_regexp_expression: function %s returned %s", ((struct expression_function *)it->content.operand)->name, cur ? "true" : "false"); + debug_task ("function %s returned %s", ((struct expression_function *)it->content.operand)->name, cur ? "true" : "false"); if (try_optimize) { try_optimize = optimize_regexp_expression (&it, stack, cur); } @@ -558,7 +558,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_ } re = parse_regexp (task->cfg->cfg_pool, it->content.operand, task->cfg->raw_mode); if (re == NULL) { - msg_warn ("process_regexp_expression: cannot parse regexp, skip expression"); + msg_warn ("cannot parse regexp, skip expression"); g_queue_free (stack); return FALSE; } @@ -570,11 +570,11 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_ else if (it->type == EXPR_OPERATION) { if (g_queue_is_empty (stack)) { /* Queue has no operands for operation, exiting */ - msg_warn ("process_regexp_expression: regexp expression seems to be invalid: empty stack while reading operation"); + msg_warn ("regexp expression seems to be invalid: empty stack while reading operation"); g_queue_free (stack); return FALSE; } - msg_debug ("process_regexp_expression: got operation %c", it->content.operation); + debug_task ("got operation %c", it->content.operation); switch (it->content.operation) { case '!': op1 = GPOINTER_TO_SIZE (g_queue_pop_head (stack)); @@ -608,7 +608,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_ } } else { - msg_warn ("process_regexp_expression: regexp expression seems to be invalid: empty stack at the end of expression, symbol %s", symbol); + msg_warn ("regexp expression seems to be invalid: empty stack at the end of expression, symbol %s", symbol); } g_queue_free (stack); @@ -641,7 +641,7 @@ rspamd_regexp_match_number (struct worker_task *task, GList * args, void *unused GList *cur; if (args == NULL) { - msg_warn ("rspamd_regexp_match_number: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } @@ -681,7 +681,7 @@ rspamd_raw_header_exists (struct worker_task *task, GList * args, void *unused) arg = get_function_arg (args->data, task, TRUE); if (!arg || arg->type == EXPRESSION_ARGUMENT_BOOL) { - msg_warn ("rspamd_raw_header_exists: invalid argument to function is passed"); + msg_warn ("invalid argument to function is passed"); return FALSE; } if (find_raw_header_pos (task->raw_headers, (char *)arg->data) == NULL) { @@ -699,14 +699,14 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused) char *type, *what = NULL; if (args == NULL) { - msg_warn ("rspamd_check_smtp_data: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } arg = get_function_arg (args->data, task, TRUE); if (!arg || !arg->data) { - msg_warn ("rspamd_check_smtp_data: no parameters to function"); + msg_warn ("no parameters to function"); return FALSE; } else { @@ -718,7 +718,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused) what = task->from; } else { - msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type); + msg_warn ("bad argument to function: %s", type); return FALSE; } break; @@ -728,7 +728,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused) what = task->helo; } else { - msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type); + msg_warn ("bad argument to function: %s", type); return FALSE; } break; @@ -738,7 +738,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused) what = task->user; } else { - msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type); + msg_warn ("bad argument to function: %s", type); return FALSE; } break; @@ -748,7 +748,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused) what = task->subject; } else { - msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type); + msg_warn ("bad argument to function: %s", type); return FALSE; } break; @@ -758,12 +758,12 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused) rcpt_list = task->rcpt; } else { - msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type); + msg_warn ("bad argument to function: %s", type); return FALSE; } break; default: - msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type); + msg_warn ("bad argument to function: %s", type); return FALSE; } } diff --git a/src/plugins/spf.c b/src/plugins/spf.c index 581f08b84..ae762f12a 100644 --- a/src/plugins/spf.c +++ b/src/plugins/spf.c @@ -107,7 +107,7 @@ spf_module_config (struct config_file *cfg) metric = g_hash_table_lookup (cfg->metrics, spf_module_ctx->metric); if (metric == NULL) { - msg_err ("spf_module_config: cannot find metric definition %s", spf_module_ctx->metric); + msg_err ("cannot find metric definition %s", spf_module_ctx->metric); return FALSE; } @@ -184,7 +184,7 @@ spf_symbol_callback (struct worker_task *task, void *unused) { if (task->from_addr.s_addr != INADDR_NONE && task->from_addr.s_addr != INADDR_ANY) { if (!resolve_spf (task, spf_plugin_callback)) { - msg_info ("spf_symbol_callback: cannot make spf request for [%s]", task->message_id); + msg_info ("cannot make spf request for [%s]", task->message_id); } } } diff --git a/src/plugins/surbl.c b/src/plugins/surbl.c index dd4e84234..d93e48dd3 100644 --- a/src/plugins/surbl.c +++ b/src/plugins/surbl.c @@ -180,7 +180,7 @@ surbl_module_config (struct config_file *cfg) metric = g_hash_table_lookup (cfg->metrics, surbl_module_ctx->metric); if (metric == NULL) { - msg_err ("surbl_module_config: cannot find metric definition %s", surbl_module_ctx->metric); + msg_err ("cannot find metric definition %s", surbl_module_ctx->metric); return FALSE; } @@ -194,7 +194,7 @@ surbl_module_config (struct config_file *cfg) *str = '\0'; new_suffix->symbol = memory_pool_strdup (surbl_module_ctx->surbl_pool, str + 1); new_suffix->suffix = memory_pool_strdup (surbl_module_ctx->surbl_pool, cur->value); - msg_debug ("surbl_module_config: add new surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol); + msg_debug ("add new surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol); *str = '_'; surbl_module_ctx->suffixes = g_list_prepend (surbl_module_ctx->suffixes, new_suffix); /* Search in factors hash table */ @@ -214,7 +214,7 @@ surbl_module_config (struct config_file *cfg) new_bit = memory_pool_alloc (surbl_module_ctx->surbl_pool, sizeof (struct surbl_bit_item)); new_bit->bit = bit; new_bit->symbol = memory_pool_strdup (surbl_module_ctx->surbl_pool, cur->value); - msg_debug ("surbl_module_config: add new bit suffix: %d with symbol: %s", (int)new_bit->bit, new_bit->symbol); + msg_debug ("add new bit suffix: %d with symbol: %s", (int)new_bit->bit, new_bit->symbol); surbl_module_ctx->bits = g_list_prepend (surbl_module_ctx->bits, new_bit); } } @@ -226,7 +226,7 @@ surbl_module_config (struct config_file *cfg) new_suffix = memory_pool_alloc (surbl_module_ctx->surbl_pool, sizeof (struct suffix_item)); new_suffix->suffix = memory_pool_strdup (surbl_module_ctx->surbl_pool, DEFAULT_SURBL_SUFFIX); new_suffix->symbol = memory_pool_strdup (surbl_module_ctx->surbl_pool, DEFAULT_SURBL_SYMBOL); - msg_debug ("surbl_module_config: add default surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol); + msg_debug ("add default surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol); surbl_module_ctx->suffixes = g_list_prepend (surbl_module_ctx->suffixes, new_suffix); w = g_hash_table_lookup (cfg->factors, new_suffix->symbol); if (w == NULL) { @@ -278,7 +278,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it octet3 = g_match_info_fetch (info, 3); octet4 = g_match_info_fetch (info, 4); result = memory_pool_alloc (pool, len); - msg_debug ("format_surbl_request: got numeric host for check: %s.%s.%s.%s", octet1, octet2, octet3, octet4); + msg_debug ("got numeric host for check: %s.%s.%s.%s", octet1, octet2, octet3, octet4); r = snprintf (result, len, "%s.%s.%s.%s", octet4, octet3, octet2, octet1); if (g_hash_table_lookup (surbl_module_ctx->whitelist, result) != NULL) { g_free (octet1); @@ -286,7 +286,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it g_free (octet3); g_free (octet4); g_match_info_free (info); - msg_debug ("format_surbl_request: url %s is whitelisted", result); + msg_debug ("url %s is whitelisted", result); g_set_error (err, SURBL_ERROR, /* error domain */ WHITELIST_ERROR, /* error code */ "URL is whitelisted: %s", /* error message format string */ @@ -314,7 +314,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it ip_num = strtoull (ip, NULL, 10); if (errno != 0) { g_match_info_free (info); - msg_info ("format_surbl_request: cannot convert ip to number '%s': %s", ip, strerror (errno)); + msg_info ("cannot convert ip to number '%s': %s", ip, strerror (errno)); g_set_error (err, SURBL_ERROR, /* error domain */ CONVERSION_ERROR, /* error code */ "URL cannot be decoded"); @@ -357,14 +357,14 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it hpart1 = g_match_info_fetch (info, 1); hpart2 = g_match_info_fetch (info, 2); hpart3 = g_match_info_fetch (info, 3); - msg_debug ("format_surbl_request: got hoster 3-d level domain %s.%s.%s", hpart1, hpart2, hpart3); + msg_debug ("got hoster 3-d level domain %s.%s.%s", hpart1, hpart2, hpart3); r = snprintf (result, len, "%s.%s.%s", hpart1, hpart2, hpart3); if (g_hash_table_lookup (surbl_module_ctx->whitelist, result) != NULL) { g_free (hpart1); g_free (hpart2); g_free (hpart3); g_match_info_free (info); - msg_debug ("format_surbl_request: url %s is whitelisted", result); + msg_debug ("url %s is whitelisted", result); g_set_error (err, SURBL_ERROR, /* error domain */ WHITELIST_ERROR, /* error code */ "URL is whitelisted: %s", /* error message format string */ @@ -389,7 +389,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it if (g_hash_table_lookup (surbl_module_ctx->whitelist, result) != NULL) { g_free (part1); g_free (part2); - msg_debug ("format_surbl_request: url %s is whitelisted", result); + msg_debug ("url %s is whitelisted", result); g_set_error (err, SURBL_ERROR, /* error domain */ WHITELIST_ERROR, /* error code */ "URL is whitelisted: %s", /* error message format string */ @@ -400,7 +400,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it r += snprintf (result + r, len - r, ".%s", suffix->suffix); } *host_end = result + r - slen - 1; - msg_debug ("format_surbl_request: got normal 2-d level domain %s.%s", part1, part2); + msg_debug ("got normal 2-d level domain %s.%s", part1, part2); } g_free (part1); g_free (part2); @@ -435,18 +435,18 @@ make_surbl_requests (struct uri *url, struct worker_task *task, GTree * tree, st *host_end = '\0'; param->host_resolve = memory_pool_strdup (task->task_pool, surbl_req); *host_end = '.'; - msg_debug ("surbl_test_url: send surbl dns request %s", surbl_req); + debug_task ("send surbl dns request %s", surbl_req); if (evdns_resolve_ipv4 (surbl_req, DNS_QUERY_NO_SEARCH, dns_callback, (void *)param) == 0) { param->task->save.saved++; register_async_event (task->s, (event_finalizer_t) dns_callback, NULL, TRUE); } } else { - msg_debug ("make_surbl_requests: request %s is already sent", surbl_req); + debug_task ("request %s is already sent", surbl_req); } } else if (err != NULL && err->code != WHITELIST_ERROR) { - msg_info ("surbl_test_url: cannot format url string for surbl %s, %s", struri (url), err->message); + msg_info ("cannot format url string for surbl %s, %s", struri (url), err->message); g_error_free (err); return; } @@ -455,7 +455,7 @@ make_surbl_requests (struct uri *url, struct worker_task *task, GTree * tree, st } } else { - msg_debug ("make_surbl_requests: skipping symbol that is not in view: %s", suffix->symbol); + debug_task ("skipping symbol that is not in view: %s", suffix->symbol); } } @@ -472,7 +472,7 @@ process_dns_results (struct worker_task *task, struct suffix_item *suffix, char while (cur) { bit = (struct surbl_bit_item *)cur->data; - msg_debug ("process_dns_results: got result(%d) AND bit(%d): %d", (int)addr, (int)ntohl (bit->bit), (int)bit->bit & (int)ntohl (addr)); + debug_task ("got result(%d) AND bit(%d): %d", (int)addr, (int)ntohl (bit->bit), (int)bit->bit & (int)ntohl (addr)); if (((int)bit->bit & (int)ntohl (addr)) != 0) { len = strlen (suffix->symbol) - 2 + strlen (bit->symbol) + 1; *c = '\0'; @@ -498,15 +498,16 @@ static void dns_callback (int result, char type, int count, int ttl, void *addresses, void *data) { struct dns_param *param = (struct dns_param *)data; + struct worker_task *task = param->task; - msg_debug ("dns_callback: in surbl request callback"); + debug_task ("in surbl request callback"); /* If we have result from DNS server, this url exists in SURBL, so increase score */ if (result == DNS_ERR_NONE && type == DNS_IPv4_A) { - msg_info ("surbl_check: <%s> domain [%s] is in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix); + msg_info ("<%s> domain [%s] is in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix); process_dns_results (param->task, param->suffix, param->host_resolve, (uint32_t) (((in_addr_t *) addresses)[0])); } else { - msg_debug ("surbl_check: <%s> domain [%s] is not in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix); + debug_task ("<%s> domain [%s] is not in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix); } param->task->save.saved--; @@ -528,7 +529,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data) switch (ctx->op) { case CMD_CONNECT: if (error != OK) { - msg_info ("memcached_callback: memcached returned error %s on CONNECT stage", memc_strerror (error)); + msg_info ("memcached returned error %s on CONNECT stage", memc_strerror (error)); memc_close_ctx (param->ctx); param->task->save.saved--; if (param->task->save.saved == 0) { @@ -543,7 +544,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data) break; case CMD_READ: if (error != OK) { - msg_info ("memcached_callback: memcached returned error %s on READ stage", memc_strerror (error)); + msg_info ("memcached returned error %s on READ stage", memc_strerror (error)); memc_close_ctx (param->ctx); param->task->save.saved--; if (param->task->save.saved == 0) { @@ -556,7 +557,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data) url_count = (int *)param->ctx->param->buf; /* Do not check DNS for urls that have count more than max_urls */ if (*url_count > surbl_module_ctx->max_urls) { - msg_info ("memcached_callback: url '%s' has count %d, max: %d", struri (param->url), *url_count, surbl_module_ctx->max_urls); + msg_info ("url '%s' has count %d, max: %d", struri (param->url), *url_count, surbl_module_ctx->max_urls); /* * XXX: try to understand why we should use memcached here * insert_result (param->task, surbl_module_ctx->metric, surbl_module_ctx->symbol, 1); @@ -568,7 +569,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data) break; case CMD_WRITE: if (error != OK) { - msg_info ("memcached_callback: memcached returned error %s on WRITE stage", memc_strerror (error)); + msg_info ("memcached returned error %s on WRITE stage", memc_strerror (error)); } memc_close_ctx (param->ctx); param->task->save.saved--; @@ -615,7 +616,7 @@ register_memcached_call (struct uri *url, struct worker_task *task, GTree * url_ task->cfg->memcached_servers_num, sizeof (struct memcached_server), time (NULL), task->cfg->memcached_error_time, task->cfg->memcached_dead_time, task->cfg->memcached_maxerrors, cur_param->key, strlen (cur_param->key)); if (selected == NULL) { - msg_err ("surbl_register_memcached_call: no memcached servers can be selected"); + msg_err ("no memcached servers can be selected"); return; } param->ctx->callback = memcached_callback; @@ -656,6 +657,7 @@ static void redirector_callback (int fd, short what, void *arg) { struct redirector_param *param = (struct redirector_param *)arg; + struct worker_task *task = param->task; char url_buf[1024]; int r; struct timeval *timeout; @@ -673,14 +675,14 @@ redirector_callback (int fd, short what, void *arg) event_add (¶m->ev, timeout); r = snprintf (url_buf, sizeof (url_buf), "GET %s HTTP/1.0\r\n\r\n", struri (param->url)); if (write (param->sock, url_buf, r) == -1) { - msg_err ("redirector_callback: write failed %s", strerror (errno)); + msg_err ("write failed %s", strerror (errno)); remove_normal_event (param->task->s, free_redirector_session, param); return; } param->state = STATE_READ; } else { - msg_info ("redirector_callback: <%s> connection to redirector timed out while waiting for write", param->task->message_id); + msg_info ("<%s> connection to redirector timed out while waiting for write", param->task->message_id); remove_normal_event (param->task->s, free_redirector_session, param); return; } @@ -698,14 +700,14 @@ redirector_callback (int fd, short what, void *arg) } } if (*p == '\0') { - msg_debug ("redirector_callback: <%s> got reply from redirector: '%s' -> '%s'", param->task->message_id, struri (param->url), c); + debug_task ("<%s> got reply from redirector: '%s' -> '%s'", param->task->message_id, struri (param->url), c); parse_uri (param->url, memory_pool_strdup (param->task->task_pool, c), param->task->task_pool); } } remove_normal_event (param->task->s, free_redirector_session, param); } else { - msg_info ("redirector_callback: <%s> reading redirector timed out, while waiting for read", param->task->message_id); + msg_info ("<%s> reading redirector timed out, while waiting for read", param->task->message_id); remove_normal_event (param->task->s, free_redirector_session, param); } break; @@ -723,7 +725,7 @@ register_redirector_call (struct uri *url, struct worker_task *task, GTree * url s = make_tcp_socket (&surbl_module_ctx->redirector_addr, surbl_module_ctx->redirector_port, FALSE, TRUE); if (s == -1) { - msg_info ("register_redirector_call: <%s> cannot create tcp socket failed: %s", task->message_id, strerror (errno)); + msg_info ("<%s> cannot create tcp socket failed: %s", task->message_id, strerror (errno)); task->save.saved--; make_surbl_requests (url, task, url_tree, suffix); return; @@ -748,12 +750,13 @@ static gboolean tree_url_callback (gpointer key, gpointer value, void *data) { struct redirector_param *param = data; + struct worker_task *task = param->task; struct uri *url = value; f_str_t f; char *urlstr, *host_end; GError *err = NULL; - msg_debug ("surbl_test_url: check url %s", struri (url)); + debug_task ("check url %s", struri (url)); if (surbl_module_ctx->use_redirector) { @@ -874,7 +877,7 @@ urls_command_handler (struct worker_task *task) outbuf[r++] = '\n'; rspamd_dispatcher_write (task->dispatcher, outbuf, r, FALSE, TRUE); - msg_info ("process_message: msg ok, id: <%s>, %d urls extracted", task->message_id, num); + msg_info ("msg ok, id: <%s>, %d urls extracted", task->message_id, num); g_tree_destroy (url_tree); return 0; diff --git a/src/protocol.c b/src/protocol.c index b89d5767a..0cba93b21 100644 --- a/src/protocol.c +++ b/src/protocol.c @@ -120,7 +120,7 @@ parse_command (struct worker_task *task, f_str_t * line) token = separate_command (line, ' '); if (line == NULL || token == NULL) { - msg_debug ("parse_command: bad command: %s", token); + debug_task ("bad command: %s", token); return -1; } @@ -132,7 +132,7 @@ parse_command (struct worker_task *task, f_str_t * line) task->cmd = CMD_CHECK; } else { - msg_debug ("parse_command: bad command: %s", token); + debug_task ("bad command: %s", token); return -1; } break; @@ -146,7 +146,7 @@ parse_command (struct worker_task *task, f_str_t * line) task->cmd = CMD_SKIP; } else { - msg_debug ("parse_command: bad command: %s", token); + debug_task ("bad command: %s", token); return -1; } break; @@ -160,7 +160,7 @@ parse_command (struct worker_task *task, f_str_t * line) task->cmd = CMD_PROCESS; } else { - msg_debug ("parse_command: bad command: %s", token); + debug_task ("bad command: %s", token); return -1; } break; @@ -174,7 +174,7 @@ parse_command (struct worker_task *task, f_str_t * line) task->cmd = CMD_REPORT_IFSPAM; } else { - msg_debug ("parse_command: bad command: %s", token); + debug_task ("bad command: %s", token); return -1; } break; @@ -191,7 +191,7 @@ parse_command (struct worker_task *task, f_str_t * line) } if (cur == NULL) { - msg_debug ("parse_command: bad command: %s", token); + debug_task ("bad command: %s", token); return -1; } break; @@ -228,7 +228,7 @@ parse_header (struct worker_task *task, f_str_t * line) /* Check end of headers */ if (line->len == 0) { - msg_debug ("parse_header: got empty line, assume it as end of headers"); + debug_task ("got empty line, assume it as end of headers"); if (task->cmd == CMD_PING || task->cmd == CMD_SKIP) { task->state = WRITE_REPLY; } @@ -264,11 +264,11 @@ parse_header (struct worker_task *task, f_str_t * line) if (task->content_length == 0) { tmp = memory_pool_fstrdup (task->task_pool, line); task->content_length = strtoul (tmp, &err, 10); - msg_debug ("parse_header: read Content-Length header, value: %lu", (unsigned long int)task->content_length); + debug_task ("read Content-Length header, value: %lu", (unsigned long int)task->content_length); } } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -277,10 +277,10 @@ parse_header (struct worker_task *task, f_str_t * line) /* Deliver-To */ if (strncasecmp (headern, DELIVER_TO_HEADER, sizeof (DELIVER_TO_HEADER) - 1) == 0) { task->deliver_to = memory_pool_fstrdup (task->task_pool, line); - msg_debug ("parse_header: read deliver-to header, value: %s", task->deliver_to); + debug_task ("read deliver-to header, value: %s", task->deliver_to); } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -289,10 +289,10 @@ parse_header (struct worker_task *task, f_str_t * line) /* helo */ if (strncasecmp (headern, HELO_HEADER, sizeof (HELO_HEADER) - 1) == 0) { task->helo = memory_pool_fstrdup (task->task_pool, line); - msg_debug ("parse_header: read helo header, value: %s", task->helo); + debug_task ("read helo header, value: %s", task->helo); } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -301,10 +301,10 @@ parse_header (struct worker_task *task, f_str_t * line) /* from */ if (strncasecmp (headern, FROM_HEADER, sizeof (FROM_HEADER) - 1) == 0) { task->from = memory_pool_fstrdup (task->task_pool, line); - msg_debug ("parse_header: read from header, value: %s", task->from); + debug_task ("read from header, value: %s", task->from); } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -313,10 +313,10 @@ parse_header (struct worker_task *task, f_str_t * line) /* Queue id */ if (strncasecmp (headern, QUEUE_ID_HEADER, sizeof (QUEUE_ID_HEADER) - 1) == 0) { task->queue_id = memory_pool_fstrdup (task->task_pool, line); - msg_debug ("parse_header: read queue_id header, value: %s", task->queue_id); + debug_task ("read queue_id header, value: %s", task->queue_id); } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -326,15 +326,15 @@ parse_header (struct worker_task *task, f_str_t * line) if (strncasecmp (headern, RCPT_HEADER, sizeof (RCPT_HEADER) - 1) == 0) { tmp = memory_pool_fstrdup (task->task_pool, line); task->rcpt = g_list_prepend (task->rcpt, tmp); - msg_debug ("parse_header: read rcpt header, value: %s", tmp); + debug_task ("read rcpt header, value: %s", tmp); } else if (strncasecmp (headern, NRCPT_HEADER, sizeof (NRCPT_HEADER) - 1) == 0) { tmp = memory_pool_fstrdup (task->task_pool, line); task->nrcpt = strtoul (tmp, &err, 10); - msg_debug ("parse_header: read rcpt header, value: %d", (int)task->nrcpt); + debug_task ("read rcpt header, value: %d", (int)task->nrcpt); } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -344,13 +344,13 @@ parse_header (struct worker_task *task, f_str_t * line) if (strncasecmp (headern, IP_ADDR_HEADER, sizeof (IP_ADDR_HEADER) - 1) == 0) { tmp = memory_pool_fstrdup (task->task_pool, line); if (!inet_aton (tmp, &task->from_addr)) { - msg_info ("parse_header: bad ip header: '%s'", tmp); + msg_info ("bad ip header: '%s'", tmp); return -1; } - msg_debug ("parse_header: read IP header, value: %s", tmp); + debug_task ("read IP header, value: %s", tmp); } else { - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } break; @@ -374,7 +374,7 @@ parse_header (struct worker_task *task, f_str_t * line) } break; default: - msg_info ("parse_header: wrong header: %s", headern); + msg_info ("wrong header: %s", headern); return -1; } @@ -419,7 +419,7 @@ show_url_header (struct worker_task *task) url = cur->data; if (task->cfg->log_urls) { /* Write this url to log as well */ - msg_info ("process_message: url found: <%s>, score: [%.2f / %.2f]", struri (url), default_score, default_required_score); + msg_info ("url found: <%s>, score: [%.2f / %.2f]", struri (url), default_score, default_required_score); } host.begin = url->host; host.len = url->hostlen; @@ -440,14 +440,14 @@ show_url_header (struct worker_task *task) if (g_list_next (cur) != NULL) { c = *(host.begin + host.len); *(host.begin + host.len) = '\0'; - msg_debug ("show_url_header: write url: %s", host.begin); + debug_task ("write url: %s", host.begin); r += snprintf (outbuf + r, sizeof (outbuf) - r, "%s, ", host.begin); *(host.begin + host.len) = c; } else { c = *(host.begin + host.len); *(host.begin + host.len) = '\0'; - msg_debug ("show_url_header: write url: %s", host.begin); + debug_task ("write url: %s", host.begin); r += snprintf (outbuf + r, sizeof (outbuf) - r, "%s" CRLF, host.begin); *(host.begin + host.len) = c; } @@ -642,7 +642,7 @@ write_check_reply (struct worker_task *task) cd.task = task; cd.log_buf = logbuf; - cd.log_offset = snprintf (logbuf, sizeof (logbuf), "process_message: msg ok, id: <%s>, ", task->message_id); + cd.log_offset = snprintf (logbuf, sizeof (logbuf), "msg ok, id: <%s>, ", task->message_id); cd.log_size = sizeof (logbuf); if (task->proto == SPAMC_PROTO) { @@ -694,7 +694,7 @@ write_process_reply (struct worker_task *task) cd.task = task; cd.log_buf = logbuf; - cd.log_offset = snprintf (logbuf, sizeof (logbuf), "process_message: msg ok, id: <%s>, ", task->message_id); + cd.log_offset = snprintf (logbuf, sizeof (logbuf), "msg ok, id: <%s>, ", task->message_id); cd.log_size = sizeof (logbuf); if (task->proto == SPAMC_PROTO) { @@ -742,18 +742,18 @@ write_reply (struct worker_task *task) int r; char outbuf[OUTBUFSIZ]; - msg_debug ("write_reply: writing reply to client"); + debug_task ("writing reply to client"); if (task->error_code != 0) { /* Write error message and error code to reply */ if (task->proto == SPAMC_PROTO) { r = snprintf (outbuf, sizeof (outbuf), "%s/%s %d %s" CRLF CRLF, SPAMD_REPLY_BANNER, task->proto_ver, task->error_code, SPAMD_ERROR); - msg_debug ("write_reply: writing error: %s", outbuf); + debug_task ("writing error: %s", outbuf); } else { r = snprintf (outbuf, sizeof (outbuf), "%s/%s %d %s" CRLF "%s: %s" CRLF CRLF, RSPAMD_REPLY_BANNER, task->proto_ver, task->error_code, SPAMD_ERROR, ERROR_HEADER, task->last_error); - msg_debug ("write_reply: writing error: %s", outbuf); + debug_task ("writing error: %s", outbuf); } /* Write to bufferevent error message */ rspamd_dispatcher_write (task->dispatcher, outbuf, r, FALSE, FALSE); diff --git a/src/settings.c b/src/settings.c index bcb40505c..6de04a7eb 100644 --- a/src/settings.c +++ b/src/settings.c @@ -126,11 +126,11 @@ json_fin_cb (memory_pool_t * pool, struct map_cb_data *data) jb = data->cur_data; } else { - msg_err ("json_fin_cb: no data read"); + msg_err ("no data read"); return; } if (jb->buf == NULL) { - msg_err ("json_fin_cb: no data read"); + msg_err ("no data read"); return; } /* NULL terminate current buf */ @@ -138,13 +138,13 @@ json_fin_cb (memory_pool_t * pool, struct map_cb_data *data) js = json_loads (jb->buf, &je); if (!js) { - msg_err ("json_fin_cb: cannot load json data: parse error %s, on line %d", je.text, je.line); + msg_err ("cannot load json data: parse error %s, on line %d", je.text, je.line); return; } if (!json_is_array (js)) { json_decref (js); - msg_err ("json_fin_cb: loaded json is not an array"); + msg_err ("loaded json is not an array"); return; } @@ -160,13 +160,13 @@ json_fin_cb (memory_pool_t * pool, struct map_cb_data *data) cur_elt = json_array_get (js, i); if (!cur_elt || !json_is_object (cur_elt)) { json_decref (js); - msg_err ("json_fin_cb: loaded json is not an object"); + msg_err ("loaded json is not an object"); return; } cur_nm = json_object_get (cur_elt, "name"); if (cur_nm == NULL || !json_is_string (cur_nm)) { json_decref (js); - msg_err ("json_fin_cb: name is not a string or not exists"); + msg_err ("name is not a string or not exists"); return; } cur_name = g_strdup (json_string_value (cur_nm)); @@ -241,7 +241,7 @@ read_settings (const char *path, struct config_file *cfg, GHashTable * table) *pjb = jb; if (!add_map (path, json_read_cb, json_fin_cb, (void **)pjb)) { - msg_err ("read_settings: cannot add map %s", path); + msg_err ("cannot add map %s", path); return FALSE; } diff --git a/src/spf.c b/src/spf.c index 49ef39891..d9f64310d 100644 --- a/src/spf.c +++ b/src/spf.c @@ -175,7 +175,7 @@ parse_spf_ipmask (const char *begin, struct spf_addr *addr) /* Also parse mask */ addr->mask = (mask_buf[0] - '0') * 10 + mask_buf[1] - '0'; if (addr->mask > 32) { - msg_info ("parse_spf_ipmask: bad ipmask value: '%s'", begin); + msg_info ("bad ipmask value: '%s'", begin); return FALSE; } } @@ -329,11 +329,11 @@ spf_record_dns_callback (int result, char type, int count, int ttl, void *addres switch (cb->cur_action) { case SPF_RESOLVE_MX: if (type == DNS_MX) { - msg_info ("spf_dns_callback: cannot find MX record for %s", cb->rec->cur_domain); + msg_info ("cannot find MX record for %s", cb->rec->cur_domain); cb->addr->addr = ntohl (INADDR_NONE); } else if (type == DNS_IPv4_A) { - msg_info ("spf_dns_callback: cannot resolve MX record for %s", cb->rec->cur_domain); + msg_info ("cannot resolve MX record for %s", cb->rec->cur_domain); cb->addr->addr = ntohl (INADDR_NONE); } break; @@ -346,10 +346,10 @@ spf_record_dns_callback (int result, char type, int count, int ttl, void *addres case SPF_RESOLVE_PTR: break; case SPF_RESOLVE_REDIRECT: - msg_info ("spf_dns_callback: cannot resolve TXT record for redirect action"); + msg_info ("cannot resolve TXT record for redirect action"); break; case SPF_RESOLVE_INCLUDE: - msg_info ("spf_dns_callback: cannot resolve TXT record for include action"); + msg_info ("cannot resolve TXT record for include action"); break; case SPF_RESOLVE_EXP: break; @@ -412,7 +412,7 @@ parse_spf_ptr (struct worker_task *task, const char *begin, struct spf_record *r { CHECK_REC (rec); - msg_info ("parse_spf_ptr: ptr parsing is unimplemented"); + msg_info ("ptr parsing is unimplemented"); return FALSE; } @@ -514,7 +514,7 @@ parse_spf_exp (struct worker_task *task, const char *begin, struct spf_record *r { CHECK_REC (rec); - msg_info ("parse_spf_exp: exp record is ignored"); + msg_info ("exp record is ignored"); return TRUE; } @@ -586,7 +586,7 @@ reverse_spf_ip (char *ip, int len) int t = 0, l = len; if (len > sizeof (ipbuf)) { - msg_info ("reverse_spf_ip: cannot reverse string of length %d", len); + msg_info ("cannot reverse string of length %d", len); return; } @@ -648,7 +648,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) } else { /* Something unknown */ - msg_info ("expand_spf_macro: bad spf element: %s", begin); + msg_info ("bad spf element: %s", begin); return begin; } p ++; @@ -681,7 +681,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) } break; default: - msg_info ("expand_spf_macro: unknown or unsupported spf macro %c in %s", *p, begin); + msg_info ("unknown or unsupported spf macro %c in %s", *p, begin); return begin; } p ++; @@ -694,7 +694,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) state = 0; } else if (*p != 'r' && !g_ascii_isdigit (*p)) { - msg_info ("expand_spf_macro: unknown or unsupported spf modifier %c in %s", *p, begin); + msg_info ("unknown or unsupported spf modifier %c in %s", *p, begin); return begin; } p ++; @@ -749,7 +749,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) } else { /* Something unknown */ - msg_info ("expand_spf_macro: bad spf element: %s", begin); + msg_info ("bad spf element: %s", begin); return begin; } p ++; @@ -799,7 +799,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) } break; default: - msg_info ("expand_spf_macro: unknown or unsupported spf macro %c in %s", *p, begin); + msg_info ("unknown or unsupported spf macro %c in %s", *p, begin); return begin; } p ++; @@ -818,7 +818,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) /*XXX: try to implement domain strimming */ } else { - msg_info ("expand_spf_macro: unknown or unsupported spf modifier %c in %s", *p, begin); + msg_info ("unknown or unsupported spf modifier %c in %s", *p, begin); return begin; } p ++; @@ -827,7 +827,7 @@ expand_spf_macro (struct worker_task *task, struct spf_record *rec, char *begin) } /* Null terminate */ *c = '\0'; - msg_info ("expanded string: %s", new); + msg_info ("%s", new); return new; } @@ -872,7 +872,7 @@ parse_spf_record (struct worker_task *task, struct spf_record *rec) res = parse_spf_a (task, begin, rec, new); } else { - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); } break; case 'i': @@ -888,7 +888,7 @@ parse_spf_record (struct worker_task *task, struct spf_record *rec) res = parse_spf_include (task, begin, rec, new); } else { - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); } break; case 'm': @@ -899,7 +899,7 @@ parse_spf_record (struct worker_task *task, struct spf_record *rec) res = parse_spf_mx (task, begin, rec, new); } else { - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); } break; case 'p': @@ -910,7 +910,7 @@ parse_spf_record (struct worker_task *task, struct spf_record *rec) res = parse_spf_ptr (task, begin, rec, new); } else { - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); } break; case 'e': @@ -925,7 +925,7 @@ parse_spf_record (struct worker_task *task, struct spf_record *rec) res = parse_spf_exists (task, begin, rec, new); } else { - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); } break; case 'r': @@ -935,11 +935,11 @@ parse_spf_record (struct worker_task *task, struct spf_record *rec) res = parse_spf_redirect (task, begin, rec, NULL); } else { - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); } break; default: - msg_info ("parse_spf_record: bad spf command: %s", begin); + msg_info ("bad spf command: %s", begin); break; } if (res) { @@ -974,7 +974,7 @@ start_spf_parse (struct spf_record *rec, char *begin) } } else { - msg_info ("start_spf_parse: bad spf record version: %*s", sizeof (SPF_VER_STR) - 1, begin); + msg_info ("bad spf record version: %*s", sizeof (SPF_VER_STR) - 1, begin); } } diff --git a/src/statfile.c b/src/statfile.c index 92a29f46d..c3313e47a 100644 --- a/src/statfile.c +++ b/src/statfile.c @@ -71,11 +71,11 @@ convert_statfile_10 (stat_file_t * file) /* Format backup name */ backup_name = g_strdup_printf ("%s.%s", file->filename, BACKUP_SUFFIX); - msg_info ("convert_statfile_10: convert old statfile %s to version %c.%c, backup in %s", file->filename, + msg_info ("convert old statfile %s to version %c.%c, backup in %s", file->filename, header.version[0], header.version[1], backup_name); if (stat (backup_name, &st) != -1) { - msg_info ("convert_statfile_10: replace old %s", backup_name); + msg_info ("replace old %s", backup_name); unlink (backup_name); } @@ -86,26 +86,26 @@ convert_statfile_10 (stat_file_t * file) unlock_file (file->fd, FALSE); close (file->fd); if ((file->fd = open (file->filename, O_RDWR | O_TRUNC | O_CREAT, S_IWUSR | S_IRUSR)) == -1) { - msg_info ("convert_statfile_10: cannot create file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot create file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } lock_file (file->fd, FALSE); /* Now make new header and copy it to new file */ if (write (file->fd, &header, sizeof (header)) == -1) { - msg_info ("convert_statfile_10: cannot write to file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot write to file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } /* Now write old map to new file */ if (write (file->fd, ((u_char *)file->map + sizeof (struct stat_file_header_10)), file->len - sizeof (struct stat_file_header_10)) == -1) { - msg_info ("convert_statfile_10: cannot write to file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot write to file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } /* Unmap old memory and map new */ munmap (file->map, file->len); file->len = file->len + sizeof (struct stat_file_header) - sizeof (struct stat_file_header_10); if ((file->map = mmap (NULL, file->len, PROT_READ | PROT_WRITE, MAP_SHARED, file->fd, 0)) == MAP_FAILED) { - msg_info ("convert_statfile_10: cannot mmap file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot mmap file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } @@ -126,7 +126,7 @@ statfile_pool_check (stat_file_t * file) } if (file->len < sizeof (struct stat_file)) { - msg_info ("statfile_pool_check: file %s is too short to be stat file: %zd", file->filename, file->len); + msg_info ("file %s is too short to be stat file: %zd", file->filename, file->len); return -1; } @@ -134,7 +134,7 @@ statfile_pool_check (stat_file_t * file) c = f->header.magic; /* Check magic and version */ if (*c++ != 'r' || *c++ != 's' || *c++ != 'd') { - msg_info ("statfile_pool_check: file %s is invalid stat file", file->filename); + msg_info ("file %s is invalid stat file", file->filename); return -1; } /* Now check version and convert old version to new one (that can be used for sync */ @@ -146,7 +146,7 @@ statfile_pool_check (stat_file_t * file) } else if (memcmp (c, valid_version, sizeof (valid_version)) != 0) { /* Unknown version */ - msg_info ("statfile_pool_check: file %s has invalid version %c.%c", file->filename, '0' + *c, '0' + *(c + 1)); + msg_info ("file %s has invalid version %c.%c", file->filename, '0' + *c, '0' + *(c + 1)); return -1; } @@ -154,7 +154,7 @@ statfile_pool_check (stat_file_t * file) file->cur_section.code = f->section.code; file->cur_section.length = f->section.length; if (file->cur_section.length * sizeof (struct stat_file_block) > file->len) { - msg_info ("statfile_pool_check: file %s is truncated: %z, must be %z", file->filename, file->len, file->cur_section.length * sizeof (struct stat_file_block)); + msg_info ("file %s is truncated: %z, must be %z", file->filename, file->len, file->cur_section.length * sizeof (struct stat_file_block)); return -1; } file->seek_pos = sizeof (struct stat_file) - sizeof (struct stat_file_block); @@ -229,7 +229,7 @@ statfile_pool_reindex (statfile_pool_t * pool, char *filename, size_t old_size, backup = g_strconcat (filename, ".old", NULL); if (rename (filename, backup) == -1) { - msg_err ("statfile_pool_reindex: cannot rename %s to %s: %s", filename, backup, strerror (errno)); + msg_err ("cannot rename %s to %s: %s", filename, backup, strerror (errno)); g_free (backup); memory_pool_unlock_mutex (pool->lock); return NULL; @@ -239,7 +239,7 @@ statfile_pool_reindex (statfile_pool_t * pool, char *filename, size_t old_size, /* Now create new file with required size */ if (statfile_pool_create (pool, filename, size) != 0) { - msg_err ("statfile_pool_reindex: cannot create new file"); + msg_err ("cannot create new file"); g_free (backup); return NULL; } @@ -248,14 +248,14 @@ statfile_pool_reindex (statfile_pool_t * pool, char *filename, size_t old_size, new = statfile_pool_open (pool, filename, size, TRUE); if (fd == -1 || new == NULL) { - msg_err ("statfile_pool_reindex: cannot open file: %s", strerror (errno)); + msg_err ("cannot open file: %s", strerror (errno)); g_free (backup); return NULL; } /* Now start reading blocks from old statfile */ if ((map = mmap (NULL, old_size, PROT_READ, MAP_SHARED, fd, 0)) == MAP_FAILED) { - msg_err ("statfile_pool_reindex: cannot mmap file: %s", strerror (errno)); + msg_err ("cannot mmap file: %s", strerror (errno)); close (fd); g_free (backup); return NULL; @@ -290,24 +290,24 @@ statfile_pool_open (statfile_pool_t * pool, char *filename, size_t size, gboolea } if (pool->opened >= STATFILES_MAX - 1) { - msg_err ("sttafile_pool_open: reached hard coded limit of statfiles opened: %d", STATFILES_MAX); + msg_err ("reached hard coded limit of statfiles opened: %d", STATFILES_MAX); return NULL; } if (stat (filename, &st) == -1) { - msg_info ("statfile_pool_open: cannot stat file %s, error %s, %d", filename, strerror (errno), errno); + msg_info ("cannot stat file %s, error %s, %d", filename, strerror (errno), errno); return NULL; } if (!forced && st.st_size > pool->max) { - msg_info ("statfile_pool_open: cannot attach file to pool, too large: %zd", (size_t) st.st_size); + msg_info ("cannot attach file to pool, too large: %zd", (size_t) st.st_size); return NULL; } memory_pool_lock_mutex (pool->lock); if (!forced && abs (st.st_size - size) > sizeof (struct stat_file)) { memory_pool_unlock_mutex (pool->lock); - msg_warn ("statfile_pool_open: need to reindex statfile old size: %zd, new size: %zd", st.st_size, size); + msg_warn ("need to reindex statfile old size: %zd, new size: %zd", st.st_size, size); return statfile_pool_reindex (pool, filename, st.st_size, size); } memory_pool_unlock_mutex (pool->lock); @@ -315,7 +315,7 @@ statfile_pool_open (statfile_pool_t * pool, char *filename, size_t size, gboolea while (!forced && (pool->max + pool->opened * sizeof (struct stat_file) * 2 < pool->occupied + st.st_size)) { if (statfile_pool_expire (pool) == -1) { /* Failed to find any more free space in pool */ - msg_info ("statfile_pool_open: expiration for pool failed, opening file %s failed", filename); + msg_info ("expiration for pool failed, opening file %s failed", filename); return NULL; } } @@ -324,7 +324,7 @@ statfile_pool_open (statfile_pool_t * pool, char *filename, size_t size, gboolea new_file = &pool->files[pool->opened++]; bzero (new_file, sizeof (stat_file_t)); if ((new_file->fd = open (filename, O_RDWR)) == -1) { - msg_info ("statfile_pool_open: cannot open file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot open file %s, error %d, %s", filename, errno, strerror (errno)); memory_pool_unlock_mutex (pool->lock); pool->opened--; return NULL; @@ -333,7 +333,7 @@ statfile_pool_open (statfile_pool_t * pool, char *filename, size_t size, gboolea if ((new_file->map = mmap (NULL, st.st_size, PROT_READ | PROT_WRITE, MAP_SHARED, new_file->fd, 0)) == MAP_FAILED) { close (new_file->fd); memory_pool_unlock_mutex (pool->lock); - msg_info ("statfile_pool_open: cannot mmap file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot mmap file %s, error %d, %s", filename, errno, strerror (errno)); pool->opened--; return NULL; @@ -370,7 +370,7 @@ statfile_pool_close (statfile_pool_t * pool, stat_file_t * file, gboolean keep_s stat_file_t *pos; if ((pos = statfile_pool_is_open (pool, file->filename)) == NULL) { - msg_info ("statfile_pool_open: file %s is not opened", file->filename); + msg_info ("file %s is not opened", file->filename); return -1; } @@ -418,7 +418,7 @@ statfile_pool_create (statfile_pool_t * pool, char *filename, size_t size) char *buf = NULL; if (statfile_pool_is_open (pool, filename) != NULL) { - msg_info ("statfile_pool_open: file %s is already opened", filename); + msg_info ("file %s is already opened", filename); return 0; } @@ -427,14 +427,14 @@ statfile_pool_create (statfile_pool_t * pool, char *filename, size_t size) header.total_blocks = nblocks; if ((fd = open (filename, O_RDWR | O_TRUNC | O_CREAT, S_IWUSR | S_IRUSR)) == -1) { - msg_info ("statfile_pool_create: cannot create file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot create file %s, error %d, %s", filename, errno, strerror (errno)); memory_pool_unlock_mutex (pool->lock); return -1; } header.create_time = (uint64_t) time (NULL); if (write (fd, &header, sizeof (header)) == -1) { - msg_info ("statfile_pool_create: cannot write header to file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot write header to file %s, error %d, %s", filename, errno, strerror (errno)); close (fd); memory_pool_unlock_mutex (pool->lock); return -1; @@ -442,7 +442,7 @@ statfile_pool_create (statfile_pool_t * pool, char *filename, size_t size) section.length = (uint64_t) nblocks; if (write (fd, §ion, sizeof (section)) == -1) { - msg_info ("statfile_pool_create: cannot write section header to file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot write section header to file %s, error %d, %s", filename, errno, strerror (errno)); close (fd); memory_pool_unlock_mutex (pool->lock); return -1; @@ -458,7 +458,7 @@ statfile_pool_create (statfile_pool_t * pool, char *filename, size_t size) if (nblocks > 256) { /* Just write buffer */ if (write (fd, buf, buflen) == -1) { - msg_info ("statfile_pool_create: cannot write blocks buffer to file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot write blocks buffer to file %s, error %d, %s", filename, errno, strerror (errno)); close (fd); memory_pool_unlock_mutex (pool->lock); g_free (buf); @@ -468,7 +468,7 @@ statfile_pool_create (statfile_pool_t * pool, char *filename, size_t size) } else { if (write (fd, &block, sizeof (block)) == -1) { - msg_info ("statfile_pool_create: cannot write block to file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot write block to file %s, error %d, %s", filename, errno, strerror (errno)); close (fd); if (buf) { g_free (buf); @@ -576,7 +576,7 @@ statfile_pool_set_block_common (statfile_pool_t * pool, stat_file_t * file, uint for (i = 0; i < CHAIN_LENGTH; i++) { if (i + blocknum >= file->cur_section.length) { /* Need to expire some block in chain */ - msg_debug ("statfile_pool_set_block: chain %u is full, starting expire", blocknum); + msg_debug ("chain %u is full, starting expire", blocknum); break; } /* First try to find block in chain */ @@ -587,7 +587,7 @@ statfile_pool_set_block_common (statfile_pool_t * pool, stat_file_t * file, uint /* Check whether we have a free block in chain */ if (block->hash1 == 0 && block->hash2 == 0) { /* Write new block here */ - msg_debug ("statfile_pool_set_block: found free block %u in chain %u, set h1=%u, h2=%u", i, blocknum, h1, h2); + msg_debug ("found free block %u in chain %u, set h1=%u, h2=%u", i, blocknum, h1, h2); block->hash1 = h1; block->hash2 = h2; block->value = value; @@ -681,7 +681,7 @@ statfile_pool_add_section (statfile_pool_t * pool, stat_file_t * file, uint32_t struct stat_file_block block = { 0, 0, 0 }; if (lseek (file->fd, 0, SEEK_END) == -1) { - msg_info ("statfile_pool_add_section: cannot lseek file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot lseek file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } @@ -689,13 +689,13 @@ statfile_pool_add_section (statfile_pool_t * pool, stat_file_t * file, uint32_t sect.length = length; if (write (file->fd, §, sizeof (sect)) == -1) { - msg_info ("statfile_pool_add_section: cannot write block to file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot write block to file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } while (length--) { if (write (file->fd, &block, sizeof (block)) == -1) { - msg_info ("statfile_pool_add_section: cannot write block to file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot write block to file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } } @@ -707,19 +707,19 @@ statfile_pool_add_section (statfile_pool_t * pool, stat_file_t * file, uint32_t file->len += length; if (file->len > pool->max) { - msg_info ("statfile_pool_open: cannot attach file to pool, too large: %lu", (long int)file->len); + msg_info ("cannot attach file to pool, too large: %lu", (long int)file->len); return FALSE; } while (pool->max <= pool->occupied + file->len) { if (statfile_pool_expire (pool) == -1) { /* Failed to find any more free space in pool */ - msg_info ("statfile_pool_open: expiration for pool failed, opening file %s failed", file->filename); + msg_info ("expiration for pool failed, opening file %s failed", file->filename); return FALSE; } } if ((file->map = mmap (NULL, file->len, PROT_READ | PROT_WRITE, MAP_SHARED, file->fd, 0)) == NULL) { - msg_info ("statfile_pool_open: cannot mmap file %s, error %d, %s", file->filename, errno, strerror (errno)); + msg_info ("cannot mmap file %s, error %d, %s", file->filename, errno, strerror (errno)); return FALSE; } statfile_pool_unlock_file (pool, file); diff --git a/src/statfile_sync.c b/src/statfile_sync.c index 490deb0fd..1e5baeb7d 100644 --- a/src/statfile_sync.c +++ b/src/statfile_sync.c @@ -118,7 +118,7 @@ parse_revision_line (struct rspamd_sync_ctx *ctx, f_str_t *in) errno = 0; *val = strtoull (numbuf, NULL, 10); if (errno != 0) { - msg_info ("parse_revision_line: cannot parse number %s", strerror (errno)); + msg_info ("cannot parse number %s", strerror (errno)); return FALSE; } state = 2; @@ -182,7 +182,7 @@ sync_read (f_str_t * in, void *arg) case SYNC_STATE_READ_LINE: /* Try to parse line from server */ if (!parse_revision_line (ctx, in)) { - msg_info ("sync_read: cannot parse line: %*s", in->len, in->begin); + msg_info ("cannot parse line: %*s", in->len, in->begin); close (ctx->sock); rspamd_remove_dispatcher (ctx->dispatcher); ctx->is_busy = FALSE; @@ -194,7 +194,7 @@ sync_read (f_str_t * in, void *arg) } else { /* Quit this session */ - msg_info ("sync_read: sync ended for: %s", ctx->st->symbol); + msg_info ("sync ended for: %s", ctx->st->symbol); close (ctx->sock); rspamd_remove_dispatcher (ctx->dispatcher); ctx->is_busy = FALSE; @@ -205,7 +205,7 @@ sync_read (f_str_t * in, void *arg) case SYNC_STATE_READ_REV: /* In now contains all blocks of specified revision, so we can read them directly */ if (!read_blocks (ctx, in)) { - msg_info ("sync_read: cannot read blocks"); + msg_info ("cannot read blocks"); close (ctx->sock); rspamd_remove_dispatcher (ctx->dispatcher); ctx->is_busy = FALSE; @@ -231,7 +231,7 @@ sync_err (GError *err, void *arg) { struct rspamd_sync_ctx *ctx = arg; - msg_info ("sync_err: abnormally closing connection, error: %s", err->message); + msg_info ("abnormally closing connection, error: %s", err->message); ctx->is_busy = FALSE; close (ctx->sock); rspamd_remove_dispatcher (ctx->dispatcher); @@ -252,12 +252,12 @@ sync_timer_callback (int fd, short what, void *ud) if (ctx->is_busy) { /* Sync is in progress */ - msg_info ("sync_timer_callback: syncronization process is in progress, do not start new one"); + msg_info ("syncronization process is in progress, do not start new one"); return; } if ((ctx->sock = make_tcp_socket (&ctx->st->binlog->master_addr, ctx->st->binlog->master_port, FALSE, TRUE)) == -1) { - msg_info ("sync_timer_callback: cannot connect to %s", inet_ntoa (ctx->st->binlog->master_addr)); + msg_info ("cannot connect to %s", inet_ntoa (ctx->st->binlog->master_addr)); return; } /* Now create and activate dispatcher */ @@ -268,7 +268,7 @@ sync_timer_callback (int fd, short what, void *ud) ctx->state = SYNC_STATE_GREETING; ctx->is_busy = TRUE; - msg_info ("sync_timer_callback: starting synchronization of %s", ctx->st->symbol); + msg_info ("starting synchronization of %s", ctx->st->symbol); } @@ -285,9 +285,9 @@ add_statfile_watch (statfile_pool_t *pool, struct statfile *st) /* Open statfile and attach it to pool */ if ((ctx->real_statfile = statfile_pool_is_open (pool, st->path)) == NULL) { if ((ctx->real_statfile = statfile_pool_open (pool, st->path, st->size, FALSE)) == NULL) { - msg_warn ("add_statfile_watch: cannot open %s", st->path); + msg_warn ("cannot open %s", st->path); if (statfile_pool_create (pool, st->path, st->size) == -1) { - msg_err ("add_statfile_watch: cannot create statfile %s", st->path); + msg_err ("cannot create statfile %s", st->path); return FALSE; } ctx->real_statfile = statfile_pool_open (pool, st->path, st->size, FALSE); diff --git a/src/symbols_cache.c b/src/symbols_cache.c index 8ecae4513..060a04187 100644 --- a/src/symbols_cache.c +++ b/src/symbols_cache.c @@ -128,7 +128,7 @@ mmap_cache_file (struct symbols_cache *cache, int fd) map = mmap (NULL, cache->used_items * sizeof (struct saved_cache_item), PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0); if (map == MAP_FAILED) { - msg_err ("mmap_cache_file: cannot mmap cache file: %d, %s", errno, strerror (errno)); + msg_err ("cannot mmap cache file: %d, %s", errno, strerror (errno)); close (fd); return FALSE; } @@ -156,7 +156,7 @@ create_cache_file (struct symbols_cache *cache, const char *filename, int fd) /* Calculate checksum */ cksum = get_mem_cksum (cache); if (cksum == NULL) { - msg_err ("load_symbols_cache: cannot calculate checksum for symbols"); + msg_err ("cannot calculate checksum for symbols"); close (fd); return FALSE; } @@ -168,7 +168,7 @@ create_cache_file (struct symbols_cache *cache, const char *filename, int fd) /* Now write data to file */ for (i = 0; i < cache->used_items; i++) { if (write (fd, cache->items[i].s, sizeof (struct saved_cache_item)) == -1) { - msg_err ("create_cache_file: cannot write to file %d, %s", errno, strerror (errno)); + msg_err ("cannot write to file %d, %s", errno, strerror (errno)); close (fd); g_checksum_free (cksum); g_free (digest); @@ -177,7 +177,7 @@ create_cache_file (struct symbols_cache *cache, const char *filename, int fd) } /* Write checksum */ if (write (fd, digest, cklen) == -1) { - msg_err ("create_cache_file: cannot write to file %d, %s", errno, strerror (errno)); + msg_err ("cannot write to file %d, %s", errno, strerror (errno)); close (fd); g_checksum_free (cksum); g_free (digest); @@ -189,7 +189,7 @@ create_cache_file (struct symbols_cache *cache, const char *filename, int fd) g_free (digest); /* Reopen for reading */ if ((fd = open (filename, O_RDWR)) == -1) { - msg_info ("create_cache_file: cannot open file %s, error %d, %s", errno, strerror (errno)); + msg_info ("cannot open file %s, error %d, %s", errno, strerror (errno)); return FALSE; } @@ -262,7 +262,7 @@ init_symbols_cache (memory_pool_t * pool, struct symbols_cache *cache, const cha if (errno == ENOENT) { /* Try to create file */ if ((fd = open (filename, O_RDWR | O_TRUNC | O_CREAT, S_IWUSR | S_IRUSR)) == -1) { - msg_info ("load_symbols_cache: cannot create file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot create file %s, error %d, %s", filename, errno, strerror (errno)); return FALSE; } else { @@ -270,13 +270,13 @@ init_symbols_cache (memory_pool_t * pool, struct symbols_cache *cache, const cha } } else { - msg_info ("load_symbols_cache: cannot stat file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot stat file %s, error %d, %s", filename, errno, strerror (errno)); return FALSE; } } else { if ((fd = open (filename, O_RDWR)) == -1) { - msg_info ("load_symbols_cache: cannot open file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot open file %s, error %d, %s", filename, errno, strerror (errno)); return FALSE; } } @@ -284,7 +284,7 @@ init_symbols_cache (memory_pool_t * pool, struct symbols_cache *cache, const cha /* Calculate checksum */ cksum = get_mem_cksum (cache); if (cksum == NULL) { - msg_err ("load_symbols_cache: cannot calculate checksum for symbols"); + msg_err ("cannot calculate checksum for symbols"); close (fd); return FALSE; } @@ -298,7 +298,7 @@ init_symbols_cache (memory_pool_t * pool, struct symbols_cache *cache, const cha close (fd); g_free (mem_sum); g_checksum_free (cksum); - msg_err ("load_symbols_cache: cannot seek to read checksum, %d, %s", errno, strerror (errno)); + msg_err ("cannot seek to read checksum, %d, %s", errno, strerror (errno)); return FALSE; } file_sum = g_malloc (cklen); @@ -307,7 +307,7 @@ init_symbols_cache (memory_pool_t * pool, struct symbols_cache *cache, const cha g_free (mem_sum); g_free (file_sum); g_checksum_free (cksum); - msg_err ("load_symbols_cache: cannot read checksum, %d, %s", errno, strerror (errno)); + msg_err ("cannot read checksum, %d, %s", errno, strerror (errno)); return FALSE; } @@ -316,10 +316,10 @@ init_symbols_cache (memory_pool_t * pool, struct symbols_cache *cache, const cha g_free (mem_sum); g_free (file_sum); g_checksum_free (cksum); - msg_info ("load_symbols_cache: checksum mismatch, recreating file"); + msg_info ("checksum mismatch, recreating file"); /* Reopen with rw permissions */ if ((fd = open (filename, O_RDWR | O_TRUNC | O_CREAT, S_IWUSR | S_IRUSR)) == -1) { - msg_info ("load_symbols_cache: cannot create file %s, error %d, %s", filename, errno, strerror (errno)); + msg_info ("cannot create file %s, error %d, %s", filename, errno, strerror (errno)); return FALSE; } else { @@ -346,7 +346,7 @@ call_symbol_callback (struct worker_task * task, struct symbols_cache * cache, s return FALSE; } if (cache->uses++ >= MAX_USES) { - msg_info ("call_symbols_callback: resort symbols cache"); + msg_info ("resort symbols cache"); memory_pool_wlock_rwlock (cache->lock); cache->uses = 0; /* Resort while having write lock */ diff --git a/src/tokenizers/osb.c b/src/tokenizers/osb.c index 8bbf30d7f..d36047efd 100644 --- a/src/tokenizers/osb.c +++ b/src/tokenizers/osb.c @@ -52,8 +52,6 @@ osb_tokenize_text (struct tokenizer *tokenizer, memory_pool_t * pool, f_str_t * memory_pool_add_destructor (pool, (pool_destruct_func) g_tree_destroy, *tree); } - msg_debug ("osb_tokenize_text: got input length: %zd", input->len); - while ((res = tokenizer->get_next_word (input, &token)) != NULL) { /* Skip small words */ if (token.len < MIN_LEN) { diff --git a/src/upstream.c b/src/upstream.c index fac7d3381..cb5171075 100644 --- a/src/upstream.c +++ b/src/upstream.c @@ -120,7 +120,6 @@ check_upstream (struct upstream *up, time_t now, time_t error_timeout, time_t re { if (up->dead) { if (now - up->time >= revive_timeout) { - msg_debug ("check_upstream: reviving upstream after %ld seconds", (long int)now - up->time); U_WLOCK (); up->dead = 0; up->errors = 0; @@ -131,7 +130,6 @@ check_upstream (struct upstream *up, time_t now, time_t error_timeout, time_t re } else { if (now - up->time >= error_timeout && up->errors >= max_errors) { - msg_debug ("check_upstream: marking upstreams as dead after %ld errors", (long int)up->errors); U_WLOCK (); up->dead = 1; up->time = now; @@ -185,7 +183,6 @@ revive_all_upstreams (void *ups, size_t members, size_t msize) u_char *p; U_WLOCK (); - msg_debug ("revive_all_upstreams: starting reviving all upstreams"); p = ups; for (i = 0; i < members; i++) { cur = (struct upstream *)p; @@ -225,7 +222,6 @@ rescan_upstreams (void *ups, size_t members, size_t msize, time_t now, time_t er alive = members; } - msg_debug ("rescan_upstreams: %d upstreams alive", alive); return alive; @@ -300,7 +296,6 @@ get_random_upstream (void *ups, size_t members, size_t msize, time_t now, time_t alive = rescan_upstreams (ups, members, msize, now, error_timeout, revive_timeout, max_errors); selected = rand () % alive; - msg_debug ("get_random_upstream: return upstream with number %d of %d", selected, alive); return get_upstream_by_number (ups, members, msize, selected); } @@ -327,7 +322,6 @@ get_upstream_by_hash (void *ups, size_t members, size_t msize, time_t now, time_ h = (h >> 16) & 0x7fff; #endif h %= members; - msg_debug ("get_upstream_by_hash: try to select upstream number %d of %zd", h, members); for (;;) { p = (char *)ups + msize * h; @@ -344,10 +338,8 @@ get_upstream_by_hash (void *ups, size_t members, size_t msize, time_t now, time_ h += ht; #endif h %= members; - msg_debug ("get_upstream_by_hash: try to select upstream number %d of %zd, tries: %d", h, members, tries); tries++; if (tries > MAX_TRIES) { - msg_debug ("get_upstream_by_hash: max tries exceed, returning NULL"); return NULL; } } @@ -403,7 +395,6 @@ get_upstream_round_robin (void *ups, size_t members, size_t msize, time_t now, t } U_UNLOCK (); } - msg_debug ("get_upstream_round_robin: selecting upstream with weight %d", max_weight); return selected; } @@ -436,7 +427,6 @@ get_upstream_master_slave (void *ups, size_t members, size_t msize, time_t now, p += msize; } U_UNLOCK (); - msg_debug ("get_upstream_master_slave: selecting upstream with priority %d", max_weight); return selected; } diff --git a/src/url.c b/src/url.c index ff112ce6e..e560128f3 100644 --- a/src/url.c +++ b/src/url.c @@ -215,13 +215,13 @@ url_init (void) if (url_initialized == 0) { text_re = g_regex_new (text_url, G_REGEX_CASELESS | G_REGEX_MULTILINE | G_REGEX_OPTIMIZE | G_REGEX_EXTENDED, 0, &err); if (err != NULL) { - msg_info ("url_init: cannot init text url parsing regexp: %s", err->message); + msg_info ("cannot init text url parsing regexp: %s", err->message); g_error_free (err); return -1; } html_re = g_regex_new (html_url, G_REGEX_CASELESS | G_REGEX_MULTILINE | G_REGEX_OPTIMIZE | G_REGEX_EXTENDED, 0, &err); if (err != NULL) { - msg_info ("url_init: cannot init html url parsing regexp: %s", err->message); + msg_info ("cannot init html url parsing regexp: %s", err->message); g_error_free (err); return -1; } @@ -665,7 +665,7 @@ parse_uri (struct uri *uri, unsigned char *uristring, memory_pool_t * pool) return URI_ERRNO_EMPTY; uri->string = reencode_escapes (uristring, pool); - msg_debug ("parse_uri: reencoding escapes in original url: '%s'", struri (uri)); + msg_debug ("reencoding escapes in original url: '%s'", struri (uri)); uri->protocollen = get_protocol_length (struri (uri)); /* Assume http as default protocol */ @@ -678,7 +678,7 @@ parse_uri (struct uri *uri, unsigned char *uristring, memory_pool_t * pool) } else { /* Figure out whether the protocol is known */ - msg_debug ("parse_uri: getting protocol from url: %d", uri->protocol); + msg_debug ("getting protocol from url: %d", uri->protocol); prefix_end = struri (uri) + uri->protocollen; /* ':' */ @@ -689,7 +689,7 @@ parse_uri (struct uri *uri, unsigned char *uristring, memory_pool_t * pool) prefix_end++; } if (*prefix_end != ':') { - msg_debug ("parse_uri: invalid protocol in uri"); + msg_debug ("invalid protocol in uri"); return URI_ERRNO_INVALID_PROTOCOL; } prefix_end++; @@ -698,7 +698,7 @@ parse_uri (struct uri *uri, unsigned char *uristring, memory_pool_t * pool) if (prefix_end[0] == '/' && prefix_end[1] == '/') { if (prefix_end[2] == '/') { - msg_debug ("parse_uri: too many '/' in uri"); + msg_debug ("too many '/' in uri"); return URI_ERRNO_TOO_MANY_SLASHES; } @@ -706,7 +706,7 @@ parse_uri (struct uri *uri, unsigned char *uristring, memory_pool_t * pool) } else { - msg_debug ("parse_uri: no '/' in uri"); + msg_debug ("no '/' in uri"); return URI_ERRNO_NO_SLASHES; } } @@ -890,7 +890,7 @@ url_parse_text (memory_pool_t * pool, struct worker_task *task, struct mime_text struct uri *new; if (!part->orig->data || part->orig->len == 0) { - msg_warn ("url_parse_text: got empty text part"); + msg_warn ("got empty text part"); return; } @@ -905,7 +905,7 @@ url_parse_text (memory_pool_t * pool, struct worker_task *task, struct mime_text if (rc) { while (g_match_info_matches (info)) { url_str = g_match_info_fetch (info, is_html ? 1 : 0); - msg_debug ("url_parse_text: extracted string with regexp: '%s', html is %s", url_str, is_html ? "on" : "off"); + debug_task ("extracted string with regexp: '%s', html is %s", url_str, is_html ? "on" : "off"); if (url_str != NULL) { if (g_tree_lookup (is_html ? part->html_urls : part->urls, url_str) == NULL) { new = memory_pool_alloc (pool, sizeof (struct uri)); @@ -927,11 +927,11 @@ url_parse_text (memory_pool_t * pool, struct worker_task *task, struct mime_text } } else if (err != NULL) { - msg_debug ("url_parse_text: error matching regexp: %s", err->message); + debug_task ("error matching regexp: %s", err->message); g_free (err); } else { - msg_debug ("url_parse_text: cannot find url pattern in given string"); + debug_task ("cannot find url pattern in given string"); } g_match_info_free (info); } diff --git a/src/util.c b/src/util.c index 5c16fa917..b43da4322 100644 --- a/src/util.c +++ b/src/util.c @@ -37,22 +37,9 @@ #define CONNECT_TIMEOUT 3 #ifdef RSPAMD_MAIN -sig_atomic_t do_reopen_log = 0; extern rspamd_hash_t *counters; #endif -struct logger_params { - GLogFunc log_func; - struct config_file *cfg; -}; - -static struct logger_params log_params; - -/* Here would be put log messages intensity */ -static uint32_t log_written; -static time_t last_check; -static char *io_buf = NULL; -static gboolean log_buffered = FALSE; static u_char* rspamd_sprintf_num (u_char *buf, u_char *last, uint64_t ui64, u_char zero, unsigned int hexadecimal, unsigned int width); int @@ -63,7 +50,7 @@ make_socket_nonblocking (int fd) ofl = fcntl (fd, F_GETFL, 0); if (fcntl (fd, F_SETFL, ofl | O_NONBLOCK) == -1) { - msg_warn ("make_socket_nonblocking: fcntl failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("fcntl failed: %d, '%s'", errno, strerror (errno)); return -1; } return 0; @@ -77,7 +64,7 @@ make_socket_blocking (int fd) ofl = fcntl (fd, F_GETFL, 0); if (fcntl (fd, F_SETFL, ofl & (~O_NONBLOCK)) == -1) { - msg_warn ("make_socket_nonblocking: fcntl failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("fcntl failed: %d, '%s'", errno, strerror (errno)); return -1; } return 0; @@ -111,7 +98,7 @@ make_inet_socket (int family, struct in_addr *addr, u_short port, gboolean is_se /* Create socket */ fd = socket (AF_INET, family, 0); if (fd == -1) { - msg_warn ("make_tcp_socket: socket failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("socket failed: %d, '%s'", errno, strerror (errno)); return -1; } @@ -121,7 +108,7 @@ make_inet_socket (int family, struct in_addr *addr, u_short port, gboolean is_se /* Set close on exec */ if (fcntl (fd, F_SETFD, FD_CLOEXEC) == -1) { - msg_warn ("make_tcp_socket: fcntl failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("fcntl failed: %d, '%s'", errno, strerror (errno)); goto out; } @@ -140,14 +127,14 @@ make_inet_socket (int family, struct in_addr *addr, u_short port, gboolean is_se if (r == -1) { if (errno != EINPROGRESS) { - msg_warn ("make_tcp_socket: bind/connect failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("bind/connect failed: %d, '%s'", errno, strerror (errno)); goto out; } if (!async) { /* Try to poll */ if (poll_sync_socket (fd, CONNECT_TIMEOUT * 1000, POLLOUT) <= 0) { errno = ETIMEDOUT; - msg_warn ("make_tcp_socket: bind/connect failed: timeout"); + msg_warn ("bind/connect failed: timeout"); goto out; } else { @@ -200,7 +187,7 @@ accept_from_socket (int listen_sock, struct sockaddr *addr, socklen_t * len) if (errno == EAGAIN) { return 0; } - msg_warn ("accept_from_socket: accept failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("accept failed: %d, '%s'", errno, strerror (errno)); return -1; } if (make_socket_nonblocking (nfd) < 0) { @@ -209,7 +196,7 @@ accept_from_socket (int listen_sock, struct sockaddr *addr, socklen_t * len) /* Set close on exec */ if (fcntl (nfd, F_SETFD, FD_CLOEXEC) == -1) { - msg_warn ("accept_from_socket: fcntl failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("fcntl failed: %d, '%s'", errno, strerror (errno)); goto out; } @@ -245,7 +232,7 @@ make_unix_socket (const char *path, struct sockaddr_un *addr, gboolean is_server fd = socket (PF_LOCAL, SOCK_STREAM, 0); if (fd == -1) { - msg_warn ("make_unix_socket: socket failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("socket failed: %d, '%s'", errno, strerror (errno)); return -1; } @@ -255,7 +242,7 @@ make_unix_socket (const char *path, struct sockaddr_un *addr, gboolean is_server /* Set close on exec */ if (fcntl (fd, F_SETFD, FD_CLOEXEC) == -1) { - msg_warn ("make_unix_socket: fcntl failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("fcntl failed: %d, '%s'", errno, strerror (errno)); goto out; } if (is_server) { @@ -268,7 +255,7 @@ make_unix_socket (const char *path, struct sockaddr_un *addr, gboolean is_server if (r == -1) { if (errno != EINPROGRESS) { - msg_warn ("make_unix_socket: bind/connect failed: %d, '%s'", errno, strerror (errno)); + msg_warn ("bind/connect failed: %d, '%s'", errno, strerror (errno)); goto out; } } @@ -713,162 +700,6 @@ pidfile_remove (struct pidfh *pfh) } #endif - -/* Logging utility functions */ -int -open_log (struct config_file *cfg) -{ - switch (cfg->log_type) { - case RSPAMD_LOG_CONSOLE: - /* Do nothing with console */ - return 0; - case RSPAMD_LOG_SYSLOG: - openlog ("rspamd", LOG_NDELAY | LOG_PID, cfg->log_facility); - return 0; - case RSPAMD_LOG_FILE: - cfg->log_fd = open (cfg->log_file, O_CREAT | O_WRONLY | O_APPEND, S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH); - if (cfg->log_fd == -1) { - fprintf (stderr, "open_log: cannot open desired log file: %s, %s", cfg->log_file, strerror (errno)); - return -1; - } - cfg->logf = fdopen (cfg->log_fd, "w"); - /* Set line buffering */ - setvbuf (cfg->logf, (char *)NULL, _IOLBF, 0); - return 0; - } - return -1; -} - -void -close_log (struct config_file *cfg) -{ - switch (cfg->log_type) { - case RSPAMD_LOG_CONSOLE: - /* Do nothing with console */ - break; - case RSPAMD_LOG_SYSLOG: - closelog (); - break; - case RSPAMD_LOG_FILE: - if (cfg->logf != NULL) { - if (fsync (cfg->log_fd) == -1) { - msg_err ("close_log: error syncing log file: %s", strerror (errno)); - } - fclose (cfg->logf); - } - break; - } - -} - -void -rspamd_set_logger (GLogFunc func, struct config_file *cfg) -{ - log_params.log_func = func; - log_params.cfg = cfg; -} - -int -reopen_log (struct config_file *cfg) -{ -#ifdef RSPAMD_MAIN - do_reopen_log = 0; -#endif - close_log (cfg); - return open_log (cfg); -} - -void -rspamd_log_function (GLogLevelFlags log_level, const char *fmt, ...) -{ - static char logbuf[BUFSIZ]; - va_list vp; - u_char *end; - - if (log_level <= log_params.cfg->log_level) { - va_start (vp, fmt); - end = rspamd_vsnprintf (logbuf, sizeof (logbuf), fmt, vp); - *end = '\0'; - va_end (vp); - log_params.log_func (NULL, log_level, logbuf, log_params.cfg); - } -} - -void -syslog_log_function (const gchar * log_domain, GLogLevelFlags log_level, const gchar * message, gpointer arg) -{ - struct config_file *cfg = (struct config_file *)arg; -#ifdef RSPAMD_MAIN - if (do_reopen_log) { - reopen_log (cfg); - } -#endif - - if (log_level <= cfg->log_level) { - if (log_level >= G_LOG_LEVEL_DEBUG) { - syslog (LOG_DEBUG, "%s", message); - } - else if (log_level >= G_LOG_LEVEL_INFO) { - syslog (LOG_INFO, "%s", message); - } - else if (log_level >= G_LOG_LEVEL_WARNING) { - syslog (LOG_WARNING, "%s", message); - } - else if (log_level >= G_LOG_LEVEL_CRITICAL) { - syslog (LOG_ERR, "%s", message); - } - } -} - -void -file_log_function (const gchar * log_domain, GLogLevelFlags log_level, const gchar * message, gpointer arg) -{ - struct config_file *cfg = (struct config_file *)arg; - char tmpbuf[128], timebuf[32]; - time_t now; - struct tm *tms; - - if (cfg->log_fd == -1 || cfg->logf == NULL) { - return; - } -#ifdef RSPAMD_MAIN - if (do_reopen_log) { - reopen_log (cfg); - } -#endif - - if (log_level <= cfg->log_level) { - now = time (NULL); - tms = localtime (&now); - - if (last_check == 0) { - last_check = now; - } - else if (now - last_check > CHECK_TIME) { - if (log_written / (now - last_check) > BUF_INTENSITY && !log_buffered) { - /* Switch to buffered logging */ - if (io_buf == NULL) { - io_buf = g_malloc (BUFSIZ); - } - setvbuf (cfg->logf, io_buf, _IOFBF, BUFSIZ); - log_buffered = TRUE; - } - else if (log_buffered) { - /* Switch to line buffering */ - setvbuf (cfg->logf, NULL, _IOLBF, 0); - log_buffered = FALSE; - } - last_check = now; - log_written = 0; - } - - strftime (timebuf, sizeof (timebuf), "%b %d %H:%M:%S", tms); - rspamd_snprintf (tmpbuf, sizeof (tmpbuf), "#%P: %s rspamd %Z", getpid (), timebuf); - fprintf (cfg->logf, "%s%s" CRLF, tmpbuf, message); - log_written++; - } -} - /* Replace %r with rcpt value and %f with from value, new string is allocated in pool */ char * resolve_stat_filename (memory_pool_t * pool, char *pattern, char *rcpt, char *from) @@ -1048,7 +879,7 @@ gperf_profiler_init (struct config_file *cfg, const char *descr) ProfilerRegisterThread (); } else { - msg_warn ("gperf_frofiler_init: cannot start google perftools profiler"); + msg_warn ("cannot start google perftools profiler"); } #endif @@ -1072,7 +903,7 @@ lock_file (int fd, gboolean async) if (async && errno == EAGAIN) { return FALSE; } - msg_warn ("lock_file: lock on file failed: %s", strerror (errno)); + msg_warn ("lock on file failed: %s", strerror (errno)); return FALSE; } @@ -1095,7 +926,7 @@ unlock_file (int fd, gboolean async) if (async && errno == EAGAIN) { return FALSE; } - msg_warn ("lock_file: lock on file failed: %s", strerror (errno)); + msg_warn ("lock on file failed: %s", strerror (errno)); return FALSE; } @@ -1118,7 +949,7 @@ lock_file (int fd, gboolean async) if (async && (errno == EAGAIN || errno == EACCES)) { return FALSE; } - msg_warn ("lock_file: lock on file failed: %s", strerror (errno)); + msg_warn ("lock on file failed: %s", strerror (errno)); return FALSE; } @@ -1139,7 +970,7 @@ unlock_file (int fd, gboolean async) if (async && (errno == EAGAIN || errno == EACCES)) { return FALSE; } - msg_warn ("lock_file: lock on file failed: %s", strerror (errno)); + msg_warn ("lock on file failed: %s", strerror (errno)); return FALSE; } @@ -1157,7 +988,7 @@ get_statfile_by_symbol (statfile_pool_t *pool, struct classifier_config *ccf, GList *cur; if (pool == NULL || ccf == NULL || symbol == NULL) { - msg_err ("get_statfile_by_symbol: invalid input arguments"); + msg_err ("invalid input arguments"); return NULL; } @@ -1171,21 +1002,21 @@ get_statfile_by_symbol (statfile_pool_t *pool, struct classifier_config *ccf, cur = g_list_next (cur); } if (*st == NULL) { - msg_info ("get_statfile_by_symbol: cannot find statfile with symbol %s", symbol); + msg_info ("cannot find statfile with symbol %s", symbol); return NULL; } if ((res = statfile_pool_is_open (pool, (*st)->path)) == NULL) { if ((res = statfile_pool_open (pool, (*st)->path, (*st)->size, FALSE)) == NULL) { - msg_warn ("get_statfile_by_symbol: cannot open %s", (*st)->path); + msg_warn ("cannot open %s", (*st)->path); if (try_create) { if (statfile_pool_create (pool, (*st)->path, (*st)->size) == -1) { - msg_err ("get_statfile_by_symbol: cannot create statfile %s", (*st)->path); + msg_err ("cannot create statfile %s", (*st)->path); return NULL; } res = statfile_pool_open (pool, (*st)->path, (*st)->size, FALSE); if (res == NULL) { - msg_err ("get_statfile_by_symbol: cannot open statfile %s after creation", (*st)->path); + msg_err ("cannot open statfile %s after creation", (*st)->path); } } } diff --git a/src/util.h b/src/util.h index 6c14d7469..844fbe6c5 100644 --- a/src/util.h +++ b/src/util.h @@ -62,14 +62,6 @@ int pidfile_close(struct pidfh *pfh); int pidfile_remove(struct pidfh *pfh); #endif -void rspamd_set_logger (GLogFunc func, struct config_file *cfg); -int open_log (struct config_file *cfg); -void close_log (struct config_file *cfg); -int reopen_log (struct config_file *cfg); -void rspamd_log_function (GLogLevelFlags log_level, const char *fmt, ...); -void syslog_log_function (const gchar *log_domain, GLogLevelFlags log_level, const gchar *message, gpointer arg); -void file_log_function (const gchar *log_domain, GLogLevelFlags log_level, const gchar *message, gpointer arg); - /* Replace %r with rcpt value and %f with from value, new string is allocated in pool */ char* resolve_stat_filename (memory_pool_t *pool, char *pattern, char *rcpt, char *from); const char* calculate_check_time (struct timespec *begin, int resolution); diff --git a/src/worker.c b/src/worker.c index 21fcc9041..2de848cf0 100644 --- a/src/worker.c +++ b/src/worker.c @@ -67,6 +67,7 @@ sig_handler (int signo, siginfo_t *info, void *unused) switch (signo) { case SIGINT: case SIGTERM: + close_log (); #ifdef WITH_GPERF_TOOLS ProfilerStop (); #endif @@ -121,7 +122,7 @@ free_task (struct worker_task *task, gboolean is_soft) struct mime_part *p; if (task) { - msg_debug ("free_task: free pointer %p", task); + debug_task ("free pointer %p", task); if (task->memc_ctx) { memc_close_ctx (task->memc_ctx); } @@ -187,10 +188,10 @@ read_socket (f_str_t * in, void *arg) task->msg = memory_pool_alloc (task->task_pool, sizeof (f_str_t)); task->msg->begin = in->begin; task->msg->len = in->len; - msg_debug ("read_socket: got string of length %ld", (long int)task->msg->len); + debug_task ("got string of length %ld", (long int)task->msg->len); r = process_message (task); if (r == -1) { - msg_warn ("read_socket: processing of message failed"); + msg_warn ("processing of message failed"); task->last_error = "MIME processing error"; task->error_code = RSPAMD_FILTER_ERROR; task->state = WRITE_ERROR; @@ -218,7 +219,7 @@ read_socket (f_str_t * in, void *arg) } break; default: - msg_debug ("read_socket: invalid state on reading stage"); + debug_task ("invalid state on reading stage"); break; } @@ -245,12 +246,12 @@ write_socket (void *arg) return FALSE; break; case CLOSING_CONNECTION: - msg_debug ("write_socket: normally closing connection"); + debug_task ("normally closing connection"); destroy_session (task->s); return FALSE; break; default: - msg_info ("write_socket: abnormally closing connection"); + msg_info ("abnormally closing connection"); destroy_session (task->s); return FALSE; break; @@ -265,7 +266,7 @@ static void err_socket (GError * err, void *arg) { struct worker_task *task = (struct worker_task *)arg; - msg_info ("err_socket: abnormally closing connection, error: %s", err->message); + msg_info ("abnormally closing connection, error: %s", err->message); /* Free buffers */ destroy_session (task->s); } @@ -277,7 +278,6 @@ construct_task (struct rspamd_worker *worker) new_task = g_malloc (sizeof (struct worker_task)); - msg_debug ("accept_socket: new task allocated: %p", new_task); bzero (new_task, sizeof (struct worker_task)); new_task->worker = worker; new_task->state = READ_COMMAND; @@ -321,12 +321,11 @@ accept_socket (int fd, short what, void *arg) int nfd; if ((nfd = accept_from_socket (fd, (struct sockaddr *)&ss, &addrlen)) == -1) { - msg_warn ("accept_socket: accept failed: %s", strerror (errno)); + msg_warn ("accept failed: %s", strerror (errno)); return; } /* Check for EAGAIN */ if (nfd == 0) { - msg_debug ("accept_socket: cannot accept socket as it was already accepted by other worker"); return; } @@ -334,12 +333,12 @@ accept_socket (int fd, short what, void *arg) new_task = construct_task (worker); if (ss.ss_family == AF_UNIX) { - msg_info ("accept_socket: accepted connection from unix socket"); + msg_info ("accepted connection from unix socket"); new_task->client_addr.s_addr = INADDR_NONE; } else if (ss.ss_family == AF_INET) { sin = (struct sockaddr_in *)&ss; - msg_info ("accept_socket: accepted connection from %s port %d", inet_ntoa (sin->sin_addr), ntohs (sin->sin_port)); + msg_info ("accepted connection from %s port %d", inet_ntoa (sin->sin_addr), ntohs (sin->sin_port)); memcpy (&new_task->client_addr, &sin->sin_addr, sizeof (struct in_addr)); } @@ -349,6 +348,7 @@ accept_socket (int fd, short what, void *arg) /* Set up dispatcher */ new_task->dispatcher = rspamd_create_dispatcher (nfd, BUFFER_LINE, read_socket, write_socket, err_socket, &io_tv, (void *)new_task); + new_task->dispatcher->peer_addr = new_task->client_addr.s_addr; } @@ -396,6 +396,8 @@ start_worker (struct rspamd_worker *worker) } event_loop (0); + + close_log (); exit (EXIT_SUCCESS); } diff --git a/utils/url_extracter.c b/utils/url_extracter.c index 97bf72c47..6130c51ef 100644 --- a/utils/url_extracter.c +++ b/utils/url_extracter.c @@ -56,9 +56,6 @@ main (int argc, char **argv) } task.cfg = memory_pool_alloc0 (task.task_pool, sizeof (struct config_file)); - task.cfg->log_level = G_LOG_LEVEL_CRITICAL; - task.cfg->log_fd = STDERR_FILENO; - g_log_set_default_handler (file_log_function, task.cfg); task.msg = memory_pool_alloc (task.task_pool, sizeof (f_str_t)); task.msg->begin = buf; -- 2.39.5