Imaptest stall

Marc Roos M.Roos at f1-outsourcing.eu
Wed Sep 18 11:23:06 EEST 2019 

 

I am not able to conclude that yet because my 'base' test against the 
mbox already stalls. I also have to empty the mailbox/folder before 
testing, to get a better chance of finishing the test. So maybe it is 
related to some 'reading' being done in the append test?
Below test results from a 1s, 2s, 3s test that finish and a 4s test that 
stalls.



mail_location = 
mbox:~/mail:INBOX=/var/spool/mail/%u:CONTROL=~/mail/control:INDEX=/var/d
ovecot/%u/index:LAYOUT=maildir++



== test 1s finishes ==
[@mail04 ~]# ./imaptest - append=100,0 logout=0 host=192.168.x.x 
port=143 user=test2 pass=testtest  secs=1 clients=1 mbox=64kb.mbox 
box=INBOX/test
Logi Sele Appe
100% 100% 100%
   1    1    7   1/  1
  38    0  773 ms/cmd avg

Totals:
Logi Sele Appe
100% 100% 100%
   1    1   17
   
Sep 18 09:46:06 mail04 dovecot: imap(test2): Debug: Namespace inbox: 
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, 
subscriptions=yes 
location=mbox:~/mail:INBOX=/var/spool/mail/test2:CONTROL=~/mail/control:
INDEX=/var/dovecot/test2/index:LAYOUT=maildir++
Sep 18 09:46:06 mail04 dovecot: imap(test2): Debug: maildir++: 
=/home/popusers/test2/mail, index=/var/dovecot/test2/index, indexpvt=, 
control=/home/popusers/test2/mail/control, inbox=/var/spool/mail/test2, 
alt=
Sep 18 09:46:06 mail04 dovecot: imap(test2): Debug: INBOX/test: Mailbox 
opened because: SELECT
Sep 18 09:46:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=378 because: full mail
Sep 18 09:46:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=375 because: full mail
Sep 18 09:46:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=377 because: full mail
Sep 18 09:46:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=376 because: full mail
Sep 18 09:46:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=379 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Logged out in=1504944 
out=2958
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=386 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=381 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=380 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=384 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=387 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=385 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=382 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=388 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=389 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=391 because: full mail
Sep 18 09:46:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=390 because: full mail
Sep 18 09:46:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=383 because: full mail


== test 2s finishes ==
[@mail04 ~]# ./imaptest - append=100,0 logout=0 host=192.168.x.x 
port=143 user=test2 pass=testtest  secs=2 clients=1 mbox=64kb.mbox 
box=INBOX/test
Logi Sele Appe
100% 100% 100%
   1    1    6   1/  1
   0    0    7   1/  1
  58   84 1025 ms/cmd avg

Totals:
Logi Sele Appe
100% 100% 100%
   1    1   23


