diff -r 262c52055f2a src/lib-index/mail-cache-compress.c --- a/src/lib-index/mail-cache-compress.c Sat Oct 18 20:26:38 2008 +0300 +++ b/src/lib-index/mail-cache-compress.c Sat Oct 18 20:27:21 2008 +0300 @@ -135,6 +135,8 @@ cache->file_field_map[idx] = i; j++; } + i_debug("cache: field_idx=%u -> file idx %u name=%s", + i, cache->field_file_map[i], cache->fields[i].field.name); /* change permanent decisions to temporary decisions. if they're still permanent they'll get updated later. */ @@ -359,6 +361,8 @@ if (mail_cache_header_fields_read(cache) < 0) return -1; + i_debug("cache compress"); + old_mask = umask(cache->index->mode ^ 0666); fd = file_dotlock_open(&cache->dotlock_settings, cache->filepath, DOTLOCK_CREATE_FLAG_NONBLOCK, &dotlock); diff -r 262c52055f2a src/lib-index/mail-cache-fields.c --- a/src/lib-index/mail-cache-fields.c Sat Oct 18 20:26:38 2008 +0300 +++ b/src/lib-index/mail-cache-fields.c Sat Oct 18 20:27:21 2008 +0300 @@ -322,6 +322,7 @@ max_drop_time = cache->index->map->hdr.day_stamp == 0 ? 0 : cache->index->map->hdr.day_stamp - MAIL_CACHE_FIELD_DROP_SECS; + i_debug("cache: reading fields - file_seq=%u", cache->hdr->file_seq); memset(&field, 0, sizeof(field)); for (i = 0; i < field_hdr->fields_count; i++) { for (p = names; p != end && *p != '\0'; p++) ; @@ -352,6 +353,7 @@ if (field_type_verify(cache, fidx, types[i], sizes[i]) < 0) return -1; + i_assert(strcasecmp(cache->fields[fidx].field.name, names) == 0); } else { field.name = names; field.type = types[i]; @@ -369,6 +371,8 @@ cache->field_file_map[fidx] = i; cache->file_field_map[i] = fidx; + i_debug("cache: field_idx=%u -> file idx %u name=%s", + fidx, i, cache->fields[fidx].field.name); /* update last_used if it's newer than ours */ if (last_used[i] > cache->fields[fidx].last_used) diff -r 262c52055f2a src/lib-index/mail-cache-lookup.c --- a/src/lib-index/mail-cache-lookup.c Sat Oct 18 20:26:38 2008 +0300 +++ b/src/lib-index/mail-cache-lookup.c Sat Oct 18 20:27:21 2008 +0300 @@ -203,9 +203,12 @@ { struct mail_cache *cache = ctx->view->cache; unsigned int field_idx; - unsigned int data_size; + unsigned int data_size, *n; uint32_t file_field; int ret; + unsigned int i, len; + unsigned char *value; + const char *name; i_assert(ctx->remap_counter == cache->remap_counter); @@ -264,7 +267,21 @@ field_r->field_idx = field_idx; field_r->data = CONST_PTR_OFFSET(ctx->rec, ctx->pos); field_r->size = data_size; - + if (data_size > 4) { + n = (unsigned int*)field_r->data; + for (i = 1; n[i-1] != 0; i++); + len = data_size - sizeof(int)*i; + value = (unsigned char *)field_r->data + sizeof(int)*i; + /*i_debug("field_idx=%u name=%s %.*s", field_idx, + cache->fields[field_idx].field.name, len, value);*/ + name = cache->fields[field_idx].field.name; + if (strncasecmp(name, "hdr.", 4) == 0 && + len > 0 && (len < strlen(name+4) || + strncasecmp(value, name + 4, strlen(name+4)) != 0)) { + i_error("BROKEN"); + sleep(3600); + } + } /* each record begins from 32bit aligned position */ ctx->pos += (data_size + sizeof(uint32_t)-1) & ~(sizeof(uint32_t)-1); return 1; @@ -434,6 +451,8 @@ hdr_data->offset = (const char *)&lines[lines_count+1] - (const char *)ctx->view->cache->data; hdr_data->data_size = data_size; + /*i_debug("found: %u lines=%d offset=%d size=%d", field->field_idx, + lines_count, (int)hdr_data->offset, data_size);*/ for (i = 0; i < lines_count; i++) { hdr_line.line_num = lines[i]; @@ -464,6 +483,7 @@ unsigned int i, count, max_field = 0; size_t hdr_size; uint8_t want = HDR_FIELD_STATE_WANT; + uint32_t file_seq; buffer_t *buf; int ret; @@ -497,6 +517,7 @@ t_array_init(&ctx.lines, 32); mail_cache_lookup_iter_init(view, seq, &iter); + file_seq = cache->hdr->file_seq; while ((ret = mail_cache_lookup_iter_next(&iter, &field)) > 0) { if (field.field_idx > max_field || field_state[field.field_idx] != HDR_FIELD_STATE_WANT) { @@ -509,6 +530,7 @@ } if (ret < 0) return -1; + i_assert(file_seq == cache->hdr->file_seq); /* check that all fields were found */ for (i = 0; i <= max_field; i++) { @@ -528,6 +550,7 @@ /* find the end of the (multiline) header */ for (p = start; p != end; p++) { + i_assert(*p != '\0'); if (*p == '\n' && (p+1 == end || (p[1] != ' ' && p[1] != '\t'))) { p++; diff -r 262c52055f2a src/lib-index/mail-cache-transaction.c --- a/src/lib-index/mail-cache-transaction.c Sat Oct 18 20:26:38 2008 +0300 +++ b/src/lib-index/mail-cache-transaction.c Sat Oct 18 20:27:21 2008 +0300 @@ -70,6 +70,7 @@ static void mail_cache_transaction_reset(struct mail_cache_transaction_ctx *ctx) { + i_debug("transaction RESET"); ctx->cache_file_seq = MAIL_CACHE_IS_UNUSABLE(ctx->cache) ? 0 : ctx->cache->hdr->file_seq; mail_index_ext_set_reset_id(ctx->trans, ctx->cache->ext_id, @@ -601,6 +602,7 @@ if (MAIL_CACHE_IS_UNUSABLE(cache)) return -1; + i_debug("cache: flushing"); commit = ctx->prev_seq == 0; if (commit) { /* committing, remove the last dummy record */ @@ -725,6 +727,7 @@ if (ctx->prev_seq != 0) mail_cache_transaction_switch_seq(ctx); + i_debug("cache: committing"); if (mail_cache_transaction_flush(ctx) < 0) ret = -1; @@ -888,9 +891,10 @@ void mail_cache_add(struct mail_cache_transaction_ctx *ctx, uint32_t seq, unsigned int field_idx, const void *data, size_t data_size) { - uint32_t file_field, data_size32; + uint32_t file_field, data_size32, uid; unsigned int fixed_size; size_t full_size; + const char *name; int ret; i_assert(field_idx < ctx->cache->fields_count); @@ -899,6 +903,24 @@ if (ctx->cache->fields[field_idx].field.decision == (MAIL_CACHE_DECISION_NO | MAIL_CACHE_DECISION_FORCED)) return; + + mail_index_lookup_uid(ctx->view->view, seq, &uid); + name = ctx->cache->fields[field_idx].field.name; + if (strncasecmp(name, "hdr.", 4) == 0 && + data_size > 4) { + const unsigned char *n = data, *value; + unsigned int i, len; + + for (i = 1; n[i-1] != 0; i++); + len = data_size - sizeof(int)*i; + value = (const unsigned char *)data + sizeof(int)*i; + if (len < strlen(name + 4) && + strncasecmp(value, name + 4, strlen(name + 4)) != 0) { + i_error("error adding"); + sleep(3600); + } + i_debug("add: uid=%u field_idx=%u name=%s: %.*s", uid, field_idx, name, (int)len, value); + } if (ctx->cache_file_seq == 0) { mail_cache_transaction_open_if_needed(ctx); @@ -969,6 +991,8 @@ } } + i_debug("added: uid=%u field_idx=%u name=%s file_field=%u", + uid, field_idx, name, file_field); buffer_append(ctx->cache_data, &file_field, sizeof(file_field)); if (fixed_size == (unsigned int)-1) { buffer_append(ctx->cache_data, &data_size32, diff -r 262c52055f2a src/lib-index/mail-cache.c --- a/src/lib-index/mail-cache.c Sat Oct 18 20:26:38 2008 +0300 +++ b/src/lib-index/mail-cache.c Sat Oct 18 20:27:21 2008 +0300 @@ -260,6 +260,8 @@ mail_cache_set_corrupted(cache, "used_file_size too large"); return FALSE; } + + i_debug("cache: verified hdr - file_seq=%u", hdr->file_seq); return TRUE; } diff -r 262c52055f2a src/lib-storage/index/index-mail-headers.c --- a/src/lib-storage/index/index-mail-headers.c Sat Oct 18 20:26:38 2008 +0300 +++ b/src/lib-storage/index/index-mail-headers.c Sat Oct 18 20:27:21 2008 +0300 @@ -17,6 +17,32 @@ #include +#include +#include +#include +#include "ioloop.h" +void i_debug(const char *format, ...) +{ + static FILE *f = NULL; + va_list args; + struct timeval tv; + + gettimeofday(&tv, NULL); + + va_start(args, format); + t_push(); + if (!f) { + const char *dir = t_strdup_printf("/tmp/dovecot/%d", (int)ioloop_time/10); + mkdir(dir, 0700); + f = fopen(t_strdup_printf("%s/%d", dir, getpid()), "a+"); + setbuf(f, NULL); + } + fprintf(f, "%10u.%06u PID=%s %s\n", + (unsigned)tv.tv_sec, (unsigned)tv.tv_usec, + dec2str(getpid()), t_strdup_vprintf(format, args)); + t_pop(); + va_end(args); +} struct index_header_lookup_ctx { struct mailbox_header_lookup_ctx ctx; pool_t pool; @@ -457,6 +483,7 @@ mail->data.save_envelope = TRUE; header_ctx = mailbox_header_lookup_init(&mail->ibox->box, imap_envelope_headers); + i_debug("%u: envelope lookup", mail->mail.mail.uid); if (mail_get_header_stream(&mail->mail.mail, header_ctx, &stream) < 0) { mailbox_header_lookup_deinit(&header_ctx); return -1; @@ -473,6 +500,7 @@ if (mail->data.stream != NULL) i_stream_seek(mail->data.stream, old_offset); + i_debug("%u: envelope success: %s", mail->mail.mail.uid, mail->data.envelope); return 0; } @@ -718,14 +746,19 @@ (struct index_header_lookup_ctx *)_headers; struct istream *input; string_t *dest; + unsigned int i; if (mail->data.save_bodystructure_header) { /* we have to parse the header. */ - if (index_mail_parse_headers(mail, _headers) < 0) + if (index_mail_parse_headers(mail, _headers) < 0) { + i_debug("%u: headers: header parsing failed", _mail->uid); return -1; + } } dest = str_new(mail->data_pool, 256); + for (i = 0; i < headers->count; i++) + i_debug("%u: map %u = %s", _mail->uid, headers->idx[i], headers->name[i]); if (mail_cache_lookup_headers(mail->trans->cache_view, dest, mail->data.seq, headers->idx, headers->count) > 0) { @@ -734,14 +767,18 @@ mail->data.filter_stream = i_stream_create_from_data(str_data(dest), str_len(dest)); + i_debug("%u: headers: <<<%s>>>", _mail->uid, str_c(dest)); *stream_r = mail->data.filter_stream; return 0; } /* not in cache / error */ p_free(mail->data_pool, dest); - if (mail_get_stream(&mail->mail.mail, NULL, NULL, &input) < 0) + if (mail_get_stream(&mail->mail.mail, NULL, NULL, &input) < 0) { + i_debug("%u: headers: stream open failed", _mail->uid); return -1; + } + i_debug("%u: headers: streaming", _mail->uid); if (mail->data.filter_stream != NULL) i_stream_destroy(&mail->data.filter_stream);