Development Notebook

Well, that (see yesterdays blog) didn't work. I got a call from the admin this morning that email didn't work, and sure enough it was not delivering mail at all. I undid the change to /var/qmail/control/ldaptimeout and restarted. It took about 5 restarts ((vi /etc/inittab; kill -HUP 1)*2), but eventually it got through the whole deliver queue. The problem still remained of why was this happening. One clue was found by setting /var/qmail/control/loglevel-send to 127 and restarting. I would get something like exhibit 1, except the "success" time was a minute and a half later than the "executing..." time.

The other big clue was that "top" on the openldap server box showed slapd pegged at close to 100% of the cpu. This told me that OpenLDAP was too busy.

Upon further examination of exhibit 1, I noticed that the mailAlternateAddress was being searched every time. The "mail" field is indexed by default, but the mailAlternateAddress was not indexed. I changed the /etc/openldap/slapd file on the OpenLDAP server by adding the line index mailAlternateAddress eq, and that seems to have fixed everything up quite nicely.

Along the way, I developed two useful utilities for looking at the logs; delivery and deliveries. Delivery's output is shown in exhibit 1. It shows all the information about a specific delivery. The source is in exhibit 2. Deliveries simply shows multiple deliveries. It's source is in exhibit 3.

Exhibit 1

[root@mail qmail]# ./delivery 42 2003-02-25 15:48:18.344906500 starting delivery 42: msg 451289 to local eddie@client.net 2003-02-25 15:48:18.402715500 delivery 42: log: LOGLEVEL_set_to_127/ 2003-02-25 15:48:18.402858500 delivery 42: log: mailaddr:_eddie@client.net/ 2003-02-25 15:48:18.422529500 delivery 42: log: ldapfilter:_'(|(mail=eddie@client.net) ... (mailAlternateAddress=eddie@client.net))'/ 2003-02-25 15:48:18.431933500 delivery 42: log: ldap_get_userinfo:_qmailUID:_ 2003-02-25 15:48:18.432307500 delivery 42: log: 508_(default)/ 2003-02-25 15:48:18.435458500 delivery 42: log: homeDirectory=/u/eddie_(from_server)/ { SOME INFORMATION SKIPPED FOR SPACE } 2003-02-25 15:48:18.439944500 delivery 42: log: found:_user='eddie'_uid=508_gid=508_... homedir='/u/eddie'_mms='/u/eddie/Maildir/'_... host='mail.client.com'_status=-1/ 2003-02-25 15:48:18.441235500 delivery 42: log: executing_'qmail-local_--_eddie_/u/eddie_... eddie@client.net_ann@abc.com_... /u/eddie/Maildir/'_under_uid=508,_gid=508/ 2003-02-25 15:48:18.604907500 delivery 42: success: did_1+0+0/

Exhibit 2: delivery

#!/bin/sh CAT="@* current" cat $CAT | grep "delivery $1:" | /command/tai64nlocal

Exhibit 3: deliveries

#!/bin/sh START=$1 FINI=$2 if [ -z "$START" ]; then echo "$0 usage:" echo "$0 r1 {r2}" echo "if r2 is not given, then deliveries 1-r1 are shown, else" echo "deliveries r1-r2 are shown" exit 1 fi if [ -z "$FINI" ]; then FINI=$START START=1 fi for i in `awk 'BEGIN{for(i='$START';i<='$FINI';i++)print i;}'`;do clear ./delivery $i /bin/echo -n "continue: " read x done

# posted by John : 4:49 PM