Sep 18 09:51:11 mail04 dovecot: auth: Debug: Loading modules from 
directory: /usr/lib64/dovecot/auth
Sep 18 09:51:11 mail04 dovecot: auth: Debug: Module loaded: 
/usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
Sep 18 09:51:11 mail04 dovecot: auth: Debug: Module loaded: 
/usr/lib64/dovecot/auth/libdriver_sqlite.so
Sep 18 09:51:11 mail04 dovecot: auth: Debug: Read auth token secret from 
/var/run/dovecot/auth-token-secret.dat
Sep 18 09:51:11 mail04 dovecot: auth: Debug: passwd-file 
/etc/dovecot/special-userdb: Read 2 users in 0 secs
Sep 18 09:51:11 mail04 dovecot: auth: Debug: auth client connected 
(pid=14466)
Sep 18 09:51:11 mail04 dovecot: auth: Debug: client in: 
AUTH#0113#011PLAIN#011service=imap#011secured#011session=yBa9Gc+SBMvAqAo
s#011lip=192.168.x.x#011rip=192.168.x.x#011lport=143#011rport=51972#011r
esp=<hidden>
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: Loading 
modules from directory: /usr/lib64/dovecot/auth
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: Module 
loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: Module 
loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: passwd-file 
/etc/dovecot/special-userdb: Read 2 users in 0 secs
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: 
pam(test2,192.168.x.x,<yBa9Gc+SBMvAqAos>): lookup service=dovecot
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: 
pam(test2,192.168.x.x,<yBa9Gc+SBMvAqAos>): #1/1 style=1 msg=Password:
Sep 18 09:51:11 mail04 dovecot: auth: Debug: client passdb out: 
OK#0113#011user=test2
Sep 18 09:51:11 mail04 dovecot: auth: Debug: master in: 
REQUEST#0111459879937#01114466#0113#0116a575944e89decb8e2ec49ca7bad1915#
011session_pid=14531#011request_auth_token
Sep 18 09:51:11 mail04 dovecot: auth: Debug: 
passwd-file(test2,192.168.x.x,<yBa9Gc+SBMvAqAos>): lookup: user=test2 
file=/etc/dovecot/special-userdb
Sep 18 09:51:11 mail04 dovecot: auth: 
passwd-file(test2,192.168.x.x,<yBa9Gc+SBMvAqAos>): unknown user
Sep 18 09:51:11 mail04 dovecot: auth: Debug: 
passwd(test2,192.168.x.x,<yBa9Gc+SBMvAqAos>): userdb cache miss
Sep 18 09:51:11 mail04 dovecot: auth-worker(14530): Debug: 
passwd(test2,192.168.x.x,<yBa9Gc+SBMvAqAos>): lookup
Sep 18 09:51:11 mail04 dovecot: auth: Debug: master userdb out: 
USER#0111459879937#011test2#011system_groups_user=test2#011uid=8496#011g
id=231#011home=/home/popusers/test2#011auth_token=c04c9e15e4068ab99fdff4
2b193f82248e070de1
Sep 18 09:51:11 mail04 dovecot: imap-login: Login: user=<test2>, 
method=PLAIN, rip=192.168.x.x, lip=192.168.x.x, mpid=14531, secured, 
session=<yBa9Gc+SBMvAqAos>
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: Loading modules from 
directory: /usr/lib64/dovecot
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/lib15_notify_plugin.so
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/lib20_listescape_plugin.so
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/libstorage_rbox_plugin.so
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: Effective uid=8496, 
gid=231, home=/home/popusers/test2
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: Namespace inbox: 
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, 
subscriptions=yes 
location=mbox:~/mail:INBOX=/var/spool/mail/test2:CONTROL=~/mail/control:
INDEX=/var/dovecot/test2/index:LAYOUT=maildir++
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: maildir++: 
=/home/popusers/test2/mail, index=/var/dovecot/test2/index, indexpvt=, 
control=/home/popusers/test2/mail/control, inbox=/var/spool/mail/test2, 
alt=
Sep 18 09:51:11 mail04 dovecot: imap(test2): Debug: INBOX/test: Mailbox 
opened because: SELECT
Sep 18 09:51:12 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=395 because: full mail
Sep 18 09:51:12 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=392 because: full mail
Sep 18 09:51:12 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=394 because: full mail
Sep 18 09:51:12 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=393 because: full mail
Sep 18 09:51:13 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=399 because: full mail
Sep 18 09:51:13 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=396 because: full mail
Sep 18 09:51:13 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=398 because: full mail
Sep 18 09:51:13 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=397 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: 
/var/dovecot/test2/index/.INBOX.test/dovecot.index.cache: Compressed, 
file_seq changed 1568667824 -> 1568667825, size=32, max_uid=414
Sep 18 09:51:14 mail04 dovecot: imap(test2): Logged out in=2036121 
out=3672
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=407 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=400 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=408 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=401 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=403 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=409 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=405 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=410 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=406 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=411 because: full mail
Sep 18 09:51:14 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=414 because: full mail
Sep 18 09:51:15 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=412 because: full mail
Sep 18 09:51:15 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=413 because: full mail
Sep 18 09:51:15 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=402 because: full mail
Sep 18 09:51:15 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=404 because: full mail
   

== test 3s finishes ==
[@mail04 ~]# ./imaptest - append=100,0 logout=0 host=192.168.x.x 
port=143 user=test2 pass=testtest  secs=3 clients=1 mbox=64kb.mbox 
box=INBOX/test
Logi Sele Appe
100% 100% 100%
   1    1    9   1/  1
   0    0    9   1/  1
   0    0   12   1/  1
  50    1  814 ms/cmd avg

Totals:
Logi Sele Appe
100% 100% 100%
   1    1   40


