MH & nmh: Email for Users & Programmers

May, 2006

slocal Debugging Tips

NOTE: for users of the online version of this book: This section has a long example followed by long explanation. To avoid jumping between the example and its explanation, it's a good idea to open a new browser window to show an example. (Check your browser's menu for a command like New Web Browser or Open in New Window). Then, use the original browser to read the explanation while you view the example in the second browser window.

If your mail-handling setup doesn't seem to work, read these sections.

The first thing to do is to look through the instructions for setting up your .maildelivery file (Sections The .maildelivery File: Overview and The .maildelivery File in Detail) and executing it (the Section Running Your .maildelivery File). Look for:

Display or print a few messages. Follow them through .maildelivery in your mind. Make sure you understand what conditions each message should match and how each condition is related to others. The Section slocal Documentation vs. Real Life can help here; it has more about the way that slocal reads your .maildelivery file.

The debugging in MH's slocal is pretty lousy. A lot can go wrong that the debugging won't tell you about; for example, slocal can silently skip an error without printing anything (the Section Even -debug Doesn't Show Syntax Errors explains that). There are some helpful debugging tips here.

The debugging support in nmh is better; for instance, nmh slocal will tell you when it's skipping a .maildelivery line. This section is about MH slocal; most of the tips will also help nmh users, though.

NOTE: Many of these sections below apply to the slocal program that runs your .maildelivery file on many systems. If your system doesn't use slocal, the tips in the Section Most Environment Variables Hidden should still be helpful -- others may help, too.

slocal Documentation vs. Real Life

If you're having trouble with your .maildelivery file, try comparing it to the list below. It tells what slocal does, step by step, as it reads an entry in .maildelivery. If that doesn't help, look at the source code yourself or call a guru. The usr_delivery() function parses the entries in .maildelivery.

First, when slocal reads a .maildelivery entry, it checks a list of conditions that make it skip the entry. The entry will be skipped if:

  1. It's a comment or it has less than five arguments.
  2. It has an N result and the previous entry with a field other than * (asterisk) did not match.
  3. It has a ? result and the message has been delivered by any previous entry.
  4. It has the undocumented select arguments 6-8 and these tell slocal to skip the message.
  5. It has a default field (first argument) and some previous entry has delivered the message.
  6. It has a field (first argument) with a message header named (but not an *, asterisk) -- and no header in the message matches that field.
  7. It has an invalid action argument.
If the message isn't skipped by any of the tests in the list above, slocal will try to perform the action. The message will be marked "delivered" if the action succeeds, unless the result was R.

Catching slocal Errors

When you run a program from your terminal -- usually by typing its name at a shell prompt -- the process has a "controlling tty": your terminal. The standard input, standard output, and standard error of the process usually come to your terminal unless they're redirected.

When sendmail runs a program like slocal, the process doesn't have a controlling tty. (That is, the TTY column in the ps output has a ? character.) Errors won't come to your terminal.

To see errors from slocal, you can run it by hand. Or, if you can't reproduce the errors running slocal by hand, grab the stdout and stderr before they're "thrown away." The following two sections show how.

Even with those tips, you still won't see any output from the individual programs in .maildelivery. The Section slocal Eats .maildelivery Errors shows how to handle that.

Running slocal by Hand

The Example Sample slocal -debug -verbose output, in the next section, shows a long chunk of slocal debugging output. It's made automatically, by a setup in the .forward file, for every new message that comes in.

For most .maildelivery debugging, that's more than you need. You want to send a test message through the .maildelivery file and watch what happens. The next Example, Running slocal -verbose interactively, shows the steps. To do that, first store a test message in a file. If you use mhl to show your messages, give -noshowproc to bypass mhl when you store the message. You can edit the test message if you want to change some address in the header (or any other part of the header). Then, run slocal with its -verbose switch; give the message to slocal's standard input:

Example: Running slocal -verbose interactively

    % show -noshowproc > testmsg
    % vi testmsg
    % /usr/local/lib/mh/slocal -verbose -user jerry < testmsg
        delivering to pipe "/usr/local/lib/mh/rcvstore +DELETE", wins.
        delivering to pipe "/usr/local/lib/mh/rcvtty"
    17:43:   307 Jerry Peek      testing slocal<<test test
    , wins.
        delivering to file "/usr/spool/mail/jerry"
    slocal: /usr/spool/mail/.jerry.map:
    pointer mismatch or incomplete index (67054!=1920524), continuing...
    , done.
    
That example is choppy -- the output was broken up by the line from rcvtty and the error message near the end. The -verbose switch prints the lines that start with delivering to .... If I'd used -debug, I'd have seen slocal parse the message and the .maildelivery file (the Example Sample slocal -debug -verbose output shows that).

First, slocal delivers a copy of the message to my backup DELETE directory (I use it for debugging). As slocal starts the program, you can see the pause until ,wins. is printed to show that the program returned a zero ("true") exit status. Next, slocal runs rcvtty; you can see the rcvtty.format output on my screen before slocal prints the verbose ,wins.. Finally, slocal tried to deliver to my system mailbox. I saw what I needed: an error from slocal, caused by a bug in MH 6.7.2. (When the MH 6.7.2 slocal appends to a system maildrop in mailbox format, with the [RPATHS] configuration option, it can fail once in a while. Then it defaults to the MMDF format. It also leaves a file named .yourname.map in the /usr/spool/mail directory.) Because of the error, slocal delivered the message another way (see the footnote); it printed ,done. when it had delivered the message to the file.

Save slocal Debugging Output with Real Messages

When you run slocal and a .maildelivery file, it can be hard to see what's happening if something goes wrong in "real time" as a message is being delivered. If an individual command in your .maildelivery file prints error (or other) messages, you won't see them because slocal throws away that output. It's especially important to see "real time" output for errors that happen intermittently, that you can't reproduce by hand -- like the error at the end of the Example Running slocal -verbose interactively, errors when the filesystem fills up, and so on.

Here are some tricks with the Bourne shell to work around those problems. The basic idea: instead of running slocal, rcvstore, and other programs directly, run a Bourne shell. Have the shell execute slocal or whatever program you want to debug. Use the shell command exec 2>>logfile to make the shell append its standard error to a log file. To see the program's output, read the log file. I'll start with an example using slocal.

The usual way to start slocal, with debugging, is by a line like this in your .forward file:

    "| /x/y/slocal -debug -verbose -user jerry"
    
Instead, use a line like the one below.
    "| /bin/sh -c 'exec >>/tmp/sllog.jerry 2>&1; /x/y/slocal -debug -verbose -user jerry'"
    
That appends the standard output and standard error from slocal into the file /tmp/sllog.jerry. (/tmp is a system temporary-file directory. /tmp is a good place for files like these because it's world-writable, also because files in /tmp are usually erased periodically and during reboots.)

The next Example, Sample slocal -debug -verbose output, shows the contents of my sllog.jerry file after I got a message from a friend in Germany. First, here's the .maildelivery file I was using:

    # toss anything from uucp (save for a few days, in case):
    From     uucp  |  A   "/usr/local/lib/mh/rcvstore +DELETE"
    # put other stuff into mailbox
    default  -     >  ?   /usr/spool/mail/jerry
    # always run rcvtty
    *        -     |  R   "/usr/local/lib/mh/rcvtty -nobell"
    
And the header of the message I got:
    From martinek@agpsa.de  Sun Jun 28 18:32:31 1992
    Delivery-Date: Sun, 28 Jun 92 10:47:00 -0400
    Return-Path: <martinek@agpsa.de>
    Received: from mail.Germany.EU.net by ora.com (5.65c/Spike-2.1)
        id AA08683; Sun, 28 Jun 1992 10:46:52 -0400
    Received: from apgwdf
        by mail.Germany.EU.net with UUCP (5.65+/UNIDO-2.1.0.b)
        via EUnet for ora.com
        id AA08647; Sun, 28 Jun 92 16:48:00 +0200
    Received: from is0001 by agpsa.de (5.52.1/APG-1.1)
        id AA21195; Sun, 28 Jun 92 15:26:58  +0100
        for ora.com!jerry
    Received: from localhost by is0001 (AIX 3.1/UCB 5.61/4.03)
              id AA56358; Sun, 28 Jun 92 16:32:32 +0200
          for jpeek@jpeek.com
    Message-Id: <9206281432.AA56358@is0001>
    To: Jerry Peek <jpeek@jpeek.com>
    Phone: +49 6239-000000  Home: +49 6241-000000
    Subject: Re: your book
    In-Reply-To: Jerry Peek's message of Fri, 26 Jun 92 14:42:35 -0400
                 <13386.709584155@babble.ora.com>
    Reply-To: Hans Martinek <martinek@agpsa.de>
    Date: Sun, 28 Jun 92 16:32:31 +0200
    From: Hans Martinek <martinek@agpsa.de>
    
Example: Sample slocal -debug -verbose output
     1> temporary file "/tmp/slocala08688" selected
     2> addr="jerry" user="jerry" info="" file="/tmp/slocala08688"
     3> sender="martinek@agpsa.de" mbox="/usr/spool/mail/jerry" home="/home/jerry" from="From martinek@agpsa.de  Sun Jun 28 18:32:31 1992
     4> "
     5> ddate="Delivery-Date: Sun, 28 Jun 92 10:47:00 -0400
     6> " now=10:47
     7> vec[0]: "From"
     8> vec[1]: "uucp"
     9> vec[2]: "|"
    10> vec[3]: "A"
    11> vec[4]: "/usr/local/lib/mh/rcvstore +DELETE"
    12> vars[3]: name="reply-to" value=" Hans Martinek <martinek@agpsa.de>
    13> "
    14> hdrs[0]: name="source" value="martinek@agpsa.de"
    15> hdrs[1]: name="addr" value="jerry"
    16> hdrs[2]: name="Return-Path" value=" <martinek@agpsa.de>
    17> "
    18> hdrs[3]: name="Reply-To" value=" Hans Martinek <martinek@agpsa.de>
    19> "
    20> hdrs[4]: name="From" value=" Hans Martinek <martinek@agpsa.de>
    21> "
    22> hdrs[5]: name="Sender" value="(null)"
    23> hdrs[6]: name="To" value=" Jerry Peek <jpeek@jpeek.com>
    24> "
    25> hdrs[7]: name="cc" value="(null)"
    26> hdrs[8]: name="Resent-Reply-To" value="(null)"
    27> hdrs[9]: name="Resent-From" value="(null)"
    28> hdrs[10]: name="Resent-Sender" value="(null)"
    29> hdrs[11]: name="Resent-To" value="(null)"
    30> hdrs[12]: name="Resent-cc" value="(null)"
    31> hdrs[13]: name="Received" value=" from mail.Germany.EU.net by ora.com (5.65c/Spike-2.1)
    32>     id AA08683; Sun, 28 Jun 1992 10:46:52 -0400
    33>      from apgwdf
    34>     by mail.Germany.EU.net with UUCP (5.65+/UNIDO-2.1.0.b)
    35>     via EUnet for ora.com
    36>     id AA08647; Sun, 28 Jun 92 16:48:00 +0200
    37>      from is0001 by agpsa.de (5.52.1/APG-1.1)
    38>     id AA21195; Sun, 28 Jun 92 15:26:58  +0100
    39>     for ora.com!jerry
    40>      from localhost by is0001 (AIX 3.1/UCB 5.61/4.03)
    41>           id AA56358; Sun, 28 Jun 92 16:32:32 +0200
    42>       for jpeek@jpeek.com
    43> "
    44> hdrs[14]: name="Message-Id" value=" <9206281432.AA56358@is0001>
    45> "
    46> hdrs[15]: name="Phone" value=" +49 6239-000000  Home: +49 6241-000000
    47> "
    48> hdrs[16]: name="Subject" value=" Re: your book
    49> "
    50> hdrs[17]: name="In-Reply-To" value=" Jerry Peek's message of Fri, 26 Jun 92 14:42:35 -0400
    51>              <13386.709584155@babble.ora.com>
    52> "
    53> hdrs[18]: name="Date" value=" Sun, 28 Jun 92 16:32:31 +0200
    54> "
    55> vec[0]: "default"
    56> vec[1]: "-"
    57> vec[2]: ">"
    58> vec[3]: "?"
    59> vec[4]: "/usr/spool/mail/jerry"
    60>     delivering to file "/usr/spool/mail/jerry" (uucp style), done.
    61> vec[0]: "*"
    62> vec[1]: "-"
    63> vec[2]: "|"
    64> vec[3]: "R"
    65> vec[4]: "/usr/local/lib/mh/rcvtty -nobell"
    66> vars[0]: name="sender" value="martinek@agpsa.de"
    67> vars[1]: name="address" value="jerry"
    68> vars[2]: name="size" value="1235"
    69> vars[3]: name="reply-to" value=" Hans Martinek <martinek@agpsa.de>
    70> "
    71> vars[4]: name="info" value=""
    72>     delivering to pipe "/usr/local/lib/mh/rcvtty -nobell", wins.
    
Line 1 shows the name of the temporary file where slocal stores the message it's processing.

Lines 2-6 list some internal variables:

Line 5 is an example of a variable holding a line of characters that ends with a newline. The closing double quote mark will be on the following line (here, line 6).

In line 7, slocal is starting to read and parse the .maildelivery entries. If you compare lines 7-11 of the debugging output to the first uncommented entry of the .maildelivery file above it, you can see that the five arguments in the entry have been split into the array members vec[0] through vec[4]. The first vec array member, vec[0], always holds the field argument, vec[1] always holds the pattern argument, and so on.

Lines similar to lines 12-54 will be printed the first time slocal calls its internal parse() function. That reads the message and splits out the header. You can use these header field names (shown as name= in the debugging output) as the field argument on .maildelivery entries. The pattern argument in .maildelivery entries is compared to the value= here.

The message didn't match the first entry in my .maildelivery file because it isn't from uucp. So, slocal checks the next .maildelivery entry; lines 55-59 show the five arguments on it.

It matches, so the action is performed; line 60 shows that. By the way, this is the first line that we'd have seen if I'd only used the slocal -verbose option!

Lines 66-72 show the last entry of the .maildelivery file being parsed and the pipe executed. In case you didn't notice, successful pipe actions "win" but deliveries to files (like line 60) are just "done".

Even -debug Doesn't Show Syntax Errors

The slocal -debug switch will show some problems. There are other problems that -debug won't tell you about. For example, if a .maildelivery entry has less than five arguments, it's skipped silently. If you have the MH source tree on your computer and you can read C programs, take a look at the uip/slocal.c file. Search for the expression if (debug) to see the places that debugging messages are printed. In the usr_delivery() function, look at the continue and return NOTOK statements that silently skip .maildelivery entries.

Choosing the lines that debug prints was a design decision. As it is, debug can give you an overwhelming amount of information. If you're having debugging trouble, though, you might recompile your your slocal code with more of if (debug) and fprintf (stderr ...).

slocal Eats .maildelivery Errors

When slocal runs .maildelivery, it throws away error messages from the commands run by pipe, |, qpipe, and ^ actions. Here's a trick that should help you see the errors. slocal runs the pipe action with a Bourne shell. You can set that shell's debugging options with set -xv. Also, redirect the shell's stdout and stderr to a file in your home directory with a command like:

    exec >/home/jerry/rcvstore.debug 2>&1
    
What I mean is: change the entry in your .maildelivery file to something like the one below:
    to    gripe  |  R  "set -xv; exec >/home/jerry/rcvstore.debug 2>&1; /usr/local/lib/mh/rvcstore +gripes"
    
Send a message and look at the debugging file. The shell shows a plus sign (+) before every command it runs:
    % cat rcvstore.debug
    + /usr/local/lib/mh/rvcstore +gripes
    sh: /usr/local/lib/mh/rvcstore: not found
    
Oh! I typed rvcstore instead of rcvstore...

Most Environment Variables Hidden

Programs in .maildelivery are run in a different environment, not from your login shell. Environment variables, aliases, shell functions, and other things set in your .cshrc, .login or .profile files probably won't reach your programs in .maildelivery. For instance, your MH profile file has to be in the standard place, $HOME/.mh_profile, unless you use a trick to reset your MH environment variable. (slocal passes in the system default settings of three environment variables: HOME, SHELL, and USER.)

For example, on my workstation I keep my mail on a separate filesystem named /Mail. But my .maildelivery file is read on a fileserver where /Mail doesn't exist. I have a separate MH profile for the fileserver named .mh_profile.server. But unless I do something, the programs in .maildelivery won't know that.

Here's the trick for running programs from .maildelivery. Don't use the qpipe or ^ action. Instead, use the pipe or | action and give the shell the environment settings it needs. Here's my .maildelivery entry for running rcvtty:

    *   -  |  R  "MH=$HOME/.mh_profile.server /x/y/rcvtty"
    
What's that? In the Bourne shell, which runs when you use the pipe or | action, you can set an environment variable before a command is run. Before starting rcvtty, I set the MH environment variable.