Issue with the log service after upgrading from 2.1.17 to 2.3.10.1

[Grant Keller]

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.com

Grant Keller
System Operations
grant.keller at sonic.com