Sieve redirect does not collect the sendmail child process correctly (Dovecot 2.3.4.1, Pigeonhole 0.5.4)
Hi,
I got this simple test Sieve config:
#
# Sieve Filter
# Generated by Ingo (http://www.horde.org/apps/ingo/) (11/01/2019, 10:46:06 PM)
# Forwards
if true {
redirect "krus...@krustev.net";
}
# Forward Keep Action
if true {
keep;
stop;
}
#
Which used to work fine with:
# 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.16 (fed8554)
# OS: Linux 4.9.0-8-amd64 x86_64 Debian 9.11
Then I've tried migrating to:
# 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.4 ()
# OS: Linux 4.19.0-6-amd64 x86_64 Debian 10.1
And started getting the following errors:
# cat .dovecot.sieve.log
sieve: info: started log at Nov 01 22:55:50.
error: msgid=<4221584.AlbrL4BjWX@home>: failed to redirect message to
: Failed to execute sendmail (temporary failure).
A google search lead me to:
https://bugs.archlinux.org/task/56933
which blames systemd service changes:
NoNewPrivileges=true
, however I'm not running dovecot via systemd but use DJB's daemontools for
service supervision .
The page above suggested to change from:
sendmail_path = /usr/sbin/sendmail
to
submission_host = localhost
in "conf.d/15-lda.conf", which worked fine.
But since I don't have other problems with "sendmail" execution I've decided
to debug this further.
I have dovecot integrated with Qmail:
# apt-cache policy qmail
qmail:
Installed: 1.06-6+b1
Candidate: 1.06-6+b1
Version table:
*** 1.06-6+b1 900
900 http://deb.debian.org/debian buster/main amd64 Packages
so sendmail's implementation comes from Qmail:
# ls -al `which sendmail`
lrwxrwxrwx 1 root root 14 Feb 23 2015 /usr/sbin/sendmail -> qmail-sendmail
I've strace-d the qmail-lspawn process which executes dovecot's LDA, which
processes the Sieve rules and executes "sendmail".
The sendmail process executes and returns successfully, the mail is delivered,
however the Sieve code does not wait for the child process correctly and tries
to kill the already exited process after 30 seconds timeout.
Here are the problematic Sieve syscalls:
22:55:15.283482 execve("/usr/lib/dovecot/deliver", ["/usr/lib/dovecot/deliver",
"-e", "-a", "tes...@krustev.net"], 0x5620b4330c40 /* 61 vars */) = 0
...
22:55:15.286845 pipe([5, 6])= 0
22:55:15.286870 fcntl(5, F_GETFL) = 0 (flags O_RDONLY)
22:55:15.286889 fcntl(5, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
22:55:15.286909 fcntl(6, F_GETFL) = 0x1 (flags O_WRONLY)
22:55:15.286928 fcntl(6, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
22:55:15.286947 fcntl(5, F_GETFD) = 0
22:55:15.286966 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
22:55:15.286985 fcntl(6, F_GETFD) = 0
22:55:15.287003 fcntl(6, F_SETFD, FD_CLOEXEC) = 0
22:55:15.287024 epoll_create(128) = 7
22:55:15.287043 fcntl(7, F_GETFD) = 0
22:55:15.287062 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
22:55:15.287084 epoll_ctl(7, EPOLL_CTL_ADD, 5,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=47201248, u64=94699781110752}}) = 0
...
22:55:15.294625 epoll_ctl(7, EPOLL_CTL_DEL, 5, 0x7ffd59156b8c) = 0
22:55:15.294647 epoll_create(128) = 12
22:55:15.294668 fcntl(12, F_GETFD) = 0
22:55:15.294687 fcntl(12, F_SETFD, FD_CLOEXEC) = 0
22:55:15.294708 epoll_ctl(12, EPOLL_CTL_ADD, 5,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=47455536, u64=94699781365040}}) = 0
Dovecot/Sieve will wait for this pipe FD 5 later, but no event will arrive.
22:55:15.294740 rt_sigaction(SIGCHLD, {sa_handler=0x7f15404b3640, sa_mask=[],
sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f1540229840}, NULL,
8) = 0
22:55:15.294763 pipe([13, 14]) = 0
22:55:15.294788 clone(child_stack=NULL,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7f15401ec2d0) = 6929
The sendmail child process with PID 6929 is forked here.
22:55:15.294928 close(13) = 0
22:55:15.294969 fcntl(14, F_GETFL) = 0x1 (flags O_WRONLY)
22:55:15.295006 fcntl(14, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
22:55:15.295039 lseek(14, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
22:55:15.295065 getsockname(14, 0x7ffd59156a40, [28]) = -1 ENOTSOCK (Socket
operation on non-socket)
22:55:15.295109 write(14, "EDITTED LONG MESSAGE DATA\n", 1461) = 1461
22:55:15.295150 close(14) = 0
22:55:15.295175 wait4(6929, 0x562102d4fee4, WNOHANG, NULL) = 0
22:55:15.295211 epoll_wait(12, [], 1, 3) = 0
Here's where the 30 second's timeout is requested and waited.
22:55:45.325580 kill(6929, SIGTERM) = 0
22:55:45.325769 epoll_wait(12, [], 1, 5000) = 0
22:55:50.331108 kill(6929, SIGKILL) = 0
22:55:50.332867 wait4(6929, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) =
6929
22:55:50.333020 epoll_ctl(12, EPOLL_CTL_DEL, 5, 0x7ffd59156b6c) = 0
22:55:50.333060 epoll_ctl(7, EPOLL_CTL_ADD, 5,
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=47201248, u64=94699781110752}}) = 0
22:55:50.333097 close(12) = 0
Re: Bug report
On 01 Nov 2019, at 16:30, Peter Nabbefeld wrote: > ~/.getmail/log > = > 2019-11-01 21:44:20 Delivery error (command deliver 42245 error (127, exec of > command deliver failed (change UID/GID to vmail/vmail failed ([Errno 1] > Operation not permitted Seems pretty clear, get mail is not running as the right user and doesn’t have permission to change to the right user. Seems to be a configuration issue with get mail (not sure what that is). -- "Whose motorcycle is this?" "It's chopper, baby." "Whose chopper is this?" "It's Zed's." "Who's Zed?" "Zed' dead, baby. Zed's dead.”
Bug report
Hello,
I've got a problem fetching my emails using getmail. First question is, of
course, what's causing the problems. I'm going to think that getmail get's an
error code from dovecot when trying to connect and just signals the most common
error, so it seems to be a problem with dovecot.
Sorry but I cannot upload any files with the silly web interface of my
provider, so I cannot attach a core dump here. :-(
Kind regards
Peter
~/.getmail/log
=
2019-11-01 21:44:20 Delivery error (command deliver 42245 error (127, exec of
command deliver failed (change UID/GID to vmail/vmail failed ([Errno 1]
Operation not permitted
dovecot-info.log
==
Oct 31 20:27:00 lda(mein.n...@gmx.de)<42409><2+iBJIQ1u12ppQAA7IIYzw>:
Panic: file istream-crlf.c: line 24 (i_stream_crlf_read_common): assertion
failed: (ret != -2)
Oct 31 20:27:00 lda(mein.n...@gmx.de)<42409><2+iBJIQ1u12ppQAA7IIYzw>:
Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xff784)
[0x7f4ec8e62784] -> /usr/lib/dovecot/libdovecot.so.0(+0xff7c1) [0x7f4ec8e627c1]
-> /usr/lib/dovecot/libdovecot.so.0(+0x493aa) [0x7f4ec8dac3aa] ->
/usr/lib/dovecot/libdovecot.so.0(+0x4bf62) [0x7f4ec8daef62] ->
/usr/lib/dovecot/libdovecot.so.0(+0x111076) [0x7f4ec8e74076] ->
/usr/lib/dovecot/libdovecot.so.0(i_stream_read_memarea+0x81) [0x7f4ec8e70291]
-> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x37) [0x7f4ec8e70477] ->
/usr/lib/dovecot/libdovecot.so.0(+0x1164a8) [0x7f4ec8e794a8] ->
/usr/lib/dovecot/libdovecot.so.0(i_stream_read_memarea+0x81) [0x7f4ec8e70291]
-> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x37) [0x7f4ec8e70477] ->
/usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x4c) [0x7f4ec8e70f3c] ->
/usr/lib/dovecot/libdovecot.so.0(io_stream_copy+0x8a) [0x7f4ec8e8bbea] ->
/usr/lib/dovecot/libdovecot.so.0(+0x12aa86) [0x7f4ec8e8da86] ->
/usr/lib/dovecot/libdovecot.so.0(o_stream_send_istream+0x4f) [0x7f4ec8e8b86f]
-> /usr/lib/dovecot/libdovecot-storage.so.0(index_storage_save_continue+0x2e)
[0x7f4ec901114e] ->
/usr/lib/dovecot/libdovecot-storage.so.0(maildir_save_continue+0x27)
[0x7f4ec8fafbe7] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mailbox_save_continue+0x47)
[0x7f4ec8f815b7] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mail_storage_copy+0xe8)
[0x7f4ec8f72388] -> /usr/lib/dovecot/libdovecot-storage.so.0(maildir_copy+0x6d)
[0x7f4ec8fab99d] -> /usr/lib/dovecot/libdovecot-lda.so.0(+0x3c46)
[0x7f4ec90a2c46] -> /usr/lib/dovecot/modules/lib20_fts_plugin.so(+0x11004)
[0x7f4ec8af0004] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x59b0c)
[0x7f4ec8f81b0c] -> /usr/lib/dovecot/libdovecot-sieve.so.0(+0x4edb8)
[0x7f4ec67e0db8] ->
/usr/lib/dovecot/libdovecot-sieve.so.0(sieve_result_execute+0x54d)
[0x7f4ec67d65cd] -> /usr/lib/dovecot/libdovecot-sieve.so.0(+0x57a79)
[0x7f4ec67e9a79] ->
/usr/lib/dovecot/libdovecot-sieve.so.0(sieve_multiscript_run+0xa9)
[0x7f4ec67eac49] -> /usr/lib/dovecot/modules/lib90_sieve_plugin.so(+0x376b)
[0x7f4ec685c76b] -> /usr/lib/dovecot/libdovecot-lda.so.0(mail_deliver+0x199)
[0x7f4ec90a46d9]
dovecot -n
===
# 2.3.8 (9df20d2db): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.8 (b7b03ba2)
# OS: Linux 5.3.7-arch1-2-ARCH x86_64 Arch Linux
# Hostname: mein.host.name
auth_verbose = yes
disable_plaintext_auth = no
info_log_path = /var/log/dovecot-info.log
log_path = /var/log/dovecot.log
mail_location = maildir:~/Maildir:LAYOUT=fs
mail_plugins = " fts fts_solr"
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope encoded-character
vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy
include variables body enotify environment mailbox date index ihave duplicate
mime foreverypart extracttext editheader
namespace inbox {
inbox = yes
location =
mailbox Entwürfe {
special_use = \Drafts
}
mailbox Gesendet {
special_use = \Sent
}
mailbox Spamverdacht {
special_use = \Junk
}
mailbox Trash {
special_use = \Trash
}
prefix =
}
passdb {
args = username_format=%u /etc/dovecot/passwd
driver = passwd-file
}
plugin {
fts = solr
fts_solr = url=http://localhost:8983/solr/
sieve = file:/home/vmail/sieve;active=/home/vmail/.dovecot.sieve
sieve_extensions = +editheader
}
service stats {
unix_listener stats-reader {
group = vmail
mode = 0666
user = vmail
}
unix_listener stats-writer {
group = vmail
mode = 0666
user = vmail
}
}
ssl = no
ssl_dh = # hidden, use -P to show it
userdb {
args = uid=vmail gid=vmail home=/home/vmail/%d/%n
driver = static
}
protocol lda {
mail_plugins = " fts fts_solr sieve"
postmaster_address = mein.n...@gmx.de
}
Help with master user
Hi, Trying to implement a master user (1) for auditing purposes without luck. Ubuntu 18.04.3, canonical official repos only, no ppa nor self-compiled anything. From the log below I understand the master password succeeds but AD auth fails. I am pretty sure I missed something here. Also, notice the messages "Ignoring unknown passdb extra field: original_user". Log: Nov 1 14:02:32 netuno dovecot: auth: Debug: client in: AUTH#0112#011PLAIN#011service=imap#011secured#011session=H2WM7kuWFKYKCQgI#011lip=10.9.8.8#011rip=10.9.8.8#011lport=143#011rport=42516#011resp= Nov 1 14:02:32 netuno dovecot: auth: Debug: passwd-file(master,10.9.8.8,master,): Master user lookup for login: test.account Nov 1 14:02:32 netuno dovecot: auth: Debug: passwd-file(master,10.9.8.8,master,): lookup: user=master file=/etc/dovecot/master-users Nov 1 14:02:32 netuno dovecot: auth: passwd-file(master,10.9.8.8,master,): Master user logging in as test.account Nov 1 14:02:32 netuno dovecot: auth: ldap(test.account,10.9.8.8,): invalid credentials Nov 1 14:02:34 netuno dovecot: auth: Debug: client passdb out: FAIL#0112#011user=test.account#011authz#011original_user=master#011auth_user=master Nov 1 14:02:34 netuno dovecot: imap-login: Debug: Ignoring unknown passdb extra field: original_user Nov 1 14:02:34 netuno dovecot: imap-login: Debug: Ignoring unknown passdb extra field: auth_user Nov 1 14:02:42 netuno dovecot: imap-login: Aborted login (auth failed, 1 attempts in 10 secs): user=, method=PLAIN, rip=10.9.8.8, lip=10.9.8.8, secured, session= doveconf -n: https://pastebin.com/3cAvfNqB root@netuno:/etc/dovecot# grep -v "^\s*#\|^\s*$" /etc/dovecot/dovecot-ldap.conf.ext hosts = ad.example.net auth_bind = yes auth_bind_userdn = cn=%Lu,CN=Users,DC=ad,DC=example,DC=net base = DC=ad,DC=example,DC=net scope = base user_attrs = \ =home=/mnt/maildirs/%Lu, \ =uid=vmail,\ =gid=vmail user_filter = (&(objectClass=person)(uid=%Lu)(mail=*@example.net)) root@netuno:/etc/dovecot# root@netuno:/etc/dovecot# cat /etc/dovecot/global-acls * user=master lr root@netuno:/etc/dovecot# (1) https://doc.dovecot.org/configuration_manual/authentication/master_users/ Best regards -- *Marcio Merlone*
Re: warning: NFS hangs with dovecot 2.3.8 on Debian buster
On 25-10-19 19:41, Jan-Pieter Cornet via dovecot wrote: We are in the process of contacting the linux-nfs folks about this, but I'm trying to reproduce this on a test-cluster first, to be able to present a well-documented case. Since this hang doesn't happen immediately, but takes a few hours to a day to occur in the wild, or a few thousand writes to the same mailbox, it's a bit hard to debug. Just FTR, I finally sent mail to the linux-nfs list about this. See eg https://marc.info/?l=linux-nfs=157260601632323=2 No replies yet - if^H^Hwhen this gets resolved I'll report back to this list. -- Jan-Pieter Cornet Systeembeheer XS4ALL Internet bv www.xs4all.nl signature.asc Description: OpenPGP digital signature
Re: Dovecot and MySQL aborted connections.
On 01/11/2019 10:16, Reio Remma via dovecot wrote: On 01/11/2019 01:19, Benjamin Connelly via dovecot wrote: during the update the log_warnings changed from 1 to 2 therefore showing lots of aborted connection notices in the logs changing the log_warnings back from 2 to 1 solved this issue Yes the same setting made the same change to the default with mysql: https://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_log-warnings So now we know how to silence the "Aborted connection" mysql loglines thank you! But still I wonder if Dovecot wants to handle these connections slightly differently - if it could be cleaner? Or is it moot? Unfortunately there are (replication info) messages that I actually need from that log level and I wouldn't want to just hide issues anyway. :) I monitored the situation in MySQL Workbench a little and it seems the userdb MySQL connection closes cleanly. What doesn't close cleanly is the dict engine MySQL connection that is updating last login timestamp (its connection shows COMMIT as the last query). The dict connection closes after sleeping exactly 60 seconds (server net_write_timeout is 60 seconds). The userdb connection closes after about 61-62 seconds for some reason. I tried changing read/write_timeout in Dovecot MySQL connection to lower, equal and higher than those set by the server, but it didn't change anything.
Re: Dovecot and MySQL aborted connections.
On 01/11/2019 01:19, Benjamin Connelly via dovecot wrote: during the update the log_warnings changed from 1 to 2 therefore showing lots of aborted connection notices in the logs changing the log_warnings back from 2 to 1 solved this issue Yes the same setting made the same change to the default with mysql: https://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_log-warnings So now we know how to silence the "Aborted connection" mysql loglines thank you! But still I wonder if Dovecot wants to handle these connections slightly differently - if it could be cleaner? Or is it moot? Unfortunately there are (replication info) messages that I actually need from that log level and I wouldn't want to just hide issues anyway. :)
Re: dovecot and ldap
-BEGIN PGP SIGNED MESSAGE- Hash: SHA512 Hi, On Thu, 2019-10-31 at 22:07 +0100, Maciej Milaszewski IQ PL via dovecot wrote: > I use dovecot+ldap So do I. It works well. > How realy works (in dovecot-2.2.x ) lists of LDAP hosts to use ? > > -- dovecot.conf > > hosts = ldap.domain.pl:389 ldap-slave.domain.pl:389 > #uris = > > > > This is simpe HA ? I mean if ldap.domain.pl have problem another request > go to ldap-slave.domain.pl ? - From https://doc.dovecot.org/configuration_manual/authentication/ldap/ : 'If multiple LDAP servers are specified, it’s decided by the LDAP library how the server connections are handled. Typically the first working server is used, and it’s never disconnected from. So there is no load balancing or automatic reconnecting to the “primary” server.' So if you want/need HA it's up to you. :) - -- Nikolai Lusan -BEGIN PGP SIGNATURE- iQIzBAEBCgAdFiEEVfd4GW6z4nsBxdLo4ZaDRV2VL6QFAl271TAACgkQ4ZaDRV2V L6T5HQ//T8DeWSpQSJ1RlrZyJr10pV1nE1aWZRr81jdOTyYy7xF+tnJmArotyqlk 9eoHsHdy2KcQeatDg8c4sA6Iad3/Iz5h1HCrRDt+jWXNtRIhn6GH0HU88umkpPIP N1Y7eVH+WAWNC+z7DmXMvvR8zTIXccrbP8Fu6CGJo/IGnh9+dcN/oX178rTYCJIB noCdkqSrb/HrnhViWMNZFlkYfwPx7SxE/NFKAla567DK7hKieUB/rKntONRpz2lb xpcLC9pW0AS/OuqzP0bpdXhDjo0E8qeu0SWpHpjKFMsTNXTcdp3hiaJgdi3jXthq gqTdDJrpt2hfPdokUfoFAWPrCXPdtMNIePn/2ZH0LqYfopaH0sG7EbPXAR9BCrtN +23y0UtZxPqwYRuMfBj0cXMNmtkB900/g0NThsEQz8FbcWtOEx928p5f///PgLW7 eTs23HBTW+f6Nl5BFhBa++wx6gwf6DwNb96KhI4Jgq7i5jHKoTt+IoeNLBl5C1vP rti69DaJIn8JVkc93S7pFStodT8jzIHRS1GVz221XnRivgLsrTMXy+J2/AFtWQUu qolaWcpJL68/a1RlkHxQqa3UJsc4qV0Qu/Mnw/aee3Q2qWo0W+9nJEBMxwqVkkBr pPiZ0OW4aj58EMTC4OoQp/2toZX4MNICnmsVhmjdBShmKsfM6YA= =18zA -END PGP SIGNATURE-
