LMTP (deliver) error 65 / Telemetry and debugging not working like described

[Bron Gondwana]

If you have an example message that you're happy to share with the list (or just privately with me even) it might be fairly easy to see what's wrong.

Regards,

Bron.

On Thu, May 28, 2015, at 08:49 PM, Recursive wrote:
> Dear all,
> 
> I am running into some problems when using fetchmail to poll mail from some external accounts and deliver the messages to cyrus imapd. The problem arises when the messages are malformed. In my previous post to this list, I have described the situation in detail. I don't want to clutter the list, so I hope it's appropriate to not repeat the whole problem description and system setup here (in short: debian wheezy, cyrus imapd 2.4.16, fetchmail 6.3.21).
> 
> In order to debug the situation and to find out which part of the respective messages actually is the problem, I changed the delivery in the /etc/fetchmailrc from
> 
> smtphost "/var/run/cyrus/socket/lmtp"
> 
> to
> 
> mda "/usr/sbin/cyrdeliver -q gmx_foo"
> 
> This made a sort of difference in the log files:
> 
> May 28 11:09:17 spock fetchmail[2795]: reading message foo at gmx.de@pop.gmx.net:77 of 80 (2602 octets) (log message incomplete)
> May 28 11:09:17 spock fetchmail[2795]: MDA returned nonzero status 65
> May 28 11:09:17 spock fetchmail[2795]:  not flushed
> 
> For the first time, I saw an error code and was full of hope that this could me on the right track. After some hours of googling, I had to notice that cyrus lmtpd / imapd error codes are obviously documented nowhere. Looking into the git repository did not reveal any error code table either, so I suspected that a header file with the source codes would be generated during compilation. I fetched the tarball for cyrus imapd 2.4.17, installed the development headers for some libraries and finally got it to compile.
> 
> Indeed, some header files were generated during compilation, but the only place where I could find error code 65 was in lib/sysexits.h:
> 
> [snip]
>  *      EX_DATAERR -- The input data was incorrect in some way.
>  *              This should only be used for user's data & not
>  *              system files.
> [snip]
> #define EX_DATAERR       65
> [snip]
> 
> EX_DATAERR doesn't seem to be used directly for a return value anywhere, but in in lib/exitcodes.h there is:
> 
> #define EC_DATAERR     EX_DATAERR
> 
> Hunting for EC_DATAERR reveals the following snippet from imap/deliver.c (which I think is the relevant snippet for my case):
> 
>         case RCPT_PERMFAIL:
>             /* we just need any permanent failure, though we should
>                probably return data from the client-side LMTP info */
>             printf("%s: %s\n",
>                    txn->rcpt[j].addr, error_message(txn->rcpt[j].r));
>             if (r != EC_TEMPFAIL) {
>                 r = EC_DATAERR;
>             }
>             break;
>         }
> 
> As far as I understand, deliver is just a wrapper for lmtp / smtp delivery, and then this means that deliver just returns EC_DATAERR whenever lmtp returns RCPT_PERMFAIL (if there was no RCPT_TEMPFAIL during the same run). It seems I've done the work for nothing - still no chance to see where the problem is (i.e. what exactly is the message part which lmtpd / imapd doesn't like and how to get around it).
> 
> Next, I googled for how I could enable more detail logging in lmtp / imapd, and read the respective man pages multiple times completely.
> 
> First, I uncommented the line
> 
> #CYRUS_VERBOSE=1
> 
> in /etc/defaults/cyrus-imapd, changed it to
> 
> CYRUS_VERBOSE=29
> 
> and restarted cyrus-imapd. According to the manuals, this should produce much more debug output. In my case, it did exactly nothing. The log entries in mail.log, mail.info and mail.err were exactly the same as with the line being commented.
> 
> So my first question is:
> 
> Do I have to perform any additional actions to make CYRUS_VERBOSE=29 effective, i.e. to get more debugging / log information?
> 
> Then I stumbled across the following document:
> 
> http://members.sange.fi/~atehwa/vc/packaging/cyrus-imapd/debian/README.Debian.debug
> 
> I have followed the steps described in the section "Telemetry logs", and indeed log files with some logging information are created in the respective directory (in my case /var/lib/cyrus/log/gmx_foo/). Unfortunately, there only seems to be some (irrelevant) information generated during the restart of cyrus in these files. The log files don't grow as fetchmail polls the respective messages and tries to deliver them, and they don't contain any trace of any communication between fetchmail and lmtpd / imapd.
> 
> So my second question is:
> 
> Could anybody out there imagine any reason why the telemetry logging does not work like it is documented?
> 
> Thank you very much for any ideas,
> 
> Recursive
> 
> ----
> Cyrus Home Page: http://www.cyrusimap.org/
> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
> To Unsubscribe:
> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus


-- 
  Bron Gondwana
  brong at fastmail.fm