Slow response -logs

[Troy McKinnon]

I have included a sample log of 1 account checking for mail, and sending 1
email message.

I would REALLY appreciate some help on this.  As you can see by the logs the
process of sending 1 email is taking > minute.

Cheers

Troy

-------------

DSZ SEND mysql

Note: 3 domains/3 ips set up:  myFooDomain, myBarDomain, myFlubberDomain @
111.111.111.1, 111.111.111.2, 111.111.111.3 respectively
       I am also relaying my email out to my isp.  myIspDomain.com (Ithought
this would be better than sending it directly ??)

       I am running bind 9 but also have my domain names registered with
myIspDomain.

This is the log for 1 sent message.

Jan 15 12:08:53 phoenix postfix/smtpd[23518]: name_mask: subnet
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: mynetworks: 127.0.0.0/8
111.111.111.0/24 111.111.111.0/24 111.111.111.0/24
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: mynetworks ~?
debug_peer_list
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: mynetworks ~?
fast_flush_domains
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: mynetworks ~?
mynetworks
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: relay_domains ~?
debug_peer_list
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: relay_domains ~?
fast_flush_domains
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: relay_domains ~?
mynetworks
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: relay_domains ~?
permit_mx_backup_networks
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: relay_domains ~?
qmqpd_authorized_clients
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: match_string: relay_domains ~?
relay_domains
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
username to 'mail'
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
password to 'xxxxxxxxxx'
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
database name to 'mail'
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: mysqlname_parse(): set table
name to 'domain'
Jan 15 12:08:53 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
select_field to 'domain_name'
Jan 15 12:08:54 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
where_field to 'domain_name'
Jan 15 12:08:54 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
additional_conditions to ''
Jan 15 12:08:54 phoenix postfix/smtpd[23518]: mysqlname_parse(): adding host
'localhost' to list of mysql server hosts
Jan 15 12:08:54 phoenix postfix/smtpd[23518]: dict_open:
mysql:/etc/postfix/mysql-mydestination.cf
Jan 15 12:08:55 phoenix postfix/smtpd[23518]: match_string:
permit_mx_backup_networks ~? debug_peer_list
Jan 15 12:08:55 phoenix postfix/smtpd[23518]: match_string:
permit_mx_backup_networks ~? fast_flush_domains
Jan 15 12:08:55 phoenix postfix/smtpd[23518]: match_string:
permit_mx_backup_networks ~? mynetworks
Jan 15 12:08:55 phoenix postfix/smtpd[23518]: match_string:
permit_mx_backup_networks ~? permit_mx_backup_networks
Jan 15 12:08:56 phoenix postfix/smtpd[23518]: connect to subsystem
private/proxymap
Jan 15 12:08:56 phoenix postfix/smtpd[23518]: send attr request = open
Jan 15 12:08:57 phoenix postfix/smtpd[23518]: send attr table =
unix:passwd.byname
Jan 15 12:08:57 phoenix postfix/smtpd[23518]: send attr flags = 64
Jan 15 12:08:57 phoenix postfix/smtpd[23518]: private/proxymap socket:
wanted attribute: status
Jan 15 12:08:57 phoenix postfix/smtpd[23518]: input attribute name: status
Jan 15 12:08:58 phoenix postfix/smtpd[23518]: input attribute value: 0
Jan 15 12:08:58 phoenix postfix/smtpd[23518]: private/proxymap socket:
wanted attribute: flags
Jan 15 12:08:58 phoenix postfix/smtpd[23518]: input attribute name: flags
Jan 15 12:08:58 phoenix postfix/smtpd[23518]: input attribute value: 80
Jan 15 12:08:59 phoenix postfix/smtpd[23518]: private/proxymap socket:
wanted attribute: (list terminator)
Jan 15 12:08:59 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:08:59 phoenix postfix/smtpd[23518]: dict_proxy_open: connect to
map=unix:passwd.byname status=0 server_flags=0120
Jan 15 12:08:59 phoenix postfix/smtpd[23518]: dict_open:
proxy:unix:passwd.byname
Jan 15 12:09:00 phoenix postfix/smtpd[23518]: dict_open: hash:/etc/aliases
Jan 15 12:09:00 phoenix postfix/smtpd[23518]: dict_open:
hash:/etc/postfix/virtual
Jan 15 12:09:00 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
username to 'mail'
Jan 15 12:09:01 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
password to 'xxxxxxxxxxx'
Jan 15 12:09:01 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
database name to 'mail'
Jan 15 12:09:01 phoenix postfix/smtpd[23518]: mysqlname_parse(): set table
name to 'virtual'
Jan 15 12:09:01 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
select_field to 'dest'
Jan 15 12:09:02 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
where_field to 'alias'
Jan 15 12:09:02 phoenix postfix/smtpd[23518]: mysqlname_parse(): set
additional_conditions to 'and status = '1' order by alias desc'
Jan 15 12:09:02 phoenix postfix/smtpd[23518]: mysqlname_parse(): adding host
'localhost' to list of mysql server hosts
Jan 15 12:09:03 phoenix postfix/smtpd[23518]: dict_open:
mysql:/etc/postfix/mysql-virtual.cf
Jan 15 12:09:03 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? debug_peer_list
Jan 15 12:09:03 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? fast_flush_domains
Jan 15 12:09:03 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? mynetworks
Jan 15 12:09:04 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? permit_mx_backup_networks
Jan 15 12:09:04 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? qmqpd_authorized_clients
Jan 15 12:09:04 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? relay_domains
Jan 15 12:09:04 phoenix postfix/smtpd[23518]: match_string:
smtpd_access_maps ~? smtpd_access_maps
Jan 15 12:09:05 phoenix postfix/smtpd[23518]: match_string: debug_peer_list
~? debug_peer_list
Jan 15 12:09:05 phoenix postfix/smtpd[23518]: attr_clnt_create:
transport=local endpoint=private/anvil
Jan 15 12:09:05 phoenix postfix/smtpd[23518]: watchdog_create: 0x8090550
18000
Jan 15 12:09:05 phoenix postfix/smtpd[23518]: watchdog_stop: 0x8090550
Jan 15 12:09:06 phoenix postfix/smtpd[23518]: watchdog_start: 0x8090550
Jan 15 12:09:06 phoenix postfix/smtpd[23518]: connection established
Jan 15 12:09:06 phoenix postfix/smtpd[23518]: master_notify: status 0
Jan 15 12:09:07 phoenix postfix/smtpd[23518]: name_mask: resource
Jan 15 12:09:07 phoenix postfix/smtpd[23518]: name_mask: software
Jan 15 12:09:07 phoenix postfix/smtpd[23518]: name_mask: noanonymous
Jan 15 12:09:07 phoenix postfix/smtpd[23518]: connect from
xxxxxxxxxxxxxxxxxxxxxxxxxx
Jan 15 12:09:08 phoenix postfix/smtpd[23518]: match_list_match:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx: no match
Jan 15 12:09:08 phoenix postfix/smtpd[23518]: match_list_match:
xxx.xxx.xxx.xxx: no match
Jan 15 12:09:08 phoenix postfix/smtpd[23518]: match_list_match:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx: no match
Jan 15 12:09:08 phoenix postfix/smtpd[23518]: match_list_match:
xxx.xxx.xxx.xxx: no match
Jan 15 12:09:09 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 127.0.0.1
Jan 15 12:09:09 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 127.0.0.1
Jan 15 12:09:09 phoenix postfix/smtpd[23518]: match_list_match:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx: no match
Jan 15 12:09:09 phoenix postfix/smtpd[23518]: match_list_match:
xxx.xxx.xxx.xxx: no match
Jan 15 12:09:10 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 127.0.0.0/8
Jan 15 12:09:10 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 127.0.0.0/8
Jan 15 12:09:10 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 111.111.111.0/24
Jan 15 12:09:11 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 111.111.111.0/24
Jan 15 12:09:11 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 111.111.111.0/24
Jan 15 12:09:11 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 111.111.111.0/24
Jan 15 12:09:11 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 111.111.111.0/24
Jan 15 12:09:12 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 111.111.111.0/24
Jan 15 12:09:12 phoenix postfix/smtpd[23518]: match_list_match:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx: no match
Jan 15 12:09:12 phoenix postfix/smtpd[23518]: match_list_match:
xxx.xxx.xxx.xxx: no match
Jan 15 12:09:12 phoenix postfix/smtpd[23518]: attr_clnt_connect: connected
to private/anvil
Jan 15 12:09:13 phoenix postfix/smtpd[23518]: send attr request = connect
Jan 15 12:09:13 phoenix postfix/smtpd[23518]: send attr ident =
smtp:xxx.xxx.xxx.xxx
Jan 15 12:09:13 phoenix postfix/smtpd[23518]: private/anvil: wanted
attribute: status
Jan 15 12:09:14 phoenix postfix/smtpd[23518]: input attribute name: status
Jan 15 12:09:14 phoenix postfix/smtpd[23518]: input attribute value: 0
Jan 15 12:09:14 phoenix postfix/smtpd[23518]: private/anvil: wanted
attribute: count
Jan 15 12:09:14 phoenix postfix/smtpd[23518]: input attribute name: count
Jan 15 12:09:15 phoenix postfix/smtpd[23518]: input attribute value: 1
Jan 15 12:09:15 phoenix postfix/smtpd[23518]: private/anvil: wanted
attribute: rate
Jan 15 12:09:15 phoenix postfix/smtpd[23518]: input attribute name: rate
Jan 15 12:09:15 phoenix postfix/smtpd[23518]: input attribute value: 1
Jan 15 12:09:16 phoenix postfix/smtpd[23518]: private/anvil: wanted
attribute: (list terminator)
Jan 15 12:09:16 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:09:16 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 220
mail.myFooDomain.com ESMTP Postfix
Jan 15 12:09:17 phoenix postfix/smtpd[23518]: watchdog_pat: 0x8090550
Jan 15 12:09:17 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: EHLO
troymckinnonAntiBot
Jan 15 12:09:17 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]:
250-mail.myFooDomain.com
Jan 15 12:09:17 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250-PIPELINING
Jan 15 12:09:18 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250-SIZE 10240000
Jan 15 12:09:18 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250-VRFY
Jan 15 12:09:18 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250-ETRN
Jan 15 12:09:18 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250-AUTH LOGIN PLAIN
Jan 15 12:09:19 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250-AUTH=LOGIN PLAIN
Jan 15 12:09:19 phoenix postfix/smtpd[23518]: match_list_match:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx: no match
Jan 15 12:09:19 phoenix postfix/smtpd[23518]: match_list_match:
xxx.xxx.xxx.xxx: no match
Jan 15 12:09:20 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250 8BITMIME
Jan 15 12:09:20 phoenix postfix/smtpd[23518]: watchdog_pat: 0x8090550
Jan 15 12:09:20 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: AUTH LOGIN
Jan 15 12:09:20 phoenix postfix/smtpd[23518]: smtpd_sasl_authenticate:
sasl_method LOGIN
Jan 15 12:09:21 phoenix postfix/smtpd[23518]: smtpd_sasl_authenticate:
uncoded challenge: Username:
Jan 15 12:09:21 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 334 asdfasdfasdfasdf
Jan 15 12:09:21 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]:
asdfasdfasdfasdfasdfasfdasfdasfasfasdfasdf=
Jan 15 12:09:21 phoenix postfix/smtpd[23518]: smtpd_sasl_authenticate:
decoded response: me.myBarDomain.com
Jan 15 12:09:22 phoenix postfix/smtpd[23518]: smtpd_sasl_authenticate:
uncoded challenge: Password:
Jan 15 12:09:22 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 334 asdfasdfasd
Jan 15 12:09:22 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: asdfasfdasdfasd=
Jan 15 12:09:22 phoenix postfix/smtpd[23518]: smtpd_sasl_authenticate:
decoded response: xxxxxxxxx
Jan 15 12:09:23 phoenix saslauthd[905]: pam_sm_authenticate called.
Jan 15 12:09:23 phoenix saslauthd[905]: dbuser changed.
Jan 15 12:09:23 phoenix saslauthd[905]: dbpasswd changed.
Jan 15 12:09:24 phoenix saslauthd[905]: host changed.
Jan 15 12:09:24 phoenix saslauthd[905]: database changed.
Jan 15 12:09:24 phoenix saslauthd[905]: table changed.
Jan 15 12:09:24 phoenix saslauthd[905]: usercolumn changed.
Jan 15 12:09:25 phoenix saslauthd[905]: passwdcolumn changed.
Jan 15 12:09:25 phoenix saslauthd[905]: crypt changed.
Jan 15 12:09:25 phoenix saslauthd[905]: logtable changed.
Jan 15 12:09:26 phoenix saslauthd[905]: logmsgcolumn changed.
Jan 15 12:09:26 phoenix saslauthd[905]: logusercolumn changed.
Jan 15 12:09:26 phoenix saslauthd[905]: loghostcolumn changed.
Jan 15 12:09:26 phoenix saslauthd[905]: logpidcolumn changed.
Jan 15 12:09:27 phoenix saslauthd[905]: logtimecolumn changed.
Jan 15 12:09:27 phoenix saslauthd[905]: db_connect  called.
Jan 15 12:09:27 phoenix saslauthd[905]: returning 0 .
Jan 15 12:09:28 phoenix saslauthd[905]: db_checkpasswd called.
Jan 15 12:09:28 phoenix saslauthd[905]: pam_mysql: where clause =
Jan 15 12:09:28 phoenix saslauthd[905]: SELECT password FROM accountuser
WHERE username='me.myBarDomain.com'
Jan 15 12:09:28 phoenix saslauthd[905]: sqlLog called.
Jan 15 12:09:29 phoenix saslauthd[905]: insert into log (msg, user, host,
pid, time) values('AUTH SUCCESSFUL', 'me.myBarDomain.com', '', '905', NOW())
Jan 15 12:09:29 phoenix saslauthd[905]: Returning 0
Jan 15 12:09:29 phoenix saslauthd[905]: returning 0 .
Jan 15 12:09:29 phoenix saslauthd[905]: returning 0.
Jan 15 12:09:30 phoenix saslauthd[905]: pam_mysql: acct_mgmt called but not
implemented. Dont panic though :)
Jan 15 12:09:30 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 235 Authentication
successful
Jan 15 12:09:30 phoenix postfix/smtpd[23518]: watchdog_pat: 0x8090550
Jan 15 12:09:31 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: MAIL FROM:
<me at myBarDomain.com>
Jan 15 12:09:31 phoenix postfix/smtpd[23518]: extract_addr: input:
<me at myBarDomain.com>
Jan 15 12:09:31 phoenix postfix/smtpd[23518]: extract_addr: result:
me at myBarDomain.com
Jan 15 12:09:31 phoenix postfix/smtpd[23518]: fsspace: .: block size 4096,
blocks free 28414952
Jan 15 12:09:32 phoenix postfix/smtpd[23518]: smtpd_check_size: blocks 4096
avail 28414952 min_free 0 msg_size_limit 10240000
Jan 15 12:09:32 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250 Ok
Jan 15 12:09:32 phoenix postfix/smtpd[23518]: watchdog_pat: 0x8090550
Jan 15 12:09:33 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: RCPT TO:
<troymckinnonAntiBot{@}hotmail.com>
Jan 15 12:09:33 phoenix postfix/smtpd[23518]: extract_addr: input:
<troymckinnonAntiBot{@}hotmail.com>
Jan 15 12:09:33 phoenix postfix/smtpd[23518]: extract_addr: result:
troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:33 phoenix postfix/smtpd[23518]: connect to subsystem
private/rewrite
Jan 15 12:09:34 phoenix postfix/smtpd[23518]: send attr request = rewrite
Jan 15 12:09:34 phoenix postfix/smtpd[23518]: send attr rule = canonicalize
Jan 15 12:09:34 phoenix postfix/smtpd[23518]: send attr address = postmaster
Jan 15 12:09:34 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: address
Jan 15 12:09:35 phoenix postfix/smtpd[23518]: input attribute name: address
Jan 15 12:09:35 phoenix postfix/smtpd[23518]: input attribute value:
postmaster at myFooDomain.com
Jan 15 12:09:35 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: (list terminator)
Jan 15 12:09:36 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:09:36 phoenix postfix/smtpd[23518]: rewrite_clnt: canonicalize:
postmaster -> postmaster at myFooDomain.com
Jan 15 12:09:36 phoenix postfix/smtpd[23518]: >>> START Recipient address
RESTRICTIONS <<<
Jan 15 12:09:36 phoenix postfix/smtpd[23518]: generic_checks:
name=permit_sasl_authenticated
Jan 15 12:09:37 phoenix postfix/smtpd[23518]: generic_checks:
name=permit_sasl_authenticated status=1
Jan 15 12:09:37 phoenix postfix/smtpd[23518]: >>> CHECKING RECIPIENT MAPS
<<<
Jan 15 12:09:37 phoenix postfix/smtpd[23518]: send attr request = rewrite
Jan 15 12:09:37 phoenix postfix/smtpd[23518]: send attr rule = canonicalize
Jan 15 12:09:38 phoenix postfix/smtpd[23518]: send attr address =
troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:38 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: address
Jan 15 12:09:38 phoenix postfix/smtpd[23518]: input attribute name: address
Jan 15 12:09:39 phoenix postfix/smtpd[23518]: input attribute value:
troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:39 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: (list terminator)
Jan 15 12:09:39 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:09:39 phoenix postfix/smtpd[23518]: rewrite_clnt: canonicalize:
troymckinnonAntiBot{@}hotmail.com -> troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:40 phoenix postfix/smtpd[23518]: send attr request = resolve
Jan 15 12:09:40 phoenix postfix/smtpd[23518]: send attr address =
troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:40 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: transport
Jan 15 12:09:40 phoenix postfix/smtpd[23518]: input attribute name:
transport
Jan 15 12:09:41 phoenix postfix/smtpd[23518]: input attribute value: smtp
Jan 15 12:09:41 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: nexthop
Jan 15 12:09:41 phoenix postfix/smtpd[23518]: input attribute name: nexthop
Jan 15 12:09:42 phoenix postfix/smtpd[23518]: input attribute value:
mail.myIspDomain.com
Jan 15 12:09:42 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: recipient
Jan 15 12:09:42 phoenix postfix/smtpd[23518]: input attribute name:
recipient
Jan 15 12:09:42 phoenix postfix/smtpd[23518]: input attribute value:
troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:43 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: flags
Jan 15 12:09:43 phoenix postfix/smtpd[23518]: input attribute name: flags
Jan 15 12:09:43 phoenix postfix/smtpd[23518]: input attribute value: 4096
Jan 15 12:09:43 phoenix postfix/smtpd[23518]: private/rewrite socket: wanted
attribute: (list terminator)
Jan 15 12:09:44 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:09:44 phoenix postfix/smtpd[23518]: resolve_clnt:
`troymckinnonAntiBot{@}hotmail.com' -> t=`smtp' h=`mail.myIspDomain.com'
r=`troymckinnonAntiBot{@}hotmail.com'
Jan 15 12:09:44 phoenix postfix/smtpd[23518]: ctable_locate: install entry
key troymckinnonAntiBot{@}hotmail.com
Jan 15 12:09:45 phoenix postfix/smtpd[23518]: maps_find:
recipient_canonical_maps: troymckinnonAntiBot{@}hotmail.com: not found
Jan 15 12:09:45 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mysql:/etc/postfix/mysql-mydestination.cf(0,100)
Jan 15 12:09:45 phoenix postfix/smtpd[23518]: dict_mysql_lookup using sql
query: select domain_name from domain where domain_name = 'hotmail.com'
Jan 15 12:09:45 phoenix postfix/smtpd[23518]: dict_mysql: attempting to
connect to host localhost
Jan 15 12:09:46 phoenix postfix/smtpd[23518]: dict_mysql: successful
connection to host localhost
Jan 15 12:09:46 phoenix postfix/smtpd[23518]: dict_mysql: successful query
from host localhost
Jan 15 12:09:46 phoenix postfix/smtpd[23518]: dict_mysql_lookup: retrieved 0
rows
Jan 15 12:09:46 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mail.myFooDomain.com
Jan 15 12:09:47 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
localhost.myFooDomain.com
Jan 15 12:09:47 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFooDomain.com
Jan 15 12:09:47 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mail.myFooDomain.com
Jan 15 12:09:47 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
www.myFooDomain.com
Jan 15 12:09:48 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
ftp.myFooDomain.com
Jan 15 12:09:48 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFooDomain.com
Jan 15 12:09:48 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFoo2Domain.com
Jan 15 12:09:49 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myBarDomain.com
Jan 15 12:09:49 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFlubberDomain.com
Jan 15 12:09:49 phoenix postfix/smtpd[23518]: match_list_match: hotmail.com:
no match
Jan 15 12:09:49 phoenix postfix/smtpd[23518]: maps_find:
recipient_canonical_maps: @hotmail.com: not found
Jan 15 12:09:50 phoenix postfix/smtpd[23518]: mail_addr_find:
troymckinnonAntiBot{@}hotmail.com -> (not found)
Jan 15 12:09:50 phoenix postfix/smtpd[23518]: maps_find: canonical_maps:
troymckinnonAntiBot{@}hotmail.com: not found
Jan 15 12:09:50 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mysql:/etc/postfix/mysql-mydestination.cf(0,100)
Jan 15 12:09:50 phoenix postfix/smtpd[23518]: dict_mysql_lookup using sql
query: select domain_name from domain where domain_name = 'hotmail.com'
Jan 15 12:09:51 phoenix postfix/smtpd[23518]: dict_mysql: successful query
from host localhost
Jan 15 12:09:51 phoenix postfix/smtpd[23518]: dict_mysql_lookup: retrieved 0
rows
Jan 15 12:09:51 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mail.myFooDomain.com
Jan 15 12:09:52 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
localhost.myFooDomain.com
Jan 15 12:09:52 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFooDomain.com
Jan 15 12:09:52 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mail.myFooDomain.com
Jan 15 12:09:52 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
www.myFooDomain.com
Jan 15 12:09:53 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
ftp.myFooDomain.com
Jan 15 12:09:53 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFooDomain.com
Jan 15 12:09:53 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFoo2Domain.com
Jan 15 12:09:53 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myBarDomain.com
Jan 15 12:09:54 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFlubberDomain.com
Jan 15 12:09:54 phoenix postfix/smtpd[23518]: match_list_match: hotmail.com:
no match
Jan 15 12:09:54 phoenix postfix/smtpd[23518]: maps_find: canonical_maps:
@hotmail.com: not found
Jan 15 12:09:54 phoenix postfix/smtpd[23518]: mail_addr_find:
troymckinnonAntiBot{@}hotmail.com -> (not found)
Jan 15 12:09:55 phoenix postfix/smtpd[23518]: dict_mysql_lookup using sql
query: select dest from virtual where alias =
'troymckinnonAntiBot{@}hotmail.com' and status = '1' order by alias desc
Jan 15 12:09:55 phoenix postfix/smtpd[23518]: dict_mysql: attempting to
connect to host localhost
Jan 15 12:09:55 phoenix postfix/smtpd[23518]: dict_mysql: successful
connection to host localhost
Jan 15 12:09:56 phoenix postfix/smtpd[23518]: dict_mysql: successful query
from host localhost
Jan 15 12:09:56 phoenix postfix/smtpd[23518]: dict_mysql_lookup: retrieved 0
rows
Jan 15 12:09:56 phoenix postfix/smtpd[23518]: maps_find: virtual_alias_maps:
troymckinnonAntiBot{@}hotmail.com: not found
Jan 15 12:09:56 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mysql:/etc/postfix/mysql-mydestination.cf(0,100)
Jan 15 12:09:57 phoenix postfix/smtpd[23518]: dict_mysql_lookup using sql
query: select domain_name from domain where domain_name = 'hotmail.com'
Jan 15 12:09:57 phoenix postfix/smtpd[23518]: dict_mysql: successful query
from host localhost
Jan 15 12:09:57 phoenix postfix/smtpd[23518]: dict_mysql_lookup: retrieved 0
rows
Jan 15 12:09:58 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mail.myFooDomain.com
Jan 15 12:09:58 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
localhost.myFooDomain.com
Jan 15 12:09:58 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFooDomain.com
Jan 15 12:09:58 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
mail.myFooDomain.com
Jan 15 12:09:59 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
www.myFooDomain.com
Jan 15 12:09:59 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
ftp.myFooDomain.com
Jan 15 12:09:59 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFooDomain.com
Jan 15 12:09:59 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFoo2Domain.com
Jan 15 12:10:00 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myBarDomain.com
Jan 15 12:10:00 phoenix postfix/smtpd[23518]: match_string: hotmail.com ~?
myFlubberDomain.com
Jan 15 12:10:00 phoenix postfix/smtpd[23518]: match_list_match: hotmail.com:
no match
Jan 15 12:10:00 phoenix postfix/smtpd[23518]: dict_mysql_lookup using sql
query: select dest from virtual where alias = '@hotmail.com' and status =
'1' order by alias desc
Jan 15 12:10:01 phoenix postfix/smtpd[23518]: dict_mysql: successful query
from host localhost
Jan 15 12:10:01 phoenix postfix/smtpd[23518]: dict_mysql_lookup: retrieved 0
rows
Jan 15 12:10:01 phoenix postfix/smtpd[23518]: maps_find: virtual_alias_maps:
@hotmail.com: not found
Jan 15 12:10:02 phoenix postfix/smtpd[23518]: mail_addr_find:
troymckinnonAntiBot{@}hotmail.com -> (not found)
Jan 15 12:10:02 phoenix postfix/smtpd[23518]: connect to subsystem
public/cleanup
Jan 15 12:10:02 phoenix postfix/smtpd[23518]: public/cleanup socket: wanted
attribute: queue_id
Jan 15 12:10:03 phoenix postfix/smtpd[23518]: input attribute name: queue_id
Jan 15 12:10:03 phoenix postfix/smtpd[23518]: input attribute value:
7B7B8DDDE
Jan 15 12:10:03 phoenix postfix/smtpd[23518]: public/cleanup socket: wanted
attribute: (list terminator)
Jan 15 12:10:03 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:10:04 phoenix postfix/smtpd[23518]: send attr flags = 50
Jan 15 12:10:04 phoenix postfix/smtpd[23518]: 7B7B8DDDE:
client=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx],
sasl_method=LOGIN, sasl_username=me.myBarDomain.com
Jan 15 12:10:04 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250 Ok
Jan 15 12:10:05 phoenix postfix/smtpd[23518]: watchdog_pat: 0x8090550
Jan 15 12:10:05 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: DATA
Jan 15 12:10:05 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 354 End data with
<CR><LF>.<CR><LF>
Jan 15 12:10:06 phoenix postfix/smtpd[23518]: public/cleanup socket: wanted
attribute: status
Jan 15 12:10:06 phoenix postfix/cleanup[23535]: 7B7B8DDDE:
message-id=<01290d1c3dba2as$fc3d766e0$0902a8c0 at tmckinnon2>
Jan 15 12:10:06 phoenix postfix/smtpd[23518]: input attribute name: status
Jan 15 12:10:06 phoenix postfix/qmgr[21606]: 7B7B8DDDE:
from=<me at myBarDomain.com>, size=1449, nrcpt=1 (queue active)
Jan 15 12:10:06 phoenix postfix/smtpd[23518]: input attribute value: 0
Jan 15 12:10:06 phoenix postfix/smtp[23539]: 7B7B8DDDE:
to=<troymckinnonAntiBot{@}hotmail.com>,
relay=mail.myIspDomain.com[xxx.xxx.xxx.xxx], delay=35, status=sent (250
Message queued)
Jan 15 12:10:07 phoenix postfix/smtpd[23518]: public/cleanup socket: wanted
attribute: reason
Jan 15 12:10:07 phoenix postfix/qmgr[21606]: 7B7B8DDDE: removed
Jan 15 12:10:07 phoenix postfix/smtpd[23518]: input attribute name: reason
Jan 15 12:10:08 phoenix postfix/smtpd[23518]: input attribute value: (end)
Jan 15 12:10:08 phoenix postfix/smtpd[23518]: public/cleanup socket: wanted
attribute: (list terminator)
Jan 15 12:10:08 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:10:09 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 250 Ok: queued as
7B7B8DDDE
Jan 15 12:10:09 phoenix postfix/smtpd[23518]: watchdog_pat: 0x8090550
Jan 15 12:10:09 phoenix postfix/smtpd[23518]: <
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: QUIT
Jan 15 12:10:10 phoenix postfix/smtpd[23518]: >
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]: 221 Bye
Jan 15 12:10:10 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 127.0.0.0/8
Jan 15 12:10:10 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 127.0.0.0/8
Jan 15 12:10:10 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 111.111.111.0/24
Jan 15 12:10:11 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 111.111.111.0/24
Jan 15 12:10:11 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 111.111.111.0/24
Jan 15 12:10:11 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 111.111.111.0/24
Jan 15 12:10:11 phoenix postfix/smtpd[23518]: match_hostname:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx ~? 111.111.111.0/24
Jan 15 12:10:12 phoenix postfix/smtpd[23518]: match_hostaddr:
xxx.xxx.xxx.xxx ~? 111.111.111.0/24
Jan 15 12:10:12 phoenix postfix/smtpd[23518]: match_list_match:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx: no match
Jan 15 12:10:12 phoenix postfix/smtpd[23518]: match_list_match:
xxx.xxx.xxx.xxx: no match
Jan 15 12:10:13 phoenix postfix/smtpd[23518]: send attr request = disconnect
Jan 15 12:10:13 phoenix postfix/smtpd[23518]: send attr ident =
smtp:xxx.xxx.xxx.xxx
Jan 15 12:10:13 phoenix postfix/smtpd[23518]: private/anvil: wanted
attribute: status
Jan 15 12:10:13 phoenix postfix/smtpd[23518]: input attribute name: status
Jan 15 12:10:14 phoenix postfix/smtpd[23518]: input attribute value: 0
Jan 15 12:10:14 phoenix postfix/smtpd[23518]: private/anvil: wanted
attribute: (list terminator)
Jan 15 12:10:14 phoenix postfix/smtpd[23518]: input attribute name: (end)
Jan 15 12:10:14 phoenix postfix/smtpd[23518]: disconnect from
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx]
Jan 15 12:10:15 phoenix postfix/smtpd[23518]: master_notify: status 1
Jan 15 12:10:15 phoenix postfix/smtpd[23518]: connection closed
Jan 15 12:10:15 phoenix postfix/smtpd[23518]: watchdog_stop: 0x8090550
Jan 15 12:10:16 phoenix postfix/smtpd[23518]: watchdog_start: 0x8090550
Jan 15 12:10:16 phoenix postfix/smtpd[23518]: private/anvil stream
disconnect
Jan 15 12:10:16 phoenix postfix/smtpd[23518]: watchdog_stop: 0x8090550
Jan 15 12:10:16 phoenix postfix/smtpd[23518]: watchdog_start: 0x8090550
Jan 15 12:10:36 phoenix postfix/smtpd[23518]: proxymap stream disconnect
Jan 15 12:10:36 phoenix postfix/smtpd[23518]: watchdog_stop: 0x8090550
Jan 15 12:10:36 phoenix postfix/smtpd[23518]: watchdog_start: 0x8090550
Jan 15 12:11:20 phoenix postfix/smtpd[23518]: rewrite stream disconnect
Jan 15 12:11:20 phoenix postfix/smtpd[23518]: watchdog_stop: 0x8090550
Jan 15 12:11:20 phoenix postfix/smtpd[23518]: watchdog_start: 0x8090550
Jan 15 12:11:55 phoenix postfix/smtpd[23518]: idle timeout -- exiting
Jan 15 12:12:05 phoenix master[23561]: about to exec
/usr/lib/cyrus/bin/ctl_cyrusdb
Jan 15 12:12:05 phoenix ctl_cyrusdb[23561]: checkpointing cyrus databases
Jan 15 12:12:05 phoenix ctl_cyrusdb[23561]: archiving log file:
/var/imap/db/log.0000000001
Jan 15 12:12:05 phoenix ctl_cyrusdb[23561]: archiving database file:
/var/imap/mailboxes.db
Jan 15 12:12:05 phoenix ctl_cyrusdb[23561]: done checkpointing cyrus
databases
Jan 15 12:12:05 phoenix master[934]: process 23561 exited, status 0




--------- this is just checking for messages.. note time of almost 1
minute ---------


Jan 15 12:05:37 phoenix saslauthd[905]: pam_mysql: acct_mgmt called but not
implemented. Dont panic though :)
Jan 15 12:05:37 phoenix imapd[23461]: login:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx] me.myFooDomain.com
plaintext
Jan 15 12:06:13 phoenix imapd[23461]: accepted connection
Jan 15 12:06:13 phoenix saslauthd[902]: pam_sm_authenticate called.
Jan 15 12:06:13 phoenix saslauthd[902]: dbuser changed.
Jan 15 12:06:13 phoenix saslauthd[902]: dbpasswd changed.
Jan 15 12:06:13 phoenix saslauthd[902]: host changed.
Jan 15 12:06:13 phoenix saslauthd[902]: database changed.
Jan 15 12:06:13 phoenix saslauthd[902]: table changed.
Jan 15 12:06:13 phoenix saslauthd[902]: usercolumn changed.
Jan 15 12:06:13 phoenix saslauthd[902]: passwdcolumn changed.
Jan 15 12:06:13 phoenix saslauthd[902]: crypt changed.
Jan 15 12:06:13 phoenix saslauthd[902]: logtable changed.
Jan 15 12:06:13 phoenix saslauthd[902]: logmsgcolumn changed.
Jan 15 12:06:13 phoenix saslauthd[902]: logusercolumn changed.
Jan 15 12:06:13 phoenix saslauthd[902]: loghostcolumn changed.
Jan 15 12:06:14 phoenix saslauthd[902]: logpidcolumn changed.
Jan 15 12:06:14 phoenix saslauthd[902]: logtimecolumn changed.
Jan 15 12:06:14 phoenix saslauthd[902]: db_connect  called.
Jan 15 12:06:14 phoenix saslauthd[902]: returning 0 .
Jan 15 12:06:15 phoenix saslauthd[902]: db_checkpasswd called.
Jan 15 12:06:15 phoenix saslauthd[902]: pam_mysql: where clause =
Jan 15 12:06:15 phoenix saslauthd[902]: SELECT password FROM accountuser
WHERE username='me.myFooDomain.com'
Jan 15 12:06:15 phoenix saslauthd[902]: sqlLog called.
Jan 15 12:06:16 phoenix saslauthd[902]: insert into log (msg, user, host,
pid, time) values('AUTH SUCCESSFUL', 'me.myFooDomain.com', '', '902', NOW())
Jan 15 12:06:16 phoenix saslauthd[902]: Returning 0
Jan 15 12:06:16 phoenix saslauthd[902]: returning 0 .
Jan 15 12:06:17 phoenix saslauthd[902]: returning 0.
Jan 15 12:06:17 phoenix saslauthd[902]: pam_mysql: acct_mgmt called but not
implemented. Dont panic though :)
Jan 15 12:06:17 phoenix imapd[23461]: login:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx] me.myFooDomain.com
plaintext
Jan 15 12:06:17 phoenix imapd[23461]: seen_db: user me^myFooDomain^com
opened /var/imap/user/m/me^myFooDomain^com.seen
Jan 15 12:06:18 phoenix imapd[23461]: accepted connection
Jan 15 12:06:18 phoenix saslauthd[904]: pam_sm_authenticate called.
Jan 15 12:06:18 phoenix saslauthd[904]: dbuser changed.
Jan 15 12:06:18 phoenix saslauthd[904]: dbpasswd changed.
Jan 15 12:06:19 phoenix saslauthd[904]: host changed.
Jan 15 12:06:19 phoenix saslauthd[904]: database changed.
Jan 15 12:06:19 phoenix saslauthd[904]: table changed.
Jan 15 12:06:20 phoenix saslauthd[904]: usercolumn changed.
Jan 15 12:06:20 phoenix saslauthd[904]: passwdcolumn changed.
Jan 15 12:06:20 phoenix saslauthd[904]: crypt changed.
Jan 15 12:06:21 phoenix saslauthd[904]: logtable changed.
Jan 15 12:06:21 phoenix saslauthd[904]: logmsgcolumn changed.
Jan 15 12:06:21 phoenix saslauthd[904]: logusercolumn changed.
Jan 15 12:06:21 phoenix saslauthd[904]: loghostcolumn changed.
Jan 15 12:06:22 phoenix saslauthd[904]: logpidcolumn changed.
Jan 15 12:06:22 phoenix saslauthd[904]: logtimecolumn changed.
Jan 15 12:06:22 phoenix saslauthd[904]: db_connect  called.
Jan 15 12:06:22 phoenix saslauthd[904]: returning 0 .
Jan 15 12:06:23 phoenix saslauthd[904]: db_checkpasswd called.
Jan 15 12:06:23 phoenix saslauthd[904]: pam_mysql: where clause =
Jan 15 12:06:23 phoenix saslauthd[904]: SELECT password FROM accountuser
WHERE username='me.myFooDomain.com'
Jan 15 12:06:24 phoenix saslauthd[904]: sqlLog called.
Jan 15 12:06:24 phoenix saslauthd[904]: insert into log (msg, user, host,
pid, time) values('AUTH SUCCESSFUL', 'me.myFooDomain.com', '', '904', NOW())
Jan 15 12:06:24 phoenix saslauthd[904]: Returning 0
Jan 15 12:06:24 phoenix saslauthd[904]: returning 0 .
Jan 15 12:06:25 phoenix saslauthd[904]: returning 0.
Jan 15 12:06:25 phoenix saslauthd[904]: pam_mysql: acct_mgmt called but not
implemented. Dont panic though :)
Jan 15 12:06:25 phoenix imapd[23461]: login:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[xxx.xxx.xxx.xxx] me.myFooDomain.com
plaintext
Jan 15 12:06:26 phoenix imapd[23461]: open: user me^myFooDomain^com opened
INBOX