[Minor] Core: Improve debugging in archive detection code

diff --git a/src/libmime/archives.c b/src/libmime/archives.c
index 8497fdf70791606e737e8affe6d1a061d95fdc45..8395d986b5520811d2982fdf2d4ae55a4eafa792 100644 (file)
--- a/src/libmime/archives.c
+++ b/src/libmime/archives.c
@@ -24,6 +24,12 @@
 #include <unicode/utf16.h>
 #include <unicode/ucnv.h>
 
+#define msg_debug_archive(...)  rspamd_conditional_debug_fast (NULL, NULL, \
+        rspamd_archive_log_id, "archive", task->task_pool->tag.uid, \
+        G_STRFUNC, \
+        __VA_ARGS__)
+
+INIT_LOG_MODULE(archive)
 
 static void
 rspamd_archive_dtor (gpointer p)
@@ -46,7 +52,8 @@ rspamd_archive_dtor (gpointer p)
 }
 
 static GString *
-rspamd_archive_file_try_utf (const gchar *in, gsize inlen)
+rspamd_archive_file_try_utf (struct rspamd_task *task,
+               const gchar *in, gsize inlen)
 {
        const gchar *charset = NULL, *p, *end;
        GString *res;
@@ -64,7 +71,7 @@ rspamd_archive_file_try_utf (const gchar *in, gsize inlen)
                utf8_converter = rspamd_get_utf8_converter ();
 
                if (conv == NULL) {
-                       msg_err ("cannot open converter for %s: %s",
+                       msg_err_task ("cannot open converter for %s: %s",
                                        charset, u_errorName (uc_err));
 
                        return NULL;
@@ -74,7 +81,7 @@ rspamd_archive_file_try_utf (const gchar *in, gsize inlen)
                r = rspamd_converter_to_uchars (conv, tmp, inlen + 1,
                                in, inlen, &uc_err);
                if (!U_SUCCESS (uc_err)) {
-                       msg_err ("cannot convert data to unicode from %s: %s",
+                       msg_err_task ("cannot convert data to unicode from %s: %s",
                                        charset, u_errorName (uc_err));
                        g_free (tmp);
 
@@ -87,7 +94,7 @@ rspamd_archive_file_try_utf (const gchar *in, gsize inlen)
                r = ucnv_fromUChars (utf8_converter, res->str, dlen, tmp, r, &uc_err);
 
                if (!U_SUCCESS (uc_err)) {
-                       msg_err ("cannot convert data from unicode from %s: %s",
+                       msg_err_task ("cannot convert data from unicode from %s: %s",
                                        charset, u_errorName (uc_err));
                        g_free (tmp);
                        g_string_free (res, TRUE);
@@ -95,7 +102,11 @@ rspamd_archive_file_try_utf (const gchar *in, gsize inlen)
                        return NULL;
                }
 
+               g_free (tmp);
                res->len = r;
+
+               msg_debug_archive ("converted from %s to UTF-8 inlen: %z, outlen: %d",
+                               charset, inlen, r);
        }
        else {
                /* Convert unsafe characters to '?' */
@@ -164,13 +175,13 @@ rspamd_archive_process_zip (struct rspamd_task *task,
 
        if (eocd == NULL) {
                /* Not a zip file */
-               msg_debug_task ("zip archive is invalid (no EOCD)");
+               msg_debug_archive ("zip archive is invalid (no EOCD)");
 
                return;
        }
 
        if (end - eocd < 21) {
-               msg_debug_task ("zip archive is invalid (short EOCD)");
+               msg_debug_archive ("zip archive is invalid (short EOCD)");
 
                return;
        }
@@ -183,7 +194,7 @@ rspamd_archive_process_zip (struct rspamd_task *task,
 
        /* We need to check sanity as well */
        if (cd_offset + cd_size != (guint)(eocd - start)) {
-               msg_debug_task ("zip archive is invalid (bad size/offset for CD)");
+               msg_debug_archive ("zip archive is invalid (bad size/offset for CD)");
 
                return;
        }
@@ -200,7 +211,7 @@ rspamd_archive_process_zip (struct rspamd_task *task,
                /* Read central directory record */
                if (eocd - cd < cd_basic_len ||
                                memcmp (cd, cd_magic, sizeof (cd_magic)) != 0) {
-                       msg_debug_task ("zip archive is invalid (bad cd record)");
+                       msg_debug_archive ("zip archive is invalid (bad cd record)");
 
                        return;
                }
@@ -217,19 +228,20 @@ rspamd_archive_process_zip (struct rspamd_task *task,
                comment_len = GUINT16_FROM_LE (comment_len);
 
                if (cd + fname_len + comment_len + extra_len + cd_basic_len > eocd) {
-                       msg_debug_task ("zip archive is invalid (too large cd record)");
+                       msg_debug_archive ("zip archive is invalid (too large cd record)");
 
                        return;
                }
 
                f = g_malloc0 (sizeof (*f));
-               f->fname = rspamd_archive_file_try_utf (cd + cd_basic_len, fname_len);
+               f->fname = rspamd_archive_file_try_utf (task,
+                               cd + cd_basic_len, fname_len);
                f->compressed_size = comp_size;
                f->uncompressed_size = uncomp_size;
 
                if (f->fname) {
                        g_ptr_array_add (arch->files, f);
-                       msg_debug_task ("found file in zip archive: %v", f->fname);
+                       msg_debug_archive ("found file in zip archive: %v", f->fname);
                }
                else {
                        g_free (f);
@@ -290,11 +302,11 @@ rspamd_archive_rar_read_vint (const guchar *start, gsize remain, guint64 *res)
 
 #define RAR_SKIP_BYTES(n) do { \
        if ((n) <= 0) { \
-               msg_debug_task ("rar archive is invalid (bad skip value)"); \
+               msg_debug_archive ("rar archive is invalid (bad skip value)"); \
                return; \
        } \
        if ((gsize)(end - p) < (n)) { \
-               msg_debug_task ("rar archive is invalid (truncated)"); \
+               msg_debug_archive ("rar archive is invalid (truncated)"); \
                return; \
        } \
        p += (n); \
@@ -303,11 +315,11 @@ rspamd_archive_rar_read_vint (const guchar *start, gsize remain, guint64 *res)
 #define RAR_READ_VINT() do { \
        r = rspamd_archive_rar_read_vint (p, end - p, &vint); \
        if (r == -1) { \
-               msg_debug_task ("rar archive is invalid (bad vint)"); \
+               msg_debug_archive ("rar archive is invalid (bad vint)"); \
                return; \
        } \
        else if (r == 0) { \
-               msg_debug_task ("rar archive is invalid (BAD vint offset)"); \
+               msg_debug_archive ("rar archive is invalid (BAD vint offset)"); \
                return; \
        }\
 } while (0)
@@ -315,7 +327,7 @@ rspamd_archive_rar_read_vint (const guchar *start, gsize remain, guint64 *res)
 #define RAR_READ_VINT_SKIP() do { \
        r = rspamd_archive_rar_read_vint (p, end - p, &vint); \
        if (r == -1) { \
-               msg_debug_task ("rar archive is invalid (bad vint)"); \
+               msg_debug_archive ("rar archive is invalid (bad vint)"); \
                return; \
        } \
        p += r; \
@@ -323,7 +335,7 @@ rspamd_archive_rar_read_vint (const guchar *start, gsize remain, guint64 *res)
 
 #define RAR_READ_UINT16(n) do { \
        if (end - p < (glong)sizeof (guint16)) { \
-               msg_debug_task ("rar archive is invalid (bad int16)"); \
+               msg_debug_archive ("rar archive is invalid (bad int16)"); \
                return; \
        } \
        n = p[0] + (p[1] << 8); \
@@ -332,7 +344,7 @@ rspamd_archive_rar_read_vint (const guchar *start, gsize remain, guint64 *res)
 
 #define RAR_READ_UINT32(n) do { \
        if (end - p < (glong)sizeof (guint32)) { \
-               msg_debug_task ("rar archive is invalid (bad int32)"); \
+               msg_debug_archive ("rar archive is invalid (bad int32)"); \
                return; \
        } \
        n = (guint)p[0] + ((guint)p[1] << 8) + ((guint)p[2] << 16) + ((guint)p[3] << 24); \
@@ -386,7 +398,7 @@ rspamd_archive_process_rar_v4 (struct rspamd_task *task, const guchar *start,
 
                if (sz == 0) {
                        /* Zero sized block - error */
-                       msg_debug_task ("rar archive is invalid (zero size block)");
+                       msg_debug_archive ("rar archive is invalid (zero size block)");
 
                        return;
                }
@@ -402,7 +414,8 @@ rspamd_archive_process_rar_v4 (struct rspamd_task *task, const guchar *start,
                        RAR_READ_UINT16 (fname_len);
 
                        if (fname_len == 0 || fname_len > (gsize)(end - p)) {
-                               msg_debug_task ("rar archive is invalid (bad fileame size)");
+                               msg_debug_archive ("rar archive is invalid (bad filename size: %d)",
+                                               fname_len);
 
                                return;
                        }
@@ -432,15 +445,21 @@ rspamd_archive_process_rar_v4 (struct rspamd_task *task, const guchar *start,
 
                                if (tmp != NULL) {
                                        /* Just use ASCII version */
-                                       f->fname = g_string_new_len (p, tmp - p);
+                                       f->fname = rspamd_archive_file_try_utf (task, p, tmp - p);
+                                       msg_debug_archive ("found ascii filename in rarv4 archive: %v",
+                                                       f->fname);
                                }
                                else {
                                        /* We have UTF8 filename, use it as is */
-                                       f->fname = g_string_new_len (p, fname_len);
+                                       f->fname = rspamd_archive_file_try_utf (task, p, fname_len);
+                                       msg_debug_archive ("found utf filename in rarv4 archive: %v",
+                                                       f->fname);
                                }
                        }
                        else {
-                               f->fname = g_string_new_len (p, fname_len);
+                               f->fname = rspamd_archive_file_try_utf (task, p, fname_len);
+                               msg_debug_archive ("found ascii (old) filename in rarv4 archive: %v",
+                                               f->fname);
                        }
 
                        f->compressed_size = comp_sz;
@@ -450,7 +469,12 @@ rspamd_archive_process_rar_v4 (struct rspamd_task *task, const guchar *start,
                                f->flags |= RSPAMD_ARCHIVE_FILE_ENCRYPTED;
                        }
 
-                       g_ptr_array_add (arch->files, f);
+                       if (f->fname) {
+                               g_ptr_array_add (arch->files, f);
+                       }
+                       else {
+                               g_free (f);
+                       }
                }
 
                p = start_section;
@@ -482,7 +506,7 @@ rspamd_archive_process_rar (struct rspamd_task *task,
        end = p + part->parsed_data.len;
 
        if ((gsize)(end - p) <= sizeof (rar_v5_magic)) {
-               msg_debug_task ("rar archive is invalid (too small)");
+               msg_debug_archive ("rar archive is invalid (too small)");
 
                return;
        }
@@ -497,7 +521,7 @@ rspamd_archive_process_rar (struct rspamd_task *task,
                return;
        }
        else {
-               msg_debug_task ("rar archive is invalid (no rar magic)");
+               msg_debug_archive ("rar archive is invalid (no rar magic)");
 
                return;
        }
@@ -539,7 +563,7 @@ rspamd_archive_process_rar (struct rspamd_task *task,
                goto end;
        }
        else if (type != rar_main_header) {
-               msg_debug_task ("rar archive is invalid (bad main header)");
+               msg_debug_archive ("rar archive is invalid (bad main header)");
 
                return;
        }
@@ -558,7 +582,7 @@ rspamd_archive_process_rar (struct rspamd_task *task,
                sz = vint;
                if (sz == 0) {
                        /* Zero sized block - error */
-                       msg_debug_task ("rar archive is invalid (zero size block)");
+                       msg_debug_archive ("rar archive is invalid (zero size block)");
 
                        return;
                }
@@ -618,7 +642,7 @@ rspamd_archive_process_rar (struct rspamd_task *task,
                        fname_len = vint;
 
                        if (fname_len == 0 || fname_len > (gsize)(end - p)) {
-                               msg_debug_task ("rar archive is invalid (bad fileame size)");
+                               msg_debug_archive ("rar archive is invalid (bad filename size)");
 
                                return;
                        }
@@ -626,8 +650,15 @@ rspamd_archive_process_rar (struct rspamd_task *task,
                        f = g_malloc0 (sizeof (*f));
                        f->uncompressed_size = uncomp_sz;
                        f->compressed_size = comp_sz;
-                       f->fname = g_string_new_len (p, fname_len);
-                       g_ptr_array_add (arch->files, f);
+                       f->fname = rspamd_archive_file_try_utf (task, p, fname_len);
+
+                       if (f->fname) {
+                               msg_debug_archive ("added rarv5 file: %v", f->fname);
+                               g_ptr_array_add (arch->files, f);
+                       }
+                       else {
+                               g_free (f);
+                       }
 
                        /* Restore p to the beginning of the header */
                        p = section_start;
@@ -714,7 +745,7 @@ rspamd_archive_7zip_read_vint (const guchar *start, gsize remain, guint64 *res)
 #define SZ_READ_VINT_SKIP() do { \
        r = rspamd_archive_7zip_read_vint (p, end - p, &vint); \
        if (r == -1) { \
-               msg_debug_task ("7z archive is invalid (bad vint)"); \
+               msg_debug_archive ("7z archive is invalid (bad vint)"); \
                return; \
        } \
        p += r; \
@@ -723,7 +754,7 @@ rspamd_archive_7zip_read_vint (const guchar *start, gsize remain, guint64 *res)
        int r; \
        r = rspamd_archive_7zip_read_vint (p, end - p, &(var)); \
        if (r == -1) { \
-               msg_debug_task ("7z archive is invalid (bad vint): %s", G_STRLOC); \
+               msg_debug_archive ("7z archive is invalid (bad vint): %s", G_STRLOC); \
                return NULL; \
        } \
        p += r; \
@@ -731,7 +762,7 @@ rspamd_archive_7zip_read_vint (const guchar *start, gsize remain, guint64 *res)
 
 #define SZ_READ_UINT64(n) do { \
        if (end - p < (goffset)sizeof (guint64)) { \
-               msg_debug_task ("7zip archive is invalid (bad vint): %s", G_STRLOC); \
+               msg_debug_archive ("7zip archive is invalid (bad vint): %s", G_STRLOC); \
                return; \
        } \
        memcpy (&(n), p, sizeof (guint64)); \
@@ -743,7 +774,7 @@ rspamd_archive_7zip_read_vint (const guchar *start, gsize remain, guint64 *res)
                p += (n); \
        } \
        else { \
-               msg_debug_task ("7zip archive is invalid (truncated); wanted to read %d bytes, %d avail: %s", (gint)(n), (gint)(end - p), G_STRLOC); \
+               msg_debug_archive ("7zip archive is invalid (truncated); wanted to read %d bytes, %d avail: %s", (gint)(n), (gint)(end - p), G_STRLOC); \
                return NULL; \
        } \
 } while (0)
@@ -901,7 +932,7 @@ rspamd_7zip_read_pack_info (struct rspamd_task *task,
                        break;
                default:
                        p = NULL;
-                       msg_debug_task ("bad 7zip type: %c; %s", t, G_STRLOC);
+                       msg_debug_archive ("bad 7zip type: %c; %s", t, G_STRLOC);
                        goto end;
                        break;
                }
@@ -1094,7 +1125,7 @@ rspamd_7zip_read_coders_info (struct rspamd_task *task,
                        break;
                default:
                        p = NULL;
-                       msg_debug_task ("bad 7zip type: %c; %s", t, G_STRLOC);
+                       msg_debug_archive ("bad 7zip type: %c; %s", t, G_STRLOC);
                        goto end;
                        break;
                }
@@ -1186,7 +1217,7 @@ rspamd_7zip_read_substreams_info (struct rspamd_task *task,
                        break;
                default:
                        p = NULL;
-                       msg_debug_task ("bad 7zip type: %c; %s", t, G_STRLOC);
+                       msg_debug_archive ("bad 7zip type: %c; %s", t, G_STRLOC);
                        goto end;
                        break;
                }
@@ -1242,7 +1273,7 @@ rspamd_7zip_read_main_streams_info (struct rspamd_task *task,
                        break;
                default:
                        p = NULL;
-                       msg_debug_task ("bad 7zip type: %c; %s", t, G_STRLOC);
+                       msg_debug_archive ("bad 7zip type: %c; %s", t, G_STRLOC);
                        goto end;
                        break;
                }
@@ -1398,7 +1429,7 @@ rspamd_7zip_read_files_info (struct rspamd_task *task,
 
                                        if (fend == NULL || fend - p == 0) {
                                                /* Crap instead of fname */
-                                               msg_debug_task ("bad 7zip name; %s", G_STRLOC);
+                                               msg_debug_archive ("bad 7zip name; %s", G_STRLOC);
                                        }
 
                                        res = rspamd_7zip_ucs2_to_utf8 (task, p, fend);
@@ -1409,7 +1440,7 @@ rspamd_7zip_read_files_info (struct rspamd_task *task,
                                                g_ptr_array_add (arch->files, fentry);
                                        }
                                        else {
-                                               msg_debug_task ("bad 7zip name; %s", G_STRLOC);
+                                               msg_debug_archive ("bad 7zip name; %s", G_STRLOC);
                                        }
                                        /* Skip zero terminating character */
                                        p = fend + 2;
@@ -1427,7 +1458,7 @@ rspamd_7zip_read_files_info (struct rspamd_task *task,
                        break;
                default:
                        p = NULL;
-                       msg_debug_task ("bad 7zip type: %c; %s", t, G_STRLOC);
+                       msg_debug_archive ("bad 7zip type: %c; %s", t, G_STRLOC);
                        goto end;
                        break;
                }
@@ -1472,7 +1503,7 @@ rspamd_7zip_read_next_section (struct rspamd_task *task,
                break;
        default:
                p = NULL;
-               msg_debug_task ("bad 7zip type: %c; %s", t, G_STRLOC);
+               msg_debug_archive ("bad 7zip type: %c; %s", t, G_STRLOC);
                break;
        }
 
@@ -1494,7 +1525,7 @@ rspamd_archive_process_7zip (struct rspamd_task *task,
 
        if (end - p <= sizeof (guint64) + sizeof (guint32) ||
                        memcmp (p, sz_magic, sizeof (sz_magic)) != 0) {
-               msg_debug_task ("7z archive is invalid (no 7z magic)");
+               msg_debug_archive ("7z archive is invalid (no 7z magic)");
 
                return;
        }
@@ -1515,7 +1546,7 @@ rspamd_archive_process_7zip (struct rspamd_task *task,
                p += sizeof (guint32);
        }
        else {
-               msg_debug_task ("7z archive is invalid (truncated crc)");
+               msg_debug_archive ("7z archive is invalid (truncated crc)");
 
                return;
        }
@@ -1524,7 +1555,7 @@ rspamd_archive_process_7zip (struct rspamd_task *task,
                p += section_offset;
        }
        else {
-               msg_debug_task ("7z archive is invalid (incorrect section offset)");
+               msg_debug_archive ("7z archive is invalid (incorrect section offset)");
 
                return;
        }
@@ -1552,7 +1583,7 @@ rspamd_archive_process_gzip (struct rspamd_task *task,
        end = p + part->parsed_data.len;
 
        if (end - p <= 10 || memcmp (p, gz_magic, sizeof (gz_magic)) != 0) {
-               msg_debug_task ("gzip archive is invalid (no gzip magic)");
+               msg_debug_archive ("gzip archive is invalid (no gzip magic)");
 
                return;
        }
@@ -1586,7 +1617,7 @@ rspamd_archive_process_gzip (struct rspamd_task *task,
                        RAR_READ_UINT16 (optlen);
 
                        if (end <= p + optlen) {
-                               msg_debug_task ("gzip archive is invalid, bad extra length: %d",
+                               msg_debug_archive ("gzip archive is invalid, bad extra length: %d",
                                                (int)optlen);
 
                                return;
@@ -1604,7 +1635,7 @@ rspamd_archive_process_gzip (struct rspamd_task *task,
                                        struct rspamd_archive_file *f;
 
                                        f = g_malloc0 (sizeof (*f));
-                                       f->fname = rspamd_archive_file_try_utf (fname_start,
+                                       f->fname = rspamd_archive_file_try_utf (task, fname_start,
                                                        p - fname_start);
 
                                        g_ptr_array_add (arch->files, f);
@@ -1617,7 +1648,7 @@ rspamd_archive_process_gzip (struct rspamd_task *task,
                }
 
                /* Wrong filename, not zero terminated */
-               msg_debug_task ("gzip archive is invalid, bad filename at pos %d",
+               msg_debug_archive ("gzip archive is invalid, bad filename at pos %d",
                                (int)(p - start));
 
                return;
@@ -1642,6 +1673,9 @@ rspamd_archive_process_gzip (struct rspamd_task *task,
                                g_string_append_len (f->fname, slash_pos + 1,
                                                dot_pos - slash_pos - 1);
 
+                               msg_debug_archive ("fallback to gzip filename based on cd: %v",
+                                               f->fname);
+
                                g_ptr_array_add (arch->files, f);
 
                                goto set;
@@ -1654,6 +1688,9 @@ rspamd_archive_process_gzip (struct rspamd_task *task,
                                g_string_append_len (f->fname, fname_start,
                                                dot_pos - fname_start);
 
+                               msg_debug_archive ("fallback to gzip filename based on cd: %v",
+                                               f->fname);
+
                                g_ptr_array_add (arch->files, f);
 
                                goto set;