Steven Winikoff
2008-Sep-30 06:08 UTC
[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 at 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 the
* system's lastlog file
*
* 2) 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 at alcor.concordia.ca | automatically to absorb any
http://alcor.concordia.ca/~smw | increased income.
Timo Sirainen
2008-Oct-05 11:51 UTC
[Dovecot] Corrupted transaction log file / record size too small
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. -------------- next part -------------- A non-text attachment was scrubbed... Name: log-debug.diff Type: text/x-patch Size: 1138 bytes Desc: not available URL: <http://dovecot.org/pipermail/dovecot/attachments/20081005/8c671142/attachment-0004.bin> -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 197 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20081005/8c671142/attachment-0005.bin>
Steven Winikoff
2008-Oct-05 23:20 UTC
[Dovecot] Corrupted transaction log file / record size too small
>> 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.Yes, that's right. I didn't realize it at first, because we were also seeing other problems (eg assertion failure at line 39 of index-sync.c) which did require the index to be deleted. I've since made the following changes: 1) commented out the assertion at line 39 of index-sync.c (as per http://www.nabble.com/dovecot-panic-after-upgrade-1.0.15-to-1.1.2-td19098506.html) 2) recompiled dovecot without optimization (ie, gcc -O0 instead of -O2) (as per http://www.mail-archive.com/dovecot at dovecot.org/msg12936.html) 3) reverted to using flock for file locking instead of fcntl (we'd been using flock with dovecot 1.0.10; 1.1.3 used fcntl by default in a couple of places, so I changed it back to see what would happen) After this, we've seen fewer problems, but there are still the occasional ones: - the original corrupted transaction log error which prompted this thread - we still see the occasional assertion failure at line 1091 of index-mail.c; this is the one that I'd hoped to solve by recompiling without optimization, but at least it seems to be happening less frequently than before - this doesn't happen often, but once in a while we see assertion failures at line 163 of src/pop3-login/client-authenticate.c or line 200 of src/imap-login/client-authenticate.c>Can you reproduce this by running imaptest (on a test account)? >http://imapwiki.org/ImapTestActually this and your other suggestions may not be necessary; I think I just realized what's been going on. I missed this originally, but on reflection I notice in the logs that every time the "record size too small" error appears, inevitably the user involved is over disk quota and out of grace period. For example, Oct 3 17:52:21 alcor dovecot: imap[14973] XXXX, NNN.NNN.NN.NNN: Corrupted transaction log file /home/XXXX/mail/.imap/sent-mail/dovecot.index.log: record size too small (type=0xcd91, offset=8180, size=0) Oct 3 17:52:21 alcor dovecot: imap[14973] XXXX, NNN.NNN.NN.NNN: fscking index file (in-memory index) Oct 3 17:52:21 alcor dovecot: imap[14973] XXXX, NNN.NNN.NN.NNN: Transaction log got desynced for index (in-memory index) Oct 3 17:52:21 alcor dovecot: imap[14973] XXXX, NNN.NNN.NN.NNN: Disconnected: IMAP session state is inconsistent, please relogin. bytes=169/1848 Oct 3 17:52:22 alcor dovecot: imap-login: Login: [14998], XXXX, NNN.NNN.NN.NNN Oct 3 17:52:22 alcor dovecot: wrapper[15023]: imap, XXXX, NNN.NNN.NN.NNN Oct 3 17:52:22 alcor dovecot: imap[15023] XXXX, NNN.NNN.NN.NNN: open(/home/XXXX/mail/.imap/CFI-Howe/.temp.alcor.15023.e786c194b1dcc08c) failed: Disk quota exceeded Having seen this, I went back to the saved log for September 30th (the one containing the excerpt I pasted into my original message in this thread) -- and interestingly, I found that the quota failure wasn't recorded there. I don't know what was different about that occurrence, but everything I've seen recently suggests that "record size too small" is due to interaction with the quota system. ...so this is where I admit that I have indeed read http://wiki.dovecot.org/Quota/FS; unfortunately, the only user-writable file system on this machine that doesn't have (or need to have!) disk quotas enabled is /var/tmp, which doesn't seem to be a suitable place for dovecot indexes. Under the circumstances, are you still interested in seeing ImapTest results and a backtrace? If so, should I do that before or after upgrading to 1.1.4? Thanks, - Steven ________________________________________________________________________ Steven Winikoff | Concordia University | "The end of the world will occur at Montreal, QC, Canada | 3:00 p.m., this Friday, with symposium smw at alcor.concordia.ca | to follow." http://alcor.concordia.ca/~smw | - fortune(6)
Steven Winikoff
2008-Oct-10 18:22 UTC
[Dovecot] Corrupted transaction log file / record size too small
>> 2) recompiled dovecot without optimization (ie, gcc -O0 instead of -O2) >> (as per http://www.mail-archive.com/dovecot at dovecot.org/msg12936.html) > >The problem here turned out to be a bug in Sun CC (and gcc -O2 >apparently worked after all, so maybe a problem with testing).Thanks. I'll revert to the default -O2 the next time we recompile (which will probably be version 1.1.4 sometime early next week).>> 3) reverted to using flock for file locking instead of fcntl (we'd been >> using flock with dovecot 1.0.10; 1.1.3 used fcntl by default in a >> couple of places, so I changed it back to see what would happen) > >This shouldn't really make a difference.That's good, because in hindsight I haven't noticed any difference. :-)>> - we still see the occasional assertion failure at line 1091 of >> index-mail.c; this is the one that I'd hoped to solve by >> recompiling without optimization, but at least it seems to be >> happening less frequently than before > >I had hoped v1.1.3 would have fixed this. But perhaps this is also >related to the disk quota issues. Are there any other errors that are >logged before the assert?Nothing obvious, I'm afraid. For example, this occurence is typical of the 24 which we've logged since Sept. 26 (which is as far back as we keep dovecot log data online; for the record, we upgraded from 1.0.10 to 1.1.3 on Sept. 23): Oct 8 13:56:39 alcor dovecot: pop3[15127] USER1, NNN.NNN.NNN.NNN: Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0, xfer=12/27 Oct 8 13:56:39 alcor dovecot: pop3-login: Login: [15118], USER2, NNN.NNN.NNN.NNN Oct 8 13:56:39 alcor dovecot: wrapper[15139]: pop3, USER2, NNN.NNN.NNN.NNN Oct 8 13:56:39 alcor dovecot: pop3-login: Login: [15058], USER3, NNN.NNN.NNN.NNN Oct 8 13:56:39 alcor dovecot: wrapper[15141]: pop3, USER3, NNN.NNN.NNN.NNN Oct 8 13:56:39 alcor dovecot: pop3[15141] USER3, NNN.NNN.NNN.NNN: mkdir(/home/USER3/.imap/INBOX) failed: Disk quota exceeded Oct 8 13:56:39 alcor dovecot: imap-login: Login: [15121], USER4, NNN.NNN.NNN.NNN Oct 8 13:56:39 alcor dovecot: wrapper[15143]: imap, USER4, NNN.NNN.NNN.NNN Oct 8 13:56:39 alcor dovecot: pop3[15139] USER2, NNN.NNN.NNN.NNN: Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0, xfer=12/27 Oct 8 13:56:39 alcor dovecot: imap-login: Login: [15001], USER5, NNN.NNN.NNN.NNN Oct 8 13:56:40 alcor dovecot: wrapper[15159]: imap, USER5, NNN.NNN.NNN.NNN Oct 8 13:56:40 alcor dovecot: imap-login: Login: [15158], USER6, NNN.NNN.NNN.NNN Oct 8 13:56:40 alcor dovecot: wrapper[15162]: imap, USER6, NNN.NNN.NNN.NNN Oct 8 13:56:40 alcor dovecot: imap[15159] USER5, NNN.NNN.NNN.NNN: Disconnected: Logged out bytes=305/13377 Oct 8 13:56:40 alcor dovecot: imap[15162] USER6, NNN.NNN.NNN.NNN: Disconnected: Logged out bytes=110/356 Oct 8 13:56:40 alcor dovecot: Panic: imap[15143] USER4, NNN.NNN.NNN.NNN: file index-mail.c: line 1091 (index_mail_close): assertion failed: (!mail->data.destroying_stream) Oct 8 13:56:40 alcor dovecot: imap[15143] USER4, NNN.NNN.NNN.NNN: Raw backtrace: dovecot-imap [0x4a3ddd] -> dovecot-imap [0x4a4b9d] -> dovecot-imap(i_fatal+0) [0x4a40d1] -> dovecot-imap(index_mail_close+0xfa) [0x4538d4] -> dovecot-imap [0x4538fe] -> dovecot-imap(index_mail_set_seq+0x6a) [0x453ac6] -> dovecot-imap [0x445e6e] -> dovecot-imap(mail_set_seq+0x28) [0x45f6a5] -> dovecot-imap(index_storage_search_next_nonblock+0xe9) [0x458ff0] -> dovecot-imap(mailbox_search_next_nonblock+0x33) [0x462de3] -> dovecot-imap(mailbox_search_next+0x2e) [0x462da2] -> dovecot-imap [0x415e99] -> dovecot-imap(cmd_copy+0x19c) [0x4160ac] -> dovecot-imap [0x41d0ac] -> dovecot-imap [0x41d2e9] -> dovecot-imap [0x41d41c] -> dovecot-imap [0x41d460] -> dovecot-imap(client_input+0xb4) [0x41d5ed] -> dovecot-imap(io_loop_handler_run+0x17d) [0x4aea11] -> dovecot-imap(io_loop_run+0x3b) [0x4adc6a] -> dovecot-imap(main+0x99) [0x42908b] -> /lib64/libc.so.6(__libc_start_main+0xf4) [0x2b306fee78c4] -> dovec! ot-imap [0x414939] Oct 8 13:56:40 alcor dovecot: child 15143 (imap) killed with signal 6 Oct 8 13:56:40 alcor dovecot: pop3[15141] USER3, NNN.NNN.NNN.NNN: Disconnected: Logged out top=0/0, retr=1/12816, del=1/1, size=12798, xfer=40/12944 Oct 8 13:56:40 alcor dovecot: imap-login: Login: [15003], USER7, NNN.NNN.NNN.NNN Although the usernames and IP addresses have been elided, each USERn token always represents the same specific account wherever it appears.>> - this doesn't happen often, but once in a while we see assertion >> failures at line 163 of src/pop3-login/client-authenticate.c or >> line 200 of src/imap-login/client-authenticate.c > >I think I've managed to get this also sometimes when killing dovecot- >auth or doing something else "wrong" (I don't remember exactly), but >not during normal operation. I should have noted down how to reproduce >this when I still knew how to reproduce it..For us this appears to happen during normal operations. That's not to say I've never killed a dovecot-auth process :-), but it's not something I do often (in fact the last time I did was when I recompiled 1.1.3 as described previously, which by now was ten days ago). For what it may be worth, this particular symptom appears to happen in clusters. The most recent spate that we saw were as follows (in context, in case any of the other log messages may be relevant): Oct 10 04:48:45 alcor dovecot: pop3-login: Disconnected (no auth attempts): [9703], NNN.NNN.NNN.NNN Oct 10 04:48:45 alcor dovecot: pop3-login: Disconnected (no auth attempts): [9705], NNN.NNN.NNN.NNN Oct 10 04:48:45 alcor dovecot: pop3-login: Disconnected (no auth attempts): [9702], NNN.NNN.NNN.NNN Oct 10 04:48:46 alcor dovecot: pop3-login: Disconnected (no auth attempts): [9704], NNN.NNN.NNN.NNN Oct 10 04:48:46 alcor dovecot: pop3-login: Disconnected: Inactivity (auth failed, 1 attempts): [9500], USER10, NNN.NNN.NNN.NNN Oct 10 04:48:46 alcor dovecot: Panic: pop3-login: file client-authenticate.c: line 163 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:46 alcor dovecot: imap-login: Disconnected: Inactivity (auth failed, 1 attempts): [9502], USER11, NNN.NNN.NNN.NNN, TLS Oct 10 04:48:46 alcor dovecot: Panic: imap-login: file client-authenticate.c: line 200 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:46 alcor dovecot: imap-login: Disconnected: Inactivity (auth failed, 1 attempts): [9503], USER12, NNN.NNN.NNN.NNN, TLS Oct 10 04:48:46 alcor dovecot: Panic: imap-login: file client-authenticate.c: line 200 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:46 alcor dovecot: imap-login: Disconnected: Inactivity (auth failed, 1 attempts): [8777], USER9, NNN.NNN.NNN.NNN Oct 10 04:48:46 alcor dovecot: Panic: imap-login: file client-authenticate.c: line 200 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:47 alcor dovecot: imap[4258] USER8, 67.223.74.40: Disconnected: Logged out bytes=7407/20930 Oct 10 04:48:47 alcor dovecot: pop3-login: Disconnected: Inactivity (auth failed, 1 attempts): [9575], USER13, NNN.NNN.NNN.NNN Oct 10 04:48:47 alcor dovecot: Panic: pop3-login: file client-authenticate.c: line 163 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:47 alcor dovecot: pop3-login: Disconnected: Inactivity (auth failed, 1 attempts): [9576], USER14, NNN.NNN.NNN.NNN Oct 10 04:48:47 alcor dovecot: Panic: pop3-login: file client-authenticate.c: line 163 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9498 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9500 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9499 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9502 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9503 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9575 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9576 Oct 10 04:48:47 alcor dovecot: auth(default): Master requested auth for nonexisting client 9174 Oct 10 04:48:47 alcor dovecot: imap[9809] USER9, 132.205.7.20: Connection closed bytes=0/0 Oct 10 04:48:47 alcor dovecot: imap-login: Disconnected: Inactivity (auth failed, 1 attempts): [9174], USER8, NNN.NNN.NNN.NNN, TLS Oct 10 04:48:47 alcor dovecot: Panic: imap-login: file client-authenticate.c: line 200 (sasl_callback): assertion failed: (!client->destroyed || reply == SASL_SERVER_REPLY_CLIENT_ERROR || reply == SASL_SERVER_REPLY_MASTER_FAILED) Oct 10 04:48:48 alcor dovecot: imap-login: Disconnected (no auth attempts): [9896], NNN.NNN.NNN.NNN Oct 10 04:48:48 alcor dovecot: imap-login: Disconnected (no auth attempts): [9895], NNN.NNN.NNN.NNN Oct 10 04:48:48 alcor dovecot: pop3-login: Disconnected (no auth attempts): [9893], NNN.NNN.NNN.NNN>> I missed this originally, but on reflection I notice in the logs that >> every time the "record size too small" error appears, inevitably the >> user involved is over disk quota and out of grace period. For >> example, > >Yes, this is most likely what's the problem. I remember testing v1.0 >quite a lot in "out of disk space" conditions, but I haven't really >done any such testing with v1.1. I'll try that and see if I can get >these problems reproduced and fixed.Thank you! :-) Please let me know if there's anything I can do to help. - Steven ________________________________________________________________________ Steven Winikoff | Concordia University | "Hanging is too good for a man who Montreal, QC, Canada | makes puns; he should be drawn and smw at alcor.concordia.ca | quoted." http://alcor.concordia.ca/~smw | - Fred Allen
Steven Winikoff
2008-Oct-10 20:54 UTC
[Dovecot] Corrupted transaction log file / record size too small
>>[...] >> Oct 8 13:56:40 alcor dovecot: Panic: imap[15143] USER4, >> NNN.NNN.NNN.NNN: file index-mail.c: line 1091 (index_mail_close): >> assertion failed: (!mail->data.destroying_stream) > >Hmm. I think I thought of a different assert before when commenting. >This assert should be fixed by 1.1.4 / this patch: http://hg.dovecot.org/dovecot-1.1/rev/3b0d23902a32Great! Thank you.>>>> - this doesn't happen often, but once in a while we see assertion >>>> failures at line 163 of src/pop3-login/client-authenticate.c or >>>> line 200 of src/imap-login/client-authenticate.c >>[...] > >I'll try to look into this soon.Much appreciated! Thanks, - Steven ________________________________________________________________________ Steven Winikoff | Concordia University | "Reality is what refuses to go away Montreal, QC, Canada | when I stop believing in it." smw at alcor.concordia.ca | http://alcor.concordia.ca/~smw | - Philip K. Dick
Steven Winikoff
2008-Oct-19 03:00 UTC
[Dovecot] Corrupted transaction log file / record size too small
>This and some other bugs are now fixed by this: >http://hg.dovecot.org/dovecot-1.1/rev/262c52055f2aThank you! Both for this and for http://hg.dovecot.org/dovecot-1.1/rev/a0693aec0245 - Steven ________________________________________________________________________ Steven Winikoff | Concordia University | "It's a control freak thing -- I Montreal, QC, Canada | wouldn't let you understand." smw at alcor.concordia.ca | http://alcor.concordia.ca/~smw | - Stephen H. Underwood