Sep 18 09:54:03 mail04 dovecot: auth: Debug: auth client connected 
(pid=14466)
Sep 18 09:54:03 mail04 dovecot: auth: Debug: client in: 
AUTH#0114#011PLAIN#011service=imap#011secured#011session=WhoAJM+SCsvAqAo
s#011lip=192.168.x.x#011rip=192.168.x.x#011lport=143#011rport=51978#011r
esp=<hidden>
Sep 18 09:54:03 mail04 dovecot: auth-worker(14535): Debug: Loading 
modules from directory: /usr/lib64/dovecot/auth
Sep 18 09:54:03 mail04 dovecot: auth-worker(14535): Debug: Module 
loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
Sep 18 09:54:03 mail04 dovecot: auth-worker(14535): Debug: Module 
loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
Sep 18 09:54:03 mail04 dovecot: auth-worker(14535): Debug: passwd-file 
/etc/dovecot/special-userdb: Read 2 users in 0 secs
Sep 18 09:54:03 mail04 dovecot: auth-worker(14535): Debug: 
pam(test2,192.168.x.x,<WhoAJM+SCsvAqAos>): lookup service=dovecot
Sep 18 09:54:03 mail04 dovecot: auth-worker(14535): Debug: 
pam(test2,192.168.x.x,<WhoAJM+SCsvAqAos>): #1/1 style=1 msg=Password:
Sep 18 09:54:03 mail04 dovecot: auth: Debug: client passdb out: 
OK#0114#011user=test2
Sep 18 09:54:03 mail04 dovecot: auth: Debug: master in: 
REQUEST#011909770753#01114466#0114#0114e586ab867a0748dc249b424b667226d#0
11session_pid=14536#011request_auth_token
Sep 18 09:54:03 mail04 dovecot: auth: Debug: 
passwd-file(test2,192.168.x.x,<WhoAJM+SCsvAqAos>): lookup: user=test2 
file=/etc/dovecot/special-userdb
Sep 18 09:54:03 mail04 dovecot: auth: 
passwd-file(test2,192.168.x.x,<WhoAJM+SCsvAqAos>): unknown user
Sep 18 09:54:03 mail04 dovecot: auth: Debug: 
passwd(test2,192.168.x.x,<WhoAJM+SCsvAqAos>): userdb cache hit: 
system_groups_user=test2#011uid=8496#011gid=231#011home=/home/popusers/t
est2
Sep 18 09:54:03 mail04 dovecot: auth: Debug: master userdb out: 
USER#011909770753#011test2#011system_groups_user=test2#011uid=8496#011gi
d=231#011home=/home/popusers/test2#011auth_token=a6897c91e48d5ac6e1783be
eab105e8b35aa7765
Sep 18 09:54:03 mail04 dovecot: imap-login: Login: user=<test2>, 
method=PLAIN, rip=192.168.x.x, lip=192.168.x.x, mpid=14536, secured, 
session=<WhoAJM+SCsvAqAos>
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: Loading modules from 
directory: /usr/lib64/dovecot
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/lib15_notify_plugin.so
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/lib20_listescape_plugin.so
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/libstorage_rbox_plugin.so
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: Effective uid=8496, 
gid=231, home=/home/popusers/test2
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: Namespace inbox: 
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, 
subscriptions=yes 
location=mbox:~/mail:INBOX=/var/spool/mail/test2:CONTROL=~/mail/control:
INDEX=/var/dovecot/test2/index:LAYOUT=maildir++
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: maildir++: 
=/home/popusers/test2/mail, index=/var/dovecot/test2/index, indexpvt=, 
control=/home/popusers/test2/mail/control, inbox=/var/spool/mail/test2, 
alt=
Sep 18 09:54:03 mail04 dovecot: imap(test2): Debug: INBOX/test: Mailbox 
opened because: SELECT
Sep 18 09:54:04 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=418 because: full mail
Sep 18 09:54:04 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=415 because: full mail
Sep 18 09:54:04 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=417 because: full mail
Sep 18 09:54:04 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=416 because: full mail
Sep 18 09:54:04 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=421 because: full mail
Sep 18 09:54:04 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=422 because: full mail
Sep 18 09:54:05 mail04 dovecot: imap(test2): Debug: 
/var/dovecot/test2/index/.INBOX.test/dovecot.index.cache: Compressed, 
file_seq changed 1568667825 -> 1568667826, size=32, max_uid=431
Sep 18 09:54:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=419 because: full mail
Sep 18 09:54:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=420 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=433 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=423 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=424 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=434 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=425 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=426 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=435 because: full mail
Sep 18 09:54:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=428 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=427 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Logged out in=3540929 
out=5448
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=429 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=436 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=430 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=437 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=431 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=432 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=438 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=439 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=442 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=441 because: full mail
Sep 18 09:54:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=440 because: full mail


