I did try to change the service names. I posted that result to the
group. It did not make a difference.
I am not a low-level programmer so maybe have the wrong idea here, but
it seems locked on reading the imapd executable. Doesn't that suggest
a system limit of either open files or open processes? I have tried to
open up those limits as it was my first angle of investigation. What
confuses me is that the problem goes away when I switch to a
single-threaded Cyrus service listening on all ports simultaneously.
Any thoughts, suggestions welcome.
Michael
On May 24, 2017 10:42:30 PM GMT+08:00, Michael Ulitskiy
<mulitskiy@xxxxxxxxxx> wrote:
well, it tells us that it has to do with locking during connection accept.
have you tried to use different service name per server as was suggested by
others?
Michael
On Wednesday, May 24, 2017 12:00:58 PM Michael Hieb wrote:
I have had good success connecting to the right process and
can replicate the result. Here is what I found; MAILSERVER:~ #
ps auwwx|grep imapd cyrus 1738 0.0 0.0 119572 10140 ? S 03:32
0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf -s cyrus 1745 0.0 0.0 119580
9812 ? S 03:32 0:00 imapd -C /etc/imapd.domain2.com
<http://imapd.domain2.com>.conf -s cyrus 1749 0.0 0.0 119596
9856 ? S 03:32 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf cyrus 1750 0.0 0.0 129424
11500 ? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1751 0.0 0.0 119696 9988
? S 03:32 0:00 imapd -C /etc/imapd.domain5.com
<http://imapd.domain5.com>.conf cyrus 1752 0.0 0.0 119596 9816
? S 03:32 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 1753 0.0 0.0 119604 9964
? S 03:32 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf cyrus 1754 0.0 0.0 119596 9652
? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1755 0.0 0.0 119596 9800
? S 03:32 0:00 imapd -C /etc/imapd.domain5.com
<http://imapd.domain5.com>.conf cyrus 1756 0.0 0.0 119604
10056 ? S 03:32 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 1757 0.0 0.0 129564
11724 ? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1758 0.0 0.0 119512 9896
? S 03:33 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf -s cyrus 1766 0.0 0.0 119588
9904 ? S 03:33 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf -s cyrus 1767 0.0 0.0 119576
9804 ? S 03:33 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf -s cyrus 1778 0.0 0.0 119480
9936 ? S 03:33 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf -s cyrus 1786 0.0 0.0 119768
10144 ? S 03:33 0:00 imapd -C /etc/imapd.domain5.com
<http://imapd.domain5.com>.conf cyrus 1881 0.0 0.0 119808
10080 ? S 03:34 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1912 0.0 0.0 119688 9868
? S 03:36 0:00 imapd -C /etc/imapd.domain2.com
<http://imapd.domain2.com>.conf cyrus 1937 0.0 0.0 119784
10216 ? S 03:38 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf cyrus 1947 0.0 0.0 125872
10660 ? S 03:39 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1993 0.0 0.0 119604 9808
? S 03:42 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 2078 0.0 0.0 117044 7628
? S 03:48 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf root 2080 0.0 0.0 10548 1656
pts/2 S+ 03:48 0:00 grep --color=auto imapd Then try to
connect: user@somesystem:~> telnet imap.domain2.com
<http://imap.domain2.com> 143 Trying 192.168.110.175
<http://192.168.110.175>... Connected to imap.domain2.com
<http://imap.domain2.com>. Escape character is '^]'. Then
mailserver is the same except one new process at the end:
MAILSERVER:~ # ps auwwx|grep imapd cyrus 1738 0.0 0.0 119572
10140 ? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf -s cyrus 1745 0.0 0.0 119580
9812 ? S 03:32 0:00 imapd -C /etc/imapd.domain2.com
<http://imapd.domain2.com>.conf -s cyrus 1749 0.0 0.0 119596
9856 ? S 03:32 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf cyrus 1750 0.0 0.0 129424
11500 ? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1751 0.0 0.0 119696 9988
? S 03:32 0:00 imapd -C /etc/imapd.domain5.com
<http://imapd.domain5.com>.conf cyrus 1752 0.0 0.0 119596 9816
? S 03:32 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 1753 0.0 0.0 119604 9964
? S 03:32 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf cyrus 1754 0.0 0.0 119596 9652
? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1755 0.0 0.0 119596 9800
? S 03:32 0:00 imapd -C /etc/imapd.domain5.com
<http://imapd.domain5.com>.conf cyrus 1756 0.0 0.0 119604
10056 ? S 03:32 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 1757 0.0 0.0 129564
11724 ? S 03:32 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1758 0.0 0.0 119512 9896
? S 03:33 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf -s cyrus 1766 0.0 0.0 119588
9904 ? S 03:33 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf -s cyrus 1767 0.0 0.0 119576
9804 ? S 03:33 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf -s cyrus 1778 0.0 0.0 119480
9936 ? S 03:33 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf -s cyrus 1786 0.0 0.0 119768
10144 ? S 03:33 0:00 imapd -C /etc/imapd.domain5.com
<http://imapd.domain5.com>.conf cyrus 1881 0.0 0.0 119808
10080 ? S 03:34 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1912 0.0 0.0 119688 9868
? S 03:36 0:00 imapd -C /etc/imapd.domain2.com
<http://imapd.domain2.com>.conf cyrus 1937 0.0 0.0 119784
10216 ? S 03:38 0:00 imapd -C /etc/imapd.domain3.com
<http://imapd.domain3.com>.conf cyrus 1947 0.0 0.0 125872
10660 ? S 03:39 0:00 imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf cyrus 1993 0.0 0.0 119604 9808
? S 03:42 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 2078 0.0 0.0 117044 7628
? S 03:48 0:00 imapd -C /etc/imapd.domain4.com
<http://imapd.domain4.com>.conf cyrus 2120 0.0 0.0 117044 7628
? S 03:48 0:00 imapd -C /etc/imapd.domain2.com
<http://imapd.domain2.com>.conf root 2122 0.0 0.0 10548 1656
pts/2 S+ 03:48 0:00 grep --color=auto imapd MAILSERVER:~ #
strace -p 2120 Process 2120 attached fcntl(13, F_SETLKW,
{type=F_WRLCK, whence=SEEK_SET, start=0, len=0} Process hangs,
nothing happening... then about 45 seconds later (in this case
- time to wait varies each time I try this) it frees itself
and strace shows this: MAILSERVER:~ # strace -p 2120 Process
2120 attached fcntl(13, F_SETLKW, {type=F_WRLCK,
whence=SEEK_SET, start=0, len=0}) = 0
stat("/usr/lib/cyrus/bin/imapd", {st_mode=S_IFREG|0755,
st_size=1758976, ...}) = 0 accept(4, 0, NULL) = 14 fcntl(13,
F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 0 getpeername(14, {sa_family=AF_INET,
sin_port=htons(43778), sin_addr=inet_addr("192.168.110.27
<http://192.168.110.27>")}, [16]) = 0 getpeername(14,
{sa_family=AF_INET, sin_port=htons(43778),
sin_addr=inet_addr("192.168.110.27 <http://192.168.110.27>")},
[16]) = 0 getsockname(14, {sa_family=AF_INET,
sin_port=htons(143), sin_addr=inet_addr("192.168.110.174
<http://192.168.110.174>")}, [16]) = 0
open("/etc/hosts.allow", O_RDONLY|O_CLOEXEC) = 15 fstat(15,
{st_mode=S_IFREG|0644, st_size=2639, ...}) = 0 mmap(NULL,
4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x7ff634095000 read(15, "# /etc/hosts.allow\n# See 'man
tc"..., 4096) = 2639 read(15, "", 4096) = 0 close(15) = 0
munmap(0x7ff634095000, 4096) = 0 open("/etc/hosts.deny",
O_RDONLY|O_CLOEXEC) = 15 fstat(15, {st_mode=S_IFREG|0644,
st_size=149, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff634095000 read(15, "#
/etc/hosts.deny\n# See 'man tcp"..., 4096) = 149 read(15, "",
4096) = 0 close(15) = 0 munmap(0x7ff634095000, 4096) = 0
write(3, "\2\0\0\0H\10\0\0", 8) = 8 sendto(6, "<31>May 24
03:56:21 imap[2120]: "..., 51, MSG_NOSIGNAL, NULL, 0) = 51
dup2(14, 0) = 0 dup2(14, 1) = 1 dup2(14, 2) = 2 close(14) = 0
write(3, "\3\0\0\0H\10\0\0", 8) = 8 getpeername(0,
{sa_family=AF_INET, sin_port=htons(43778),
sin_addr=inet_addr("192.168.110.27 <http://192.168.110.27>")},
[16]) = 0 socket(PF_LOCAL,
SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 14 connect(14,
{sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) =
0 sendto(14, "\2\0\0\0\r\0\0\0\6\0\0\0hosts\0", 18,
MSG_NOSIGNAL, NULL, 0) = 18 poll([{fd=14,
events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=14,
revents=POLLIN|POLLHUP}]) recvmsg(14, {msg_name(0)=NULL,
msg_iov(2)=[{"hosts\0", 6}, {"\310O\3\0\0\0\0\0", 8}],
msg_controllen=20, [{cmsg_len=20, cmsg_level=SOL_SOCKET,
cmsg_type=SCM_RIGHTS, [15]}], msg_flags=MSG_CMSG_CLOEXEC},
MSG_CMSG_CLOEXEC) = 14 mmap(NULL, 217032, PROT_READ,
MAP_SHARED, 15, 0) = 0x7ff634021000 close(15) = 0 close(14) =
0 getsockname(0, {sa_family=AF_INET, sin_port=htons(143),
sin_addr=inet_addr("192.168.110.174
<http://192.168.110.174>")}, [16]) = 0
open("/var/lib/imap/proc/2120", O_RDWR|O_CREAT|O_TRUNC, 0666)
= 14 fstat(14, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff634095000 lseek(14,
0, SEEK_SET) = 0 write(14, "somehost.domain1.com
<http://somehost.domain1.com> [192.168.110.2
<http://192.168.110.2>"..., 35) = 35 lseek(14, 0, SEEK_CUR) =
35 ftruncate(14, 35) = 0 open("/var/lib/imap/msg/motd",
O_RDONLY) = -1 ENOENT (No such file or directory) write(1, "*
OK [CAPABILITY IMAP4rev1 LITER"..., 199) = 199 select(1, [0],
NULL, NULL, {1800, 0} and telnet session shows this:
user@somesystem:~> telnet imap.domain2.com
<http://imap.domain2.com> 143 Trying 192.168.110.175
<http://192.168.110.175>... Connected to imap.domain2.com
<http://imap.domain2.com>. Escape character is '^]'. * OK
[CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE STARTTLS
AUTH=GSS-SPNEGO AUTH=GSSAPI AUTH=DIGEST-MD5 AUTH=CRAM-MD5
AUTH=LOGIN AUTH=PLAIN SASL-IR] imap.domain2.com
<http://imap.domain2.com> Cyrus IMAP v2.4.18 server ready
Thereafter telnet to imap.domain2.com
<http://imap.domain2.com> has immediate response and other
domains hang.. I can replicate this at will. What does it
mean? Michael On 05/23/2017 10:38 PM, Michael Ulitskiy wrote:
you can use 'strace -p <pid>', specifying the pid of
process you want to trace. you will have to "catch" the
process that blocks. it may not be easy, but I have no
other suggestions. On Tuesday, May 23, 2017 06:19:17 PM
Michael Hieb wrote:
The SASL is cyrus-sasl 2.1.26-9.5. I believe it does
use /dev/urandom. I am not sure how to run strace on
the process that the Master listener forks. Here is
the strace run on the imapd process at a command
prompt (which is not quite the same as the master
listener forking it to a port where another process is
waiting to connect to it). MAILSERVER:~ # strace
/usr/lib/cyrus/bin/imapd -C /etc/imapd.domain1.com
<http://imapd.domain1.com>.conf
execve("/usr/lib/cyrus/bin/imapd",
["/usr/lib/cyrus/bin/imapd", "-C",
"/etc/imapd.domain1.com
<http://imapd.domain1.com>.conf"], [/* 56 vars */]) =
0 brk(0) = 0x5573deaf5000 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb770c000 access("/etc/ld.so
<http://ld.so>.preload", R_OK) = -1 ENOENT (No such
file or directory) open("/etc/ld.so
<http://ld.so>.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=80522, ...}) =
0 mmap(NULL, 80522, PROT_READ, MAP_PRIVATE, 3, 0) =
0x7fdeb76f8000 close(3) = 0
open("/usr/lib64/libsasl2.so <http://libsasl2.so>.3",
O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300N\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=118552, ...}) = 0 mmap(NULL, 2213800,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb72d0000 mprotect(0x7fdeb72ec000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb74eb000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) =
0x7fdeb74eb000 close(3) = 0
open("/usr/lib64/libkrb5.so <http://libkrb5.so>.3",
O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200Y\2\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=855280, ...}) = 0 mmap(NULL, 2951008,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb6fff000 mprotect(0x7fdeb70c1000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb72c0000, 65536,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xc1000) =
0x7fdeb72c0000 close(3) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f7000 open("/lib64/libcom_err.so
<http://err.so>.2", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\26\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=14760, ...}) = 0 mmap(NULL, 2109928,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb6dfb000 mprotect(0x7fdeb6dfe000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb6ffd000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) =
0x7fdeb6ffd000 close(3) = 0 open("/lib64/libssl.so
<http://libssl.so>.1.0.0", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0pr\1\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0555,
st_size=440632, ...}) = 0 mmap(NULL, 2535888,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb6b8f000 mprotect(0x7fdeb6bf0000, 2097152,
PROT_NONE) = 0 mmap(0x7fdeb6df0000, 45056,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x61000) =
0x7fdeb6df0000 close(3) = 0 open("/lib64/libcrypto.so
<http://libcrypto.so>.1.0.0", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\313\6\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0555,
st_size=2447744, ...}) = 0 mmap(NULL, 4559184,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb6735000 mprotect(0x7fdeb6962000, 2097152,
PROT_NONE) = 0 mmap(0x7fdeb6b62000, 167936,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22d000) =
0x7fdeb6b62000 mmap(0x7fdeb6b8b000, 12624,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb6b8b000 close(3) = 0
open("/usr/lib64/libdb-4.8.so <http://libdb-4.8.so>",
O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@X\2\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=1560248, ...}) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f6000 mmap(NULL, 3655304,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb63b8000 mprotect(0x7fdeb6530000, 2097152,
PROT_NONE) = 0 mmap(0x7fdeb6730000, 20480,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x178000) =
0x7fdeb6730000 close(3) = 0 open("/lib64/libz.so
<http://libz.so>.1", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P#\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=88216, ...}) = 0 mmap(NULL, 2183304,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb61a2000 mprotect(0x7fdeb61b7000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb63b6000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14000) =
0x7fdeb63b6000 close(3) = 0 open("/lib64/libwrap.so
<http://libwrap.so>.0", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p8\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=40952, ...}) = 0 mmap(NULL, 2139520,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb5f97000 mprotect(0x7fdeb5fa0000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb619f000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x8000) =
0x7fdeb619f000 mmap(0x7fdeb61a1000, 1408,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb61a1000 close(3) = 0 open("/lib64/libc.so
<http://libc.so>.6", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\10\2\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=1925280, ...}) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f5000 mmap(NULL, 3811872,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb5bf4000 mprotect(0x7fdeb5d8e000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb5f8d000, 24576,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x199000) =
0x7fdeb5f8d000 mmap(0x7fdeb5f93000, 14880,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb5f93000 close(3) = 0 open("/lib64/libdl.so
<http://libdl.so>.2", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\r\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=18712, ...}) = 0 mmap(NULL, 2109680,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb59f0000 mprotect(0x7fdeb59f2000, 2097152,
PROT_NONE) = 0 mmap(0x7fdeb5bf2000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) =
0x7fdeb5bf2000 close(3) = 0
open("/usr/lib64/libk5crypto.so
<http://libk5crypto.so>.3", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340K\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=191424, ...}) = 0 mmap(NULL, 2290168,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb57c0000 mprotect(0x7fdeb57ed000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb59ec000, 12288,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2c000) =
0x7fdeb59ec000 mmap(0x7fdeb59ef000, 504,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb59ef000 close(3) = 0
open("/usr/lib64/libkrb5support.so
<http://libkrb5support.so>.0", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20:\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=52416, ...}) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f4000 mmap(NULL, 2147816,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb55b3000 mprotect(0x7fdeb55bf000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb57be000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xb000) =
0x7fdeb57be000 close(3) = 0
open("/lib64/libkeyutils.so
<http://libkeyutils.so>.1", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\26\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=14688, ...}) = 0 mmap(NULL, 2109704,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb53af000 mprotect(0x7fdeb53b2000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb55b1000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) =
0x7fdeb55b1000 close(3) = 0 open("/lib64/libresolv.so
<http://libresolv.so>.2", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\2209\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=97152, ...}) = 0 mmap(NULL, 2189896,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb5198000 mprotect(0x7fdeb51ac000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb53ab000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13000) =
0x7fdeb53ab000 mmap(0x7fdeb53ad000, 6728,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb53ad000 close(3) = 0 open("/lib64/libpthread.so
<http://libpthread.so>.0", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360r\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=135952, ...}) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f3000 mmap(NULL, 2213008,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb4f7b000 mprotect(0x7fdeb4f93000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb5192000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) =
0x7fdeb5192000 mmap(0x7fdeb5194000, 13456,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb5194000 close(3) = 0 open("/lib64/libselinux.so
<http://libselinux.so>.1", O_RDONLY|O_CLOEXEC) = 3
read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0ps\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=147208, ...}) = 0 mmap(NULL, 2251056,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb4d55000 mprotect(0x7fdeb4d78000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb4f77000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) =
0x7fdeb4f77000 mmap(0x7fdeb4f79000, 6448,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) =
0x7fdeb4f79000 close(3) = 0
open("/usr/lib64/libpcre.so <http://libpcre.so>.1",
O_RDONLY|O_CLOEXEC) = 3 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\30\0\0\0\0\0\0"...,
832) = 832 fstat(3, {st_mode=S_IFREG|0755,
st_size=452976, ...}) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f2000 mmap(NULL, 2548232,
PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x7fdeb4ae6000 mprotect(0x7fdeb4b54000, 2093056,
PROT_NONE) = 0 mmap(0x7fdeb4d53000, 8192,
PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) =
0x7fdeb4d53000 close(3) = 0 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f1000 mmap(NULL, 4096,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76f0000 mmap(NULL, 8192,
PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fdeb76ee000 arch_prctl(ARCH_SET_FS,
0x7fdeb76ee840) = 0 mprotect(0x7fdeb5f8d000, 16384,
PROT_READ) = 0 mprotect(0x7fdeb5192000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb4d53000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb5bf2000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb4f77000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb53ab000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb55b1000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb57be000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb59ec000, 8192,
PROT_READ) = 0 mprotect(0x7fdeb619f000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb63b6000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb6730000, 8192,
PROT_READ) = 0 mprotect(0x7fdeb6b62000, 110592,
PROT_READ) = 0 mprotect(0x7fdeb6df0000, 16384,
PROT_READ) = 0 mprotect(0x7fdeb6ffd000, 4096,
PROT_READ) = 0 mprotect(0x7fdeb72c0000, 53248,
PROT_READ) = 0 mprotect(0x7fdeb74eb000, 4096,
PROT_READ) = 0 mprotect(0x5573dd954000, 8192,
PROT_READ) = 0 mprotect(0x7fdeb770d000, 4096,
PROT_READ) = 0 munmap(0x7fdeb76f8000, 80522) = 0
set_tid_address(0x7fdeb76eeb10) = 18042
set_robust_list(0x7fdeb76eeb20, 24) = 0
rt_sigaction(SIGRTMIN, {0x7fdeb4f81d80, [],
SA_RESTORER|SA_SIGINFO, 0x7fdeb4f8bb10}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x7fdeb4f81e10, [],
SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7fdeb4f8bb10},
NULL, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1],
NULL, 8) = 0 getrlimit(RLIMIT_STACK,
{rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
statfs("/sys/fs/selinux", 0x7ffe1b4e8b00) = -1 ENOENT
(No such file or directory) statfs("/selinux",
{f_type="EXT2_SUPER_MAGIC", f_bsize=4096,
f_blocks=474903111, f_bfree=452714842,
f_bavail=452228240, f_files=120627200,
f_ffree=120300880, f_fsi\ d={352889743, -1913047647},
f_namelen=255, f_frsize=4096}) = 0 brk(0) =
0x5573deaf5000 brk(0x5573deb16000) = 0x5573deb16000
open("/proc/filesystems", O_RDONLY) = 3 fstat(3,
{st_mode=S_IFREG|0444, st_size=0, ...}) = 0 mmap(NULL,
4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7fdeb770b000 read(3,
"nodev\tsysfs\nnodev\trootfs\nnodev\tr"..., 1024) =
297 read(3, "", 1024) = 0 close(3) = 0
munmap(0x7fdeb770b000, 4096) = 0
access("/etc/selinux/config", F_OK) = -1 ENOENT (No
such file or directory) stat("/dev/urandom",
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 open("/dev/urandom", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\355\207\254Q\253\17d\266\22x\324\257
\236\205H\327b\32\221nzmx\251\216D\257J\362\301\357"...,
60) = 60 close(3) = 0 open("/dev/urandom",
O_RDONLY|O_NOCTTY|O_NONBLOCK|O_CLOEXEC) = 3 fstat(3,
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 poll([{fd=3, events=POLLIN}], 1, 10) = 1 ([{fd=3,
revents=POLLIN}]) read(3,
"r\324\5\243C\224\n\222d\333\25\25\2738\7\ts\351\3759\265\207&\n\251}\316
\20 5\224v\17\253"..., 1024) = 1024 close(3) = 0
getuid() = 0 stat("/dev/urandom",
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 open("/dev/urandom", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\3323i\236\226J\353\241\201\213\20\30\201b<\371\5\246\234\230",
20) = 20 close(3) = 0 stat("/dev/urandom",
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 open("/dev/urandom", O_RDONLY|O_CLOEXEC) = 3 read(3,
"u2V%3\367\276\251\202$\376_\1\365r`N^\5?\303H\330\3173i\335\247]A\222\37
6". .., 256) = 256 close(3) = 0 stat("/dev/urandom",
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 open("/dev/urandom", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\333_\2\335]:\7\"\373s]\352\375\305\312t\244.@;\245\345\245^(\262d\350\2
73[ \327-"..., 216) = 216 close(3) = 0
stat("/dev/urandom", {st_mode=S_IFCHR|0666,
st_rdev=makedev(1, 9), ...}) = 0 open("/dev/urandom",
O_RDONLY|O_CLOEXEC) = 3 read(3, "\207", 1) = 1
close(3) = 0 stat("/dev/urandom",
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 open("/dev/urandom", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\332", 1) = 1 close(3) = 0 stat("/dev/urandom",
{st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) =
0 open("/dev/urandom", O_RDONLY|O_CLOEXEC) = 3 read(3,
"\22\335\242$\210`\376\376d\200\215m\213-\0162\r\257\206\335\nY\343\3376/
\22 4\352\360\312\336\360", 32) = 32 close(3) = 0
stat("/dev/urandom", {st_mode=S_IFCHR|0666,
st_rdev=makedev(1, 9), ...}) = 0 open("/dev/urandom",
O_RDONLY|O_CLOEXEC) = 3 read(3,
"U\2\251M\21fm\345\334\215Q1(\253\1M!\270\226\212s&A\263}\351\16\271",
28) = 28 close(3) = 0 futex(0x7fdeb5bf30a8,
FUTEX_WAKE_PRIVATE, 2147483647) = 0
open("/lib64/.libcrypto.so
<http://libcrypto.so>.1.0.0.hmac", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/proc/sys/crypto/fips_enabled", O_RDONLY) = -1
ENOENT (No such file or directory)
access("/lib64/.libcrypto.so
<http://libcrypto.so>.1.0.0.hmac", F_OK) = -1 ENOENT
(No such file or directory) open("/etc/localtime",
O_RDONLY|O_CLOEXEC) = 3 fstat(3,
{st_mode=S_IFREG|0644, st_size=127, ...}) = 0 fstat(3,
{st_mode=S_IFREG|0644, st_size=127, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fdeb770b000
read(3,
"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0\0\0\0"...,
4096) = 127 lseek(3, -71, SEEK_CUR) = 56 read(3,
"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0\0\0\0"...,
4096) = 71 close(3) = 0 munmap(0x7fdeb770b000, 4096) =
0 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 3
connect(3, {sa_family=AF_LOCAL, sun_path="/dev/log"},
110) = 0 sendto(3, "<11>May 23 10:11:18 imapd:
could"..., 67, MSG_NOSIGNAL, NULL, 0) = 67
exit_group(70) = ? +++ exited with 70 +++ Michael On
05/19/2017 05:55 PM, Michael Ulitskiy wrote: Msg #
57050 Previous in Sequence
<http://asg.andrew.cmu.edu/archive/message.php?mailbox=archive.info-cyrus
&ms g=57374> Date Fri, 19 May 2017 11:32:38 -0400 To
info-cyrus@xxxxxxxxxxxxxxxxxxxx From Michael Ulitskiy
<mulitskiy@xxxxxxxxxx> Reply-To: Michael Ulitskiy
<mulitskiy@xxxxxxxxxx> Subject Re: Multi-thread cyrus
delayed forking of imapd processes after connecting to
master listener My immediate guess is it blocks at
reading /dev/random. strace should show you exactly
where it blocks. What version of SASL are you using?
Newer versions have switched to /dev/urandom AFAIK
Michael On Friday, May 19, 2017 05:48:36 PM Michael
Hieb wrote:
Apologies for long post, most of it is
configuration details. I have recently changed
from a single threaded cyrus server in which
multiple domains were overloaded on one listener
as multiple virtual domains to a multiple threaded
cyrus server in which multiple domains are
listened for on separate ip addresses with
separate configurations. The primary motivation
was to have separate tls certificates for each
domain. The problem is that I can connect to cyrus
listener on all ip/ports for all domains, but
while one of them will fork immediately and
respond with a banner, the others will delay for a
period of time from a few seconds to a minute or
so before forking and responding with a banner.
With the same setup, I change to a single threaded
cyrus server to listen on all ip/ports then I get
an immediate response on all, but of course I do
not get the separate tls certificate or
configuration. It is replicable that switching
between the single threaded and multiple threaded
configuration triggers the problem. I have
searched the logs and the mail-lists and found
nothing that seems related. Question: why does
switching to multiple threaded cyrus server
trigger delayed forking of imapd processes after
connecting to master listener? On listener which
responds immediately (as expected) I get this:
user@somehost:~> telnet imap.domain1.com
<http://imap.domain1.com> 143 Trying
192.168.110.171 <http://192.168.110.171>...
Connected to imap.domain1.com
<http://imap.domain1.com>. Escape character is
'^]'. * OK [CAPABILITY IMAP4rev1 LITERAL+ ID
ENABLE STARTTLS AUTH=GSS-SPNEGO AUTH=GSSAPI
AUTH=DIGEST-MD5 AUTH=CRAM-MD5 AUTH=LOGIN
AUTH=PLAIN SASL-IR] imap.domain1.com
<http://imap.domain1.com> Cyrus IMAP v2.4.18
server ready On listener with delay, I get this
(and process hangs for many seconds or even a
minute or two): user@somehost:~> telnet
imap.domain2.com <http://imap.domain2.com> 143
Trying 192.168.110.171 <http://192.168.110.171>...
Connected to imap.domain2.com
<http://imap.domain2.com>. Escape character is
'^]'. The domain for which the listener responds
and the one for which it delays seems to change
and be random as far as I can tell. There is nothing
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.
