[Dovecot] Corrupted transaction log file / record size too small
I recently upgradeded dovecot on one of our servers from version 1.0.10 to version 1.1.3. Ever since, we've been seeing occasional errors similar to this sequence (with the username and IP addresses elided):
Sep 30 00:09:56 alcor dovecot: pop3-login: Login: [4954], XXXX, NNN.NNN.NN.NNN Sep 30 00:09:56 alcor dovecot: wrapper[5006]: pop3, XXXX, NNN.NNN.NN.NNN Sep 30 00:09:56 alcor dovecot: pop3[5006] XXXX, NNN.NNN.NN.NNN: Corrupted transaction log file /home/XXXX/.imap/INBOX/dovecot.index.log: record size too small (type=0x40, offset=12224, size=0) Sep 30 00:09:56 alcor dovecot: pop3[5006] XXXX, NNN.NNN.NN.NNN: Couldn't init INBOX: Internal error occurred. Refer to server log for more information. [2008-09-30 00:09:56] Sep 30 00:09:56 alcor dovecot: pop3[5006] XXXX, NNN.NNN.NN.NNN: Mailbox init failed top=0/0, retr=0/0, del=0/0, size=0, xfer=0/95
System and dovecot configuration details are appended.
I saw an archived mailing list message from January 2007 which may be relevant (www.mailinglistarchive.com/dovecot@dovecot.org/msg07908.html), in which the original poster's symptoms disappeared when he recompiled dovecot with gcc-3.4.0 instead of using gcc-3.1. In my case I used gcc-4.1.2, so I don't know if that's still relevant (and if so, what other version to use instead).
In the output of dovecot -n which follows,
/local/pkg/dovecot/localmods/wrapper.imap is a locally written program
which registers the user's IMAP or POP connection in the lastlog file
and also ensures that the user's shell is considered valid. I'd be
surprised if this is relevant, but I've appended the source code in
case it may be (and/or in case anyone else may find it useful!).
I've been working around the problem by deleting the contents of ~user/.imap for affected users, but I'd really prefer to fix it properly. :-) Any suggestions would be gratefully received.
Thanks,
- Steven# server type = SunFire X4100 (two dual-core Opteron CPUs) # OS = Linux (Slamd64 12.0) # file system type = XFS
# uname -a Linux alcor 2.6.25.2 #1 SMP Fri May 16 07:06:34 EDT 2008 x86_64 x86_64 x86_64 GNU/Linux
# dovecot --version 1.1.3
# (limit descriptors 4096; dovecot -n) # 1.1.3: /local/pkg/dovecot/root-dovecot-1.1.3/etc/dovecot.conf base_dir: /local/pkg/dovecot/data/var/run/dovecot syslog_facility: local0 protocols: imap imaps pop3 pop3s listen(default): *:143 listen(imap): *:143 listen(pop3): *:110 ssl_listen(default): *:993 ssl_listen(imap): *:993 ssl_listen(pop3): *:995 ssl_cert_file: /public/apache/ssl/combined.cert ssl_key_file: /public/apache/ssl/key.pem disable_plaintext_auth: no login_dir: /local/pkg/dovecot/data/var/run login_executable(default): /local/pkg/dovecot/root-dovecot-1.1.3/libexec/dovecot/imap-login login_executable(imap): /local/pkg/dovecot/root-dovecot-1.1.3/libexec/dovecot/imap-login login_executable(pop3): /local/pkg/dovecot/root-dovecot-1.1.3/libexec/dovecot/pop3-login login_user: nul-mail login_log_format_elements: [%p] %u %r %c login_greeting_capability(default): yes login_greeting_capability(imap): yes login_greeting_capability(pop3): no login_processes_count: 6 login_max_processes_count: 512 max_mail_processes: 1024 verbose_proctitle: yes first_valid_uid: 111 mail_location: mbox:~/:INBOX=/var/spool/mail/%u mail_full_filesystem_access: yes mail_executable(default): /local/pkg/dovecot/localmods/wrapper.imap mail_executable(imap): /local/pkg/dovecot/localmods/wrapper.imap mail_executable(pop3): /local/pkg/dovecot/localmods/wrapper.pop3 mail_plugin_dir(default): /local/pkg/dovecot/root-dovecot-1.1.3/lib/dovecot/imap mail_plugin_dir(imap): /local/pkg/dovecot/root-dovecot-1.1.3/lib/dovecot/imap mail_plugin_dir(pop3): /local/pkg/dovecot/root-dovecot-1.1.3/lib/dovecot/pop3 mail_log_prefix: %Ls[%p] %u, %r: imap_capability(default): IMAP4rev1 QUOTA SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS imap_capability(imap): IMAP4rev1 QUOTA SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS imap_capability(pop3): imap_client_workarounds(default): delay-newmail tb-extra-mailbox-sep imap_client_workarounds(imap): delay-newmail tb-extra-mailbox-sep imap_client_workarounds(pop3): pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh pop3_logout_format(default): top=%t/%p, retr=%r/%b, del=%d/%m, size=%s pop3_logout_format(imap): top=%t/%p, retr=%r/%b, del=%d/%m, size=%s pop3_logout_format(pop3): top=%t/%p, retr=%r/%b, del=%d/%m, size=%s, xfer=%i/%o auth default: cache_negative_ttl: 0 passdb: driver: shadow userdb: driver: passwd
# source code for /local/pkg/dovecot/localmods/wrapper.imap # and /local/pkg/dovecot/localmods/wrapper.pop3 # follows:
8<---------------------------- cut here -------------------------->8 /*
- wrapper.c -- login wrapper program for dovecot
- Steven Winikoff
- 2008/01/31
- Part of this program is based on code written by Sylvain Robitaille.
- The intention is twofold:
1) ensure that IMAP and POP sessions are registered in thesystem's lastlog file2) ensure that all IMAP and POP users have a valid login shell- Rather than hack the code for the dovecot server directly, this use
- of a wrapper is based on dovecot's intrinsic "post-login scripting"
- facility; for details, see http://wiki.dovecot.org/PostLoginScripting */
#include <unistd.h> #include <stdlib.h> #include <string.h> #include <sys/types.h> #include <sys/stat.h> #include <lastlog.h> #include <fcntl.h> #include <pwd.h> #include <syslog.h> #include <errno.h> #include <time.h>
#define STRLEN 1024+1
#define LASTLOG "/var/adm/lastlog" #define NEWSHELL "/local/paths/newshell" #define BLOCKSHELL "/local/paths/blocksh"
#define REAL_IMAP_SERVER "/local/paths/dovecot-imap" #define REAL_POP3_SERVER "/local/paths/dovecot-pop3"
#define REAL_IMAP_NAME "dovecot-imap" #define REAL_POP3_NAME "dovecot-pop3"
#define LOGNAME "dovecot: wrapper"
int valid_shell(char *); void update_lastlog(uid_t, char *, char *);
/*-----------------------------------------------------------------------*/
int main(int argc, char **argv) { char service[STRLEN]; char server[STRLEN], server_name[STRLEN], *u, *rh; int unknown_service = 0, len;
struct passwd *p;
/** the service name we've been invoked to wrap is determined **/
/** by the last four characters of our own basename ("imap" or **/
/** "pop3"): **/
len = strlen(argv[0]);
(void)strcpy(service, argv[0] + (len-4));
if (strcmp(service, "imap") == 0)
{
(void)strcpy(server, REAL_IMAP_SERVER);
(void)strcpy(server_name, REAL_IMAP_NAME);
}
else if (strcmp(service, "pop3") == 0)
{
(void)strcpy(server, REAL_POP3_SERVER);
(void)strcpy(server_name, REAL_POP3_NAME);
}
else
{
unknown_service = 1;
}
/** prepare to log: **/
openlog(LOGNAME, LOG_PID, LOG_LOCAL0);
if (unknown_service)
{
syslog(LOG_INFO, "can't handle unknown service '%s'", service);
exit(1);
}
/** $USER is the only way we can determine who called us: **/
if (! (u = getenv("USER")))
{
syslog(LOG_INFO, "aborting: no value supplied for $USER");
exit(2);
}
/** likewise, $IP is our only source for the host we were called **/
/** from: **/
if (! (rh = getenv("IP")))
{
syslog(LOG_INFO, "aborting: no value supplied for (remote host) $IP");
exit(3);
}
/** grab $USER's password file entry: **/
if (! (p = getpwnam(u)))
{
syslog(LOG_INFO, "aborting: can't find a passwd entry for %s", u);
exit(4);
}
/** is this user blocked? **/
if (strcmp(p->pw_shell, BLOCKSHELL) == 0)
{
/** yes, so we're out of here: **/
syslog(LOG_INFO, "aborting: %s is blocked", u);
exit(5);
}
/** okay, but is the user's shell recognized? **/
if (! valid_shell(p->pw_shell))
{
syslog(LOG_INFO, "aborting: %s has invalid shell %s",
u, p->pw_shell);
exit(6);
}
/** update the user's lastlog entry: **/
update_lastlog(p->pw_uid, service, rh);
/** now run the real program for the requested service: **/
syslog(LOG_INFO, "%s, %s, %s", service, u, rh);
argv[0] = server_name;
(void) execv(server, argv);
/** if we're still here, execv() failed: **/
syslog(LOG_INFO, "execv(%s) FAILED (%s), %s, %s",
server_name, strerror(errno), u, rh);
return(7);}
/*-----------------------------------------------------------------------*/
int valid_shell(char *s)
/*
- return 1 if s represents a valid login shell, or 0 otherwise
- for our purposes, "valid" means anything returned by getusershell(3),
- or NEWSHELL as a special case */
{ char *next_shell;
/** a NULL pointer can't be a valid shell: **/
if (! s) return(0);
/** NEWSHELL is always valid: **/
if (strcmp(s, NEWSHELL) == 0) return(1);
/** okay, we have to consult /etc/shells: **/
while ((next_shell = getusershell()) != NULL) { if (strcmp(s, next_shell) == 0) { endusershell(); return(1); } }
/** if we're still here, we don't have a valid shell: **/
endusershell(); return(0); }
/*-----------------------------------------------------------------------*/
void update_lastlog(uid_t uid, char *service, char *remote_system)
/*
- records the user's activity in the system lastlog file.
- Sylvain Robitaille (using code borrowed from the ssh source)
- 1997/11/21
- 2000/07/31 (call with the uid as a parameter)
- */
{
int fd;
struct lastlog ll;
const char *lastlog = LASTLOG;
/** initialize the lastlog structure: **/
memset(&ll, 0, sizeof(ll));
/** fill in the data: **/
ll.ll_time = time(NULL); strncpy(ll.ll_line, service, sizeof(ll.ll_line)); strncpy(ll.ll_host, remote_system, sizeof(ll.ll_host));
/** update the lastlog file: **/
if ((fd = open(lastlog, O_RDWR)) >= 0) { lseek(fd, (off_t)(uid * sizeof(ll)), 0);
if(write(fd, &ll, sizeof(ll)) != sizeof(ll))
{
syslog(LOG_INFO, "Could not write %.100s: %.100s",
lastlog, strerror(errno));
}
close(fd);} else { syslog(LOG_INFO, "Could not open %.100s: %.100s", lastlog, strerror(errno)); } } 8<---------------------------- cut here -------------------------->8
Steven Winikoff | Concordia University | Doyle's Law: Montreal, QC, Canada | Expenditures shall rise smw@alcor.concordia.ca | automatically to absorb any http://alcor.concordia.ca/~smw | increased income.
On Tue, 2008-09-30 at 02:08 -0400, Steven Winikoff wrote:
Sep 30 00:09:56 alcor dovecot: pop3[5006] XXXX, NNN.NNN.NN.NNN: Corrupted transaction log file /home/XXXX/.imap/INBOX/dovecot.index.log: record size too small (type=0x40, offset=12224, size=0) .. I've been working around the problem by deleting the contents of ~user/.imap for affected users, but I'd really prefer to fix it properly. :-) Any suggestions would be gratefully received.
I think this should get fixed by itself? Although the first login fails, the next one should succeed.
Can you reproduce this by running imaptest (on a test account)? http://imapwiki.org/ImapTest
Could you apply the attached patch and when it happens for some user send the saved dovecot.index.broken and dovecot.index.log.broken files to me? Those files don't contain anything sensitive about the user's mails. It'll also log a raw backtrace which might show something useful, so I'd like to see that too (that's only useful if it shows function names, so debug symbols shouldn't be stripped from the Dovecot binaries).
I'm not really sure how that error message could happen unless the log file's contents changed while it was being read.
You could also see if setting mmap_disable=yes makes any difference.
participants (2)
-
Steven Winikoff
-
Timo Sirainen