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@sonic.com
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@sonic.com
Grant Keller System Operations grant.keller@sonic.com
participants (1)
-
Grant Keller