[PATCH] Re: Limit msg body length in debug output

[Nicolas Sebrecht]

On Sun, May 08, 2011 at 10:46:08PM +0200, Sebastian Spaeth wrote:
> 
> We were outputting full message bodies to the debug log (often stderr),
> and then again (as they go over the imaplib2 wire, imaplib logs
> everything too). Not only is quite a privacy issue when sending in debug
> logs but it can also freeze a console for quite some time. Plus it
> bloats debug logs A LOT.
> 
> Only output the first and last 100 bytes of each message body to the
> debug log (we still get the full body from imaplib2 logging). This
> limits privacy issues when handing the log to someone else, but usually
> still contains all the interesting bits that we want to see in a log.
> 
> Signed-off-by: Sebastian Spaeth <Sebastian at SSpaeth.de>
> ---
> Rebased against current next.

Thank you; merged.

>                               Patch got somewhat larger because I added
> a scary warning to it. I discovered that this function is broken when a
> message has been deleted on the IMAP server since we started syncing. We
> need to fix this pretty soon, I would say.
> 
>  offlineimap/folder/IMAP.py |   50 +++++++++++++++++++++++++++++--------------
>  1 files changed, 34 insertions(+), 16 deletions(-)
> 
> diff --git a/offlineimap/folder/IMAP.py b/offlineimap/folder/IMAP.py
> index 9c91ddd..b8d91c7 100644
> --- a/offlineimap/folder/IMAP.py
> +++ b/offlineimap/folder/IMAP.py
> @@ -203,17 +203,32 @@ class IMAPFolder(BaseFolder):
>          try:
>              imapobj.select(self.getfullname(), readonly = 1)
>              res_type, data = imapobj.uid('fetch', '%d' % uid, '(BODY.PEEK[])')
> +            assert res_type == 'OK', "Fetching message with UID '%d' failed" % uid
> +            # data looks now e.g. [('320 (UID 17061 BODY[]
> +            # {2565}','msgbody....')]  we only asked for one message,
> +            # and that msg is in data[0]. msbody is in [0][1]
> +
> +            #NB & TODO: When the message on the IMAP server has been
> +            #deleted in the mean time, it will respond with an 'OK'
> +            #res_type, but it will simply not send any data. This will
> +            #lead to a crash in the below line. We need urgently to
> +            #detect this, protect from this and need to think about what
> +            #to return in this case.

True. It's exactly what I reported back in this mail:

  Subject: Re: TypeError: 'NoneType' object is not subscriptable.
  Date: Fri, 29 Apr 2011 19:51:27 +0200
  Message-ID: <20110429175127.GA20420 at vidovic>

What we should probably do is to catch this 

  TypeError: 'NoneType' object is unsubscriptable

error and raise a OfflineImapError with severity MESSAGE. As previously
said, there two reasons I can see why we get this error:

  - the mail is actually deleted on remote;
  - something was going wrong while fetching it.

To effectively know what happened, the better seems to check if the UID
is still valid. If not, ignore the original error. If it's still valid,
either warn or retry the fetch (and again warn if this last try failed).


> +            #                        Probably returning `None` in this
> +            #case would be good. But we need to make sure that all
> +            #Backends behave the same, and that we actually check the
> +            #return value and behave accordingly.
> +            data = data[0][1].replace("\r\n", "\n")
> +
> +            if len(data)>200:
> +                dbg_output = "%s...%s" % (str(data)[:150],
> +                                          str(data)[-50:])
> +            else:
> +                dbg_output = data
> +            self.ui.debug('imap', "Returned object from fetching %d: '%s'" %
> +                          (uid, dbg_output))

-- 
Nicolas Sebrecht