Hi list,
I have come across a bug that brings down an entire cyrus system when
using sieve and the sendmail path is misconfigured and pointing to a
non-existant sendmail executable file. I have set up a testing
environment where I have been able to reproduce the bug and identify
part of the "offending" code. I'd like to write what my findings are and
ask the cyrus developers and community for some insight :-)
Scenario is this:
- Cyrus 2.3.7 configured against sasl and brekeley db 4.2. Using
berkeley database for delivery.db as well as tls_connections.db.
singleinstancestore enabled to save disk space. sendmail path configured
to the default path, and no sendmail executable file on such location.
- A sieve script set up for one user where mail is rejected when coming
from a specific email address. A simple filter like this:
require ["reject"];
if header :contains ["From"] ["jron@xxxxxxxxx"] {
reject "Rejecting your mail";
}
- When a message is dispatched to the cyrus mail system, and the filter
triggers the rejection, it works for a few times and then, repeating the
event makes the lmtp process and its child (the one that should run
sendmail) end up in a frozen state where they no longer accept any
connections and they are waiting for something to happen with the
berkeley db.
- The problem gets worse as all available preforked lmtp daemons reach
the same state while others processes try to access the berkeley db and
they cannot do it because the lmtpd process have blocked the access to
the database or something. Restarting cyrus may end up with a corrupted
database and multiples instances of cyrusdb_ctl running trying to
recover the database. Imap servers end up not responding as well.
- At this point, all messages are queued at the MTA, trying to deliver
them all to cyrus through lmtp, including the one to be filtered by sieve.
As I said before I've been able to reproduce the bug in a controlled
environment and have done some analysis of the source code and might
have got to the point where this is happening. I also have some gdb
backtraces, which are attached to this message, so you can see exactly
where it is happening.
The problem, I think, lies on the file imap/lmtp_sieve.c when the
function open_sendmail is called, for example on the function
send_rejection:
sm_pid = open_sendmail(smbuf, &sm);
if (sm == NULL) {
return -1;
}
returning -1 should be happening when sendmail could not be executed, as
it can be seen on the function that calls send_rejection. The thing is
that sm never gets NULL when sendmail has not been executed, in fact, it
always gets a valid file descriptor. The code for open_sendmail is:
pid_t open_sendmail(const char *argv[], FILE **sm)
{
int fds[2];
FILE *ret;
pid_t p;
pipe(fds);
if ((p = fork()) == 0) {
/* i'm the child! run sendmail! */
close(fds[1]);
/* make the pipe be stdin */
dup2(fds[0], 0);
execv(config_getstring(IMAPOPT_SENDMAIL), (char **) argv);
/* if we're here we suck */
printf("451 lmtpd: didn't exec() sendmail?!?\r\n");
fatal("couldn't exec() sendmail", EC_OSERR);
}
if (p < 0) {
/* failure */
*sm = NULL;
return p;
}
/* parent */
close(fds[0]);
ret = fdopen(fds[1], "w");
*sm = ret;
return p;
}
in the case of the parent, the call to fdopen to the pipe opened below
will _always_ return a valid file descriptor, thus, never returning
NULL. On the other hand, the child calls the function fatal when it
cannot "execv" the sendmail executable. I guess that the function fatal
should gracefully kill the running process without doing anything extra,
but it turns out that fatal does a number of function calls that end up
trying to close the berkeley db that was opened. This, and the fact that
the parent also tries to do some stuff with the berkeley db, results in
both processes blocked while accessing the database and the possibility
of corrupting the db, as can be seen on the backtraces.
What I've done to fix this is to insert a call to exit just before the
call to fatal (so this one is never executed):
exit(EXIT_FAILURE);
In any case, I think, it shouldn't matter that anything else is not
executed on the child process as, on success, the call to execv would
replace the running process and nothing would be executed that is
executed on the call to fatal (regarding the database).
I haven't gone that far away into checking all the source code involved
in this calls, but it would be great if any cyrus developer with more
expertise on the matter could just have a look at this and check it and,
if possible, find a more elegant way of dealing with this issue :-).
In my case, calling exit causes cyrus to behave correctly, by printing
an error message and inserting the message in the INBOX folder, which, I
guess, is the right thing to do when the rejection sieve filter fails,
so the mail is not lost, and also, the mail system does not fail because
of a misconfiguration.
Thanks for reading that far away.
--
Jesús Roncero <jesus@xxxxxxxxxxxxx>
System Developer
Tel: +44 (0) 845 666 7778
http://www.mxtelecom.com
#0 0x4020163c in __db_shalloc_free () from /lib/libdb-4.2.so
#1 0x402040c2 in __dbreg_teardown () from /lib/libdb-4.2.so
#2 0x401e4493 in __db_refresh () from /lib/libdb-4.2.so
#3 0x401e41c6 in __db_close () from /lib/libdb-4.2.so
#4 0x401f2ed5 in __db_close_pp () from /lib/libdb-4.2.so
#5 0x0809db87 in myclose (db=0x815b508) at cyrusdb_berkeley.c:435
#6 0x080725b5 in duplicate_done () at duplicate.c:407
#7 0x0804eab2 in shut_down (code=75) at lmtpd.c:913
#8 0x0804e9ec in fatal (s=0x80a9507 "couldn't exec() sendmail", code=75) at lmtpd.c:883
#9 0x080565e8 in open_sendmail (argv=0xbfff90c0, sm=0xbfff90fc) at smtpclient.c:78
#10 0x08054a9f in send_rejection (origid=0x816cec8 "<cmu-lmtpd-3654-1170340563-1@puma>", rejto=0x816fdb8 "jron@xxxxxxxxx", origreceip=0x0,
mailreceip=0xbfffa460 "jesus@xxxxxxxxxx", reason=0x4166106c "Rejecting your mail", file=0x816cfb8) at lmtp_sieve.c:234
#11 0x08055351 in sieve_reject (ac=0x81679d0, ic=0x0, sc=0xbfffa650, mc=0xbfffbcd0, errmsg=0xbfff91e0) at lmtp_sieve.c:444
#12 0x0807e1fe in do_action_list (interp=0x815b488, body_cache=0xbfff9200, script_context=0xbfffa650, message_context=0xbfffbcd0, imapflags=0xbfff9210,
actions=0x8167970, notify_list=0x816f040, actions_string=0xbfff9220 "Action(s) taken:\n", errmsg=0x0) at script.c:714
#13 0x0807e881 in sieve_execute_bytecode (exe=0x816f010, interp=0x815b488, script_context=0xbfffa650, message_context=0xbfffbcd0) at script.c:926
#14 0x0805641f in run_sieve (user=0x815c0a8 "jesus", domain=0x815c0ae "domain.com", mailbox=0x0, interp=0x815b488, msgdata=0xbfffbcd0)
at lmtp_sieve.c:911
#15 0x0804e6d8 in deliver (msgdata=0x815b928, authuser=0x0, authstate=0x0) at lmtpd.c:781
#16 0x08052238 in lmtpmode (func=0x8132b60, pin=0x816d920, pout=0x816d990, fd=0) at lmtpengine.c:1300
#17 0x0804d387 in service_main (argc=1, argv=0x8158c98, envp=0xbffff60c) at lmtpd.c:285
#18 0x0804cff6 in main (argc=1, argv=0xbffff604, envp=0xbffff60c) at service.c:532
(gdb) bt
#0 0x40332812 in select () from /lib/libc.so.6
#1 0x40246448 in ?? () from /lib/libdb-4.2.so
#2 0x00000000 in ?? ()
#3 0x40017f48 in ?? ()
#4 0x4022a115 in __os_sleep () from /lib/libdb-4.2.so
#5 0x4022a23f in __os_yield () from /lib/libdb-4.2.so
#6 0x4018bb60 in __db_tas_mutex_lock () from /lib/libdb-4.2.so
#7 0x4021e89d in __log_txn_lsn () from /lib/libdb-4.2.so
#8 0x4022cb5c in __txn_compensate_begin () from /lib/libdb-4.2.so
#9 0x4022c825 in __txn_begin () from /lib/libdb-4.2.so
#10 0x40206492 in __dbreg_lazy_id () from /lib/libdb-4.2.so
#11 0x401e62f6 in __db_addrem_log () from /lib/libdb-4.2.so
#12 0x401f15c6 in __db_pitem () from /lib/libdb-4.2.so
#13 0x4019561a in __bam_iitem () from /lib/libdb-4.2.so
#14 0x40190a62 in __bam_bulk_duplicates () from /lib/libdb-4.2.so
#15 0x401ec84c in __db_c_put () from /lib/libdb-4.2.so
#16 0x401e51f4 in __db_put () from /lib/libdb-4.2.so
#17 0x401f4ab7 in __db_put_pp () from /lib/libdb-4.2.so
#18 0x0809e5ed in mystore (mydb=0x815b508, key=0xbfff6c20 "<cmu-sieve-3654-1170340563-1@puma>", keylen=63, data=0xbfff6bb0 "��", datalen=8, mytid=0x0,
putflags=0, txnflags=256) at cyrusdb_berkeley.c:746
#19 0x0809e7bd in store_nosync (db=0x815b508, key=0xbfff6c20 "<cmu-sieve-3654-1170340563-1@puma>", keylen=63, data=0xbfff6bb0 "��", datalen=8, tid=0x0)
at cyrusdb_berkeley.c:820
#20 0x08072090 in duplicate_mark (id=0xbfff70c0 "<cmu-sieve-3654-1170340563-1@puma>", idlen=34, to=0x813b2a0 ".jesus@xxxxxxxxxxxxxxxxx", tolen=27,
mark=1170340563, uid=0) at duplicate.c:198
#21 0x08054b6b in send_rejection (origid=0x816cec8 "<cmu-lmtpd-3654-1170340563-1@puma>", rejto=0x816fdb8 "jron@xxxxxxxxx", origreceip=0x0,
mailreceip=0xbfffa460 "jesus@xxxxxxxxxx", reason=0x4166106c "Rejecting your mail", file=0x816cfb8) at lmtp_sieve.c:245
#22 0x08055351 in sieve_reject (ac=0x81679d0, ic=0x0, sc=0xbfffa650, mc=0xbfffbcd0, errmsg=0xbfff91e0) at lmtp_sieve.c:444
#23 0x0807e1fe in do_action_list (interp=0x815b488, body_cache=0xbfff9200, script_context=0xbfffa650, message_context=0xbfffbcd0, imapflags=0xbfff9210,
actions=0x8167970, notify_list=0x816f040, actions_string=0xbfff9220 "Action(s) taken:\n", errmsg=0x0) at script.c:714
#24 0x0807e881 in sieve_execute_bytecode (exe=0x816f010, interp=0x815b488, script_context=0xbfffa650, message_context=0xbfffbcd0) at script.c:926
#25 0x0805641f in run_sieve (user=0x815c0a8 "jesus", domain=0x815c0ae "domain.com", mailbox=0x0, interp=0x815b488, msgdata=0xbfffbcd0)
at lmtp_sieve.c:911
#26 0x0804e6d8 in deliver (msgdata=0x815b928, authuser=0x0, authstate=0x0) at lmtpd.c:781
#27 0x08052238 in lmtpmode (func=0x8132b60, pin=0x816d920, pout=0x816d990, fd=0) at lmtpengine.c:1300
#28 0x0804d387 in service_main (argc=1, argv=0x8158c98, envp=0xbffff60c) at lmtpd.c:285
#29 0x0804cff6 in main (argc=1, argv=0xbffff604, envp=0xbffff60c) at service.c:532
----
Cyrus Home Page: http://cyrusimap.web.cmu.edu/
Cyrus Wiki/FAQ: http://cyrusimap.web.cmu.edu/twiki
List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html
