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.conf -s
cyrus 1745 0.0 0.0 119580 9812 ? S 03:32 0:00 imapd
-C /etc/imapd.domain2.com.conf -s
cyrus 1749 0.0 0.0 119596 9856 ? S 03:32 0:00 imapd
-C /etc/imapd.domain3.com.conf
cyrus 1750 0.0 0.0 129424 11500 ? S 03:32 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1751 0.0 0.0 119696 9988 ? S 03:32 0:00 imapd
-C /etc/imapd.domain5.com.conf
cyrus 1752 0.0 0.0 119596 9816 ? S 03:32 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 1753 0.0 0.0 119604 9964 ? S 03:32 0:00 imapd
-C /etc/imapd.domain3.com.conf
cyrus 1754 0.0 0.0 119596 9652 ? S 03:32 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1755 0.0 0.0 119596 9800 ? S 03:32 0:00 imapd
-C /etc/imapd.domain5.com.conf
cyrus 1756 0.0 0.0 119604 10056 ? S 03:32 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 1757 0.0 0.0 129564 11724 ? S 03:32 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1758 0.0 0.0 119512 9896 ? S 03:33 0:00 imapd
-C /etc/imapd.domain1.com.conf -s
cyrus 1766 0.0 0.0 119588 9904 ? S 03:33 0:00 imapd
-C /etc/imapd.domain3.com.conf -s
cyrus 1767 0.0 0.0 119576 9804 ? S 03:33 0:00 imapd
-C /etc/imapd.domain3.com.conf -s
cyrus 1778 0.0 0.0 119480 9936 ? S 03:33 0:00 imapd
-C /etc/imapd.domain1.com.conf -s
cyrus 1786 0.0 0.0 119768 10144 ? S 03:33 0:00 imapd
-C /etc/imapd.domain5.com.conf
cyrus 1881 0.0 0.0 119808 10080 ? S 03:34 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1912 0.0 0.0 119688 9868 ? S 03:36 0:00 imapd
-C /etc/imapd.domain2.com.conf
cyrus 1937 0.0 0.0 119784 10216 ? S 03:38 0:00 imapd
-C /etc/imapd.domain3.com.conf
cyrus 1947 0.0 0.0 125872 10660 ? S 03:39 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1993 0.0 0.0 119604 9808 ? S 03:42 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 2078 0.0 0.0 117044 7628 ? S 03:48 0:00 imapd
-C /etc/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 143
Trying 192.168.110.175...
Connected to 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.conf -s
cyrus 1745 0.0 0.0 119580 9812 ? S 03:32 0:00 imapd
-C /etc/imapd.domain2.com.conf -s
cyrus 1749 0.0 0.0 119596 9856 ? S 03:32 0:00 imapd
-C /etc/imapd.domain3.com.conf
cyrus 1750 0.0 0.0 129424 11500 ? S 03:32 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1751 0.0 0.0 119696 9988 ? S 03:32 0:00 imapd
-C /etc/imapd.domain5.com.conf
cyrus 1752 0.0 0.0 119596 9816 ? S 03:32 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 1753 0.0 0.0 119604 9964 ? S 03:32 0:00 imapd
-C /etc/imapd.domain3.com.conf
cyrus 1754 0.0 0.0 119596 9652 ? S 03:32 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1755 0.0 0.0 119596 9800 ? S 03:32 0:00 imapd
-C /etc/imapd.domain5.com.conf
cyrus 1756 0.0 0.0 119604 10056 ? S 03:32 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 1757 0.0 0.0 129564 11724 ? S 03:32 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1758 0.0 0.0 119512 9896 ? S 03:33 0:00 imapd
-C /etc/imapd.domain1.com.conf -s
cyrus 1766 0.0 0.0 119588 9904 ? S 03:33 0:00 imapd
-C /etc/imapd.domain3.com.conf -s
cyrus 1767 0.0 0.0 119576 9804 ? S 03:33 0:00 imapd
-C /etc/imapd.domain3.com.conf -s
cyrus 1778 0.0 0.0 119480 9936 ? S 03:33 0:00 imapd
-C /etc/imapd.domain1.com.conf -s
cyrus 1786 0.0 0.0 119768 10144 ? S 03:33 0:00 imapd
-C /etc/imapd.domain5.com.conf
cyrus 1881 0.0 0.0 119808 10080 ? S 03:34 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1912 0.0 0.0 119688 9868 ? S 03:36 0:00 imapd
-C /etc/imapd.domain2.com.conf
cyrus 1937 0.0 0.0 119784 10216 ? S 03:38 0:00 imapd
-C /etc/imapd.domain3.com.conf
cyrus 1947 0.0 0.0 125872 10660 ? S 03:39 0:00 imapd
-C /etc/imapd.domain1.com.conf
cyrus 1993 0.0 0.0 119604 9808 ? S 03:42 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 2078 0.0 0.0 117044 7628 ? S 03:48 0:00 imapd
-C /etc/imapd.domain4.com.conf
cyrus 2120 0.0 0.0 117044 7628 ? S 03:48 0:00 imapd
-C /etc/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")}, [16]) = 0
getpeername(14, {sa_family=AF_INET, sin_port=htons(43778),
sin_addr=inet_addr("192.168.110.27")}, [16]) = 0
getsockname(14, {sa_family=AF_INET, sin_port=htons(143),
sin_addr=inet_addr("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")}, [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")}, [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 [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 143
Trying 192.168.110.175...
Connected to 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 Cyrus IMAP v2.4.18 server ready
Thereafter telnet to 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.conf
execve("/usr/lib/cyrus/bin/imapd", ["/usr/lib/cyrus/bin/imapd", "-C",
"/etc/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.preload", R_OK) = -1 ENOENT (No such file or
directory)
open("/etc/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.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.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.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.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.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", 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.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.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.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.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.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.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.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.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.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.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.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.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.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 143
Trying 192.168.110.171...
Connected to 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 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 143
Trying 192.168.110.171...
Connected to 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.
---- Cyrus Home Page: http://www.cyrusimap.org/ List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/ To Unsubscribe: https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus
