Bug 528093 - imaps logging excessive inflate/deflate messages
Summary: imaps logging excessive inflate/deflate messages
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cyrus-imapd
Version: 11
Hardware: All
OS: Linux
low
urgent
Target Milestone: ---
Assignee: Michal Hlavinka
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-10-09 01:54 UTC by Philip Prindeville
Modified: 2011-11-17 22:33 UTC (History)
4 users (show)

Fixed In Version: 2.3.15-4.fc11
Clone Of:
Environment:
Last Closed: 2009-11-25 14:55:31 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)

Description Philip Prindeville 2009-10-09 01:54:16 UTC
Description of problem:

Our server has logged 3GB of messages like:

Oct  8 19:43:01 mail imaps[6149]: deflate(4096 bytes, level=-1, flush=SYNC)
Oct  8 19:43:01 mail imaps[6149]:    => compressed to 325 bytes
Oct  8 19:43:01 mail imaps[6149]: deflate(4096 bytes, level=-1, flush=SYNC)
Oct  8 19:43:01 mail imaps[6149]:    => compressed to 320 bytes
Oct  8 19:43:01 mail imaps[6149]: deflate(4096 bytes, level=-1, flush=SYNC)
Oct  8 19:43:01 mail imaps[6149]:    => compressed to 231 bytes
Oct  8 19:43:01 mail imaps[6149]: deflate(4096 bytes, level=-1, flush=SYNC)
Oct  8 19:43:01 mail imaps[6149]:    => compressed to 451 bytes
Oct  8 19:43:01 mail imaps[5932]: inflate(14 bytes)
Oct  8 19:43:01 mail imaps[5932]:    => decompressed to 32 bytes
Oct  8 19:43:02 mail imaps[6202]: deflate(4096 bytes, level=-1, flush=SYNC)
Oct  8 19:43:02 mail imaps[6202]:    => compressed to 783 bytes


over a relatively low-traffic 24 hour period.  On a busy server, this could cause denial-of-service.


Version-Release number of selected component (if applicable):

2.3.15-1

How reproducible:

Change rsyslog.conf from:

mail.*                                                  -/var/log/maillog

to:

mail.debug                                              -/var/log/maillog


and kill -HUP rsyslogd... then sit and wait as /var/log/maillog fills up.


Steps to Reproduce:
1. Above
2.
3.
  
Actual results:

Lots of useless logging as above.


Expected results:

No useless logging about inflate/deflate.


Additional info:

Comment 1 Philip Prindeville 2009-10-09 05:18:29 UTC
Actually, this also happens even with an unmodified /etc/rsyslog.conf file.

Comment 2 Michal Hlavinka 2009-10-09 08:06:05 UTC
Is this "after update" issue? Or this is first cyrus-imapd version you've tried to use?

Comment 3 Philip Prindeville 2009-10-09 17:34:26 UTC
No, I've been running cyrus-imapd on this box since FC6...

Comment 4 Matt Bernstein 2009-10-09 22:30:06 UTC
I found this earlier (I'd backported the IMAP COMPRESS patch into 2.3.14) and just lowered the logging to mail.info. I agree that mail.* is no longer a sane default.

Comment 5 Philip Prindeville 2009-10-12 19:12:34 UTC
I'm wondering if there aren't more serious things going on at this point.  I'm also seeing:

Oct 12 12:58:30 mail imaps[10064]: imapd:Loading hard-coded DH parameters
Oct 12 12:58:30 mail imaps[10064]: starttls: TLSv1 with cipher DHE-RSA-CAMELLIA256-SHA (256/256 bits new) no authentication
Oct 12 12:58:30 mail imaps[10064]: login: builder.redfish-solutions.com [192.168.10.7] philipp plain+TLS User logged in
Oct 12 12:58:32 mail imaps[10064]: IOERROR: reading message: unexpected end of file
Oct 12 12:58:32 mail imaps[10064]: Error decompressing data, closing connection

Does compression have any sort of exposed controls that can be used, say to turn it off?

Comment 6 Michal Hlavinka 2009-10-14 15:19:53 UTC
(In reply to comment #1)
> Actually, this also happens even with an unmodified /etc/rsyslog.conf file.  

yes, mail.* means everything and mail.debug means debug and everything more important and there is nothing less important than LOG_DEBUG

(In reply to comment #4)
> ... and just lowered the logging to mail.info. I agree that mail.* is no
> longer a sane default.  

yes, you can change it from mail.* to mail.info then you'll get all messages except debug messages

Other imap servers such like dovecot usually have some config option to turn debug messages on/off, but I didn't find anything like this in cyrus-imapd

But this can be easily implemented by just calling setlogmask(LOG_UPTO(LOG_INFO)); 

I'll ask upstream if they will do this change or at least accept patch.

(In reply to comment #5)
> I'm wondering if there aren't more serious things going on at this point.  I'm
> also seeing:
> 
> Oct 12 12:58:32 mail imaps[10064]: IOERROR: reading message: unexpected end of
> file
> Oct 12 12:58:32 mail imaps[10064]: Error decompressing data, closing connection

Compression was added to 2.3.15 so it's maybe a little buggy yet.

Do you see any problems except these messages in log? How often are they?


> Does compression have any sort of exposed controls that can be used, say to
> turn it off?  

Compression can be disabled when compiling package, there are no exposed controls that can be used.

Comment 7 Philip Prindeville 2009-10-19 16:52:20 UTC
> (In reply to comment #5)
> > I'm wondering if there aren't more serious things going on at this point.  I'm
> > also seeing:
> > 
> > Oct 12 12:58:32 mail imaps[10064]: IOERROR: reading message: unexpected end of
> > file
> > Oct 12 12:58:32 mail imaps[10064]: Error decompressing data, closing connection
> 
> Compression was added to 2.3.15 so it's maybe a little buggy yet.
> 
> Do you see any problems except these messages in log? How often are they?
> 
> > Does compression have any sort of exposed controls that can be used, say to
> > turn it off?  
> 
> Compression can be disabled when compiling package, there are no exposed
> controls that can be used.  

Oddly, I've not seen further messages...

From what I can tell,this didn't correspond to yum updates on either the client (running TB3) nor the server.

It just went away, at least for now.

Comment 8 Michal Hlavinka 2009-10-20 16:41:31 UTC
> Oddly, I've not seen further messages...
>
> From what I can tell,this didn't correspond to yum updates
> on either the client (running TB3) nor the server.
>
> It just went away, at least for now.  

ok, let me know if it appears again

for iflate/deflate messages: I've sent email upstream, waiting for response. Change level of logging in your rsyslog.conf meanwhile. If there is no response within few days, I'll make that patch.

Comment 9 Philip Prindeville 2009-10-20 19:15:25 UTC
See also:

http://bugzilla.adiscon.com/show_bug.cgi?id=37

Comment 10 Michal Hlavinka 2009-11-05 13:39:55 UTC
upstream has decided to remove all these messages

fixed since cyrus-imapd-2.3.15-3.fc11

Comment 11 Fedora Update System 2009-11-05 13:56:55 UTC
cyrus-imapd-2.3.15-3.fc11 has been submitted as an update for Fedora 11.
http://admin.fedoraproject.org/updates/cyrus-imapd-2.3.15-3.fc11

Comment 12 Fedora Update System 2009-11-05 13:57:00 UTC
cyrus-imapd-2.3.15-2.fc10 has been submitted as an update for Fedora 10.
http://admin.fedoraproject.org/updates/cyrus-imapd-2.3.15-2.fc10

Comment 13 Fedora Update System 2009-11-06 00:07:00 UTC
cyrus-imapd-2.3.15-3.fc11 has been pushed to the Fedora 11 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update cyrus-imapd'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F11/FEDORA-2009-11045

Comment 14 Fedora Update System 2009-11-06 00:08:00 UTC
cyrus-imapd-2.3.15-2.fc10 has been pushed to the Fedora 10 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update cyrus-imapd'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F10/FEDORA-2009-11053

Comment 15 Fedora Update System 2009-11-06 14:51:10 UTC
cyrus-imapd-2.3.15-5.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/cyrus-imapd-2.3.15-5.fc12

Comment 16 Philip Prindeville 2009-11-06 22:38:02 UTC
Not sure why, but I'm still getting these:

[root@mail mail]# rpm -qa cyrus-imapd\*
cyrus-imapd-utils-2.3.15-2.fc11.x86_64
cyrus-imapd-perl-2.3.15-2.fc11.x86_64
cyrus-imapd-2.3.15-2.fc11.x86_64
[root@mail mail]# 
[root@mail mail]# tail -n 10 /var/log/maillog
Nov  6 15:34:57 mail imap[4790]: inflate(14 bytes)
Nov  6 15:34:57 mail imap[4790]:    => decompressed to 51 bytes
Nov  6 15:34:57 mail imap[4790]: deflate(4096 bytes, level=-1, flush=SYNC)
Nov  6 15:34:57 mail imap[4790]:    => compressed to 747 bytes
Nov  6 15:34:57 mail imap[4790]: deflate(28 bytes, level=-1, flush=SYNC)
Nov  6 15:34:57 mail imap[4790]:    => compressed to 10 bytes
Nov  6 15:34:57 mail imap[4790]: inflate(14 bytes)
Nov  6 15:34:57 mail imap[4790]:    => decompressed to 51 bytes
Nov  6 15:34:57 mail imap[4790]: deflate(4096 bytes, level=-1, flush=SYNC)
Nov  6 15:34:57 mail imap[4790]:    => compressed to 922 bytes
[root@mail mail]#

I even forced a "service cyrus-imapd stop", looked for lingering processes (none), and then restarted.

Comment 17 Michal Hlavinka 2009-11-09 11:46:12 UTC
(In reply to comment #16)
> Not sure why, but I'm still getting these:
> 
> [root@mail mail]# rpm -qa cyrus-imapd\*
> cyrus-imapd-utils-2.3.15-2.fc11.x86_64
> cyrus-imapd-perl-2.3.15-2.fc11.x86_64
> cyrus-imapd-2.3.15-2.fc11.x86_64

see my comment #10:
> fixed since cyrus-imapd-2.3.15-3.fc11

you don't have the version containing fix for this

this version is update-testing repository now, package update information for Fedora 11 is in comment #13

Michal

Comment 18 Philip Prindeville 2009-11-09 16:43:53 UTC
(In reply to comment #17)
> (In reply to comment #16)
> > Not sure why, but I'm still getting these:
> > 
> > [root@mail mail]# rpm -qa cyrus-imapd\*
> > cyrus-imapd-utils-2.3.15-2.fc11.x86_64
> > cyrus-imapd-perl-2.3.15-2.fc11.x86_64
> > cyrus-imapd-2.3.15-2.fc11.x86_64
> 
> see my comment #10:
> > fixed since cyrus-imapd-2.3.15-3.fc11
> 
> you don't have the version containing fix for this
> 
> this version is update-testing repository now, package update information for
> Fedora 11 is in comment #13
> 
> Michal  

I'm not seeing it there.  I'll dig deeper.

[root@mail mail]# yum --enablerepo=updates-testing list cyrus-imapd
Loaded plugins: dellsysidplugin2, fastestmirror, refresh-packagekit
Loading mirror speeds from cached hostfile
 * fedora: mirrors.xmission.com
 * updates: mirrors.xmission.com
 * updates-testing: mirrors.xmission.com
Installed Packages
cyrus-imapd.x86_64                2.3.15-2.fc11                 @updates-testing
[root@mail mail]#

Comment 19 Michal Hlavinka 2009-11-09 16:54:47 UTC
right, 2.3.15-3.fc11 was obsoleted by 2.3.15-4.fc11 which is still pending:

https://admin.fedoraproject.org/updates/F11/FEDORA-2009-11045

a) you can use not signed packages directly from koji (requires manual download and installation) :

http://koji.fedoraproject.org/koji/buildinfo?buildID=140078

b) wait till this update makes it into updates-testing (it takes about one days)

Comment 20 Fedora Update System 2009-11-10 17:53:09 UTC
cyrus-imapd-2.3.15-4.fc11 has been pushed to the Fedora 11 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update cyrus-imapd'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F11/FEDORA-2009-11045

Comment 21 Fedora Update System 2009-11-25 14:55:25 UTC
cyrus-imapd-2.3.15-2.fc10 has been pushed to the Fedora 10 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 22 Fedora Update System 2009-11-25 15:03:07 UTC
cyrus-imapd-2.3.15-5.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 23 Fedora Update System 2009-11-25 15:32:32 UTC
cyrus-imapd-2.3.15-4.fc11 has been pushed to the Fedora 11 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 24 Philip Prindeville 2011-11-17 22:33:33 UTC
There's an upstream fix that's been submitted:

https://bugzilla.cyrusimap.org/show_bug.cgi?id=3269


Note You need to log in before you can comment on or make changes to this bug.