Grant Keller
2021-Oct-01 02:04 UTC
Issue with the log service after upgrading from 2.1.17 to 2.3.10.1
Hello,
As stated in the subject we have been doing a pretty big version
upgrade. Both new and old are on CentOS 7. For the second time, one of
our upgraded servers have had the dovecot log process start consuming
100% cpu, and the strace output shows it trying to access
/etc/localtime:
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
With no other output then that multiple times a second. The process
itself shows this from ps:
root 76106 8.3 0.0 15384 6532 ? R Sep29 140:21 dovecot/log
[service too fast: 34/34/imap-postlogin: ]
As a part of this upgrade we also modified our postlogin script to
include an index location for each user, so I am not sure if this is
related to that change or a change in the logging service. Any help
tracking this down is appreciated.
# OS: Linux 3.10.0-1160.42.2.el7.x86_64 x86_64 CentOS Linux release 7.9.2009
(Core)
# Hostname: d.lab.imapd.sonic.net
auth_failure_delay = 0
auth_master_user_separator = *
auth_username_format = %Ln
auth_verbose = yes
auth_verbose_passwords = sha1
auth_worker_max_count = 64
default_client_limit = 10000
listen = *
login_log_format_elements = user=<%u> session=%{session} method=%m rip=%r
lip=%l mpid=%e %c
login_trusted_networks = 64.142.18.0/24 64.142.111.71/32 64.142.111.37/32
76.191.254.238/32 64.142.111.79/32 64.142.111.34/32 157.131.224.152/32
157.131.224.153/32 184.23.168.75/32 184.23.168.76/32
mail_fsync = always
mail_log_prefix = "%s(%u): session=%{session} "
mail_plugins = zlib
maildir_very_dirty_syncs = yes
mmap_disable = yes
passdb {
args = /etc/dovecot/master-users
driver = passwd-file
master = yes
}
passdb {
args = imap
driver = pam
}
plugin {
lazy_expunge = DELETED_MESSAGES.
mail_log_events = delete expunge flag_change
mail_log_fields = uid box msgid from flags size
mwi_update_debug = no
mwi_update_events = flag_change delete undelete expunge copy save
mwi_update_hosts = 76.191.249.68 76.191.255.180
mwi_update_master_user = _mwi-master
mwi_update_port = 6472
mwi_update_watch_folder = INBOX.Voicemail
quota = fs:User quota
stats_refresh = 30 secs
stats_track_cmds = yes
}
protocols = imap pop3
service anvil {
client_limit = 10000
}
service auth {
client_limit = 10000
vsz_limit = 1 G
}
service doveadm {
inet_listener {
port = 1842
}
unix_listener doveadm-server {
mode = 0666
}
}
service imap-login {
inet_listener imap {
port = 143
}
inet_listener imaps {
port = 993
ssl = yes
}
process_limit = 7000
process_min_avail = 32
vsz_limit = 256 M
}
service imap-postlogin {
executable = script-login -d /etc/dovecot/bin/sonic-imap-postlogin
user = $default_internal_user
}
service imap {
executable = imap imap-postlogin
process_limit = 7000
vsz_limit = 2516 M
}
service pop3-login {
inet_listener pop3 {
port = 110
}
inet_listener pop3s {
port = 995
ssl = yes
}
process_limit = 2000
process_min_avail = 32
vsz_limit = 512 M
}
service pop3-postlogin {
executable = script-login -d /etc/dovecot/bin/sonic-pop3-postlogin
user = $default_internal_user
}
service pop3 {
executable = pop3 pop3-postlogin
process_limit = 2000
vsz_limit = 512 M
}
shutdown_clients = no
ssl = no
ssl_cipher_list = ALL:!LOW:!SSLv2:!EXP:!aNULL
syslog_facility = local0
userdb {
driver = passwd
}
verbose_proctitle = yes
protocol imap {
imap_id_send = support-url support-email
imap_max_line_length = 128 k
mail_max_userip_connections = 20
mail_plugins = zlib mwi_update mail_log notify imap_zlib
}
protocol pop3 {
mail_plugins = zlib lazy_expunge
pop3_fast_size_lookups = yes
pop3_uidl_format = %f
}
Grant Keller
System Operations
grant.keller at sonic.com
Grant Keller
2021-Oct-04 23:58 UTC
Issue with the log service after upgrading from 2.1.17 to 2.3.10.1
Dug a bit more because we are still seeing this issue after upgrading. Apparently this error has to do with a high rate of log messages: Oct 4 16:54:39 f.imapd.sonic.net dovecot: log(30450): Warning: Log connection fd 34 listen_fd 34 prefix 'imap-postlogin: ' is sending input faster than we can write But how do I determine what is doing so much logging? The mail logs on the system seem fine. This server in particular has had that same warning for 4 days, with the corresponding log process consuming 100% cpu. There is no stuck postlogin script spewing to the logs that I can see. Quoting Grant Keller (2021-09-30 19:04:02)> Hello, > > As stated in the subject we have been doing a pretty big version > upgrade. Both new and old are on CentOS 7. For the second time, one of > our upgraded servers have had the dovecot log process start consuming > 100% cpu, and the strace output shows it trying to access > /etc/localtime: > stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 > stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 > stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 > stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 > stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 > stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 > > With no other output then that multiple times a second. The process > itself shows this from ps: > root 76106 8.3 0.0 15384 6532 ? R Sep29 140:21 dovecot/log [service too fast: 34/34/imap-postlogin: ] > As a part of this upgrade we also modified our postlogin script to > include an index location for each user, so I am not sure if this is > related to that change or a change in the logging service. Any help > tracking this down is appreciated. > > # OS: Linux 3.10.0-1160.42.2.el7.x86_64 x86_64 CentOS Linux release 7.9.2009 (Core) > # Hostname: d.lab.imapd.sonic.net > auth_failure_delay = 0 > auth_master_user_separator = * > auth_username_format = %Ln > auth_verbose = yes > auth_verbose_passwords = sha1 > auth_worker_max_count = 64 > default_client_limit = 10000 > listen = * > login_log_format_elements = user=<%u> session=%{session} method=%m rip=%r lip=%l mpid=%e %c > login_trusted_networks = 64.142.18.0/24 64.142.111.71/32 64.142.111.37/32 76.191.254.238/32 64.142.111.79/32 64.142.111.34/32 157.131.224.152/32 157.131.224.153/32 184.23.168.75/32 184.23.168.76/32 > mail_fsync = always > mail_log_prefix = "%s(%u): session=%{session} " > mail_plugins = zlib > maildir_very_dirty_syncs = yes > mmap_disable = yes > passdb { > args = /etc/dovecot/master-users > driver = passwd-file > master = yes > } > passdb { > args = imap > driver = pam > } > plugin { > lazy_expunge = DELETED_MESSAGES. > mail_log_events = delete expunge flag_change > mail_log_fields = uid box msgid from flags size > mwi_update_debug = no > mwi_update_events = flag_change delete undelete expunge copy save > mwi_update_hosts = 76.191.249.68 76.191.255.180 > mwi_update_master_user = _mwi-master > mwi_update_port = 6472 > mwi_update_watch_folder = INBOX.Voicemail > quota = fs:User quota > stats_refresh = 30 secs > stats_track_cmds = yes > } > protocols = imap pop3 > service anvil { > client_limit = 10000 > } > service auth { > client_limit = 10000 > vsz_limit = 1 G > } > service doveadm { > inet_listener { > port = 1842 > } > unix_listener doveadm-server { > mode = 0666 > } > } > service imap-login { > inet_listener imap { > port = 143 > } > inet_listener imaps { > port = 993 > ssl = yes > } > process_limit = 7000 > process_min_avail = 32 > vsz_limit = 256 M > } > service imap-postlogin { > executable = script-login -d /etc/dovecot/bin/sonic-imap-postlogin > user = $default_internal_user > } > service imap { > executable = imap imap-postlogin > process_limit = 7000 > vsz_limit = 2516 M > } > service pop3-login { > inet_listener pop3 { > port = 110 > } > inet_listener pop3s { > port = 995 > ssl = yes > } > process_limit = 2000 > process_min_avail = 32 > vsz_limit = 512 M > } > service pop3-postlogin { > executable = script-login -d /etc/dovecot/bin/sonic-pop3-postlogin > user = $default_internal_user > } > service pop3 { > executable = pop3 pop3-postlogin > process_limit = 2000 > vsz_limit = 512 M > } > shutdown_clients = no > ssl = no > ssl_cipher_list = ALL:!LOW:!SSLv2:!EXP:!aNULL > syslog_facility = local0 > userdb { > driver = passwd > } > verbose_proctitle = yes > protocol imap { > imap_id_send = support-url support-email > imap_max_line_length = 128 k > mail_max_userip_connections = 20 > mail_plugins = zlib mwi_update mail_log notify imap_zlib > } > protocol pop3 { > mail_plugins = zlib lazy_expunge > pop3_fast_size_lookups = yes > pop3_uidl_format = %f > } > > > > Grant Keller > System Operations > grant.keller at sonic.comGrant Keller System Operations grant.keller at sonic.com