== test 4s stalls ==

[@mail04 ~]# ./imaptest - append=100,0 logout=0 host=192.168.x.x 
port=143 user=test2 pass=testtest  secs=4 clients=1 mbox=64kb.mbox 
box=INBOX/test
Logi Sele Appe
100% 100% 100%
   1    1    7   1/  1
   0    0   10   1/  1
   0    0   10   1/  1


Sep 18 09:56:04 mail04 dovecot: auth: Debug: client passdb out: 
OK#0119#011user=test2
Sep 18 09:56:04 mail04 dovecot: auth: Debug: master in: 
REQUEST#0112707030017#01114466#0119#01163348e5efb431c443120dd11d5688bb3#
011session_pid=14563#011request_auth_token
Sep 18 09:56:04 mail04 dovecot: auth: Debug: 
passwd-file(test2,192.168.x.x,<D5o5K8+SHsvAqAos>): lookup: user=test2 
file=/etc/dovecot/special-userdb
Sep 18 09:56:04 mail04 dovecot: auth: 
passwd-file(test2,192.168.x.x,<D5o5K8+SHsvAqAos>): unknown user
Sep 18 09:56:04 mail04 dovecot: auth: Debug: 
passwd(test2,192.168.x.x,<D5o5K8+SHsvAqAos>): userdb cache hit: 
system_groups_user=test2#011uid=8496#011gid=231#011home=/home/popusers/t
est2
Sep 18 09:56:04 mail04 dovecot: auth: Debug: master userdb out: 
USER#0112707030017#011test2#011system_groups_user=test2#011uid=8496#011g
id=231#011home=/home/popusers/test2#011auth_token=c13d4e59f0fb682ba75be4
b67deecb48bb9c2388
Sep 18 09:56:04 mail04 dovecot: imap-login: Login: user=<test2>, 
method=PLAIN, rip=192.168.x.x, lip=192.168.x.x, mpid=14563, secured, 
session=<D5o5K8+SHsvAqAos>
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: Loading modules from 
directory: /usr/lib64/dovecot
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/lib15_notify_plugin.so
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/lib20_listescape_plugin.so
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: Module loaded: 
/usr/lib64/dovecot/libstorage_rbox_plugin.so
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: Effective uid=8496, 
gid=231, home=/home/popusers/test2
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: Namespace inbox: 
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, 
subscriptions=yes 
location=mbox:~/mail:INBOX=/var/spool/mail/test2:CONTROL=~/mail/control:
INDEX=/var/dovecot/test2/index:LAYOUT=maildir++
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: maildir++: 
=/home/popusers/test2/mail, index=/var/dovecot/test2/index, indexpvt=, 
control=/home/popusers/test2/mail/control, inbox=/var/spool/mail/test2, 
alt=
Sep 18 09:56:04 mail04 dovecot: imap(test2): Debug: INBOX/test: Mailbox 
opened because: SELECT
Sep 18 09:56:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=458 because: full mail
Sep 18 09:56:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=455 because: full mail
Sep 18 09:56:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=457 because: full mail
Sep 18 09:56:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=456 because: full mail
Sep 18 09:56:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=460 because: full mail
Sep 18 09:56:05 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=459 because: full mail
Sep 18 09:56:06 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=468 because: full mail
Sep 18 09:56:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=461 because: full mail
Sep 18 09:56:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=462 because: full mail
Sep 18 09:56:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=469 because: full mail
Sep 18 09:56:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=463 because: full mail
Sep 18 09:56:07 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=464 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=470 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=465 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=472 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=471 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=473 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=467 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=474 because: full mail
Sep 18 09:56:08 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=466 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=486 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=475 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=487 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=477 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=476 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=480 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=488 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=482 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=478 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=483 because: full mail
Sep 18 09:56:09 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=489 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=490 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=491 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=484 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=492 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=494 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=493 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=495 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=479 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=496 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=497 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=485 because: full mail
Sep 18 09:56:10 mail04 dovecot: imap(test2): Debug: Mailbox INBOX/test: 
Opened mail UID=481 because: full mail

More information about the dovecot mailing list