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: <[EMAIL PROTECTED]> Jan 15 12:09:31 phoenix postfix/smtpd[23518]: extract_addr: input: <[EMAIL PROTECTED]> Jan 15 12:09:31 phoenix postfix/smtpd[23518]: extract_addr: result: [EMAIL PROTECTED] 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: <[EMAIL PROTECTED]> Jan 15 12:09:33 phoenix postfix/smtpd[23518]: extract_addr: input: <[EMAIL PROTECTED]> Jan 15 12:09:33 phoenix postfix/smtpd[23518]: extract_addr: result: [EMAIL PROTECTED] 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: [EMAIL PROTECTED] 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 -> [EMAIL PROTECTED] 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 = [EMAIL PROTECTED] 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: [EMAIL PROTECTED] 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: [EMAIL PROTECTED] -> [EMAIL PROTECTED] 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 = [EMAIL PROTECTED] 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: [EMAIL PROTECTED] 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: [EMAIL PROTECTED]' -> t=`smtp' h=`mail.myIspDomain.com' [EMAIL PROTECTED]' Jan 15 12:09:44 phoenix postfix/smtpd[23518]: ctable_locate: install entry key [EMAIL PROTECTED] Jan 15 12:09:45 phoenix postfix/smtpd[23518]: maps_find: recipient_canonical_maps: [EMAIL PROTECTED]: 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: [EMAIL PROTECTED] -> (not found) Jan 15 12:09:50 phoenix postfix/smtpd[23518]: maps_find: canonical_maps: [EMAIL PROTECTED]: 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: [EMAIL PROTECTED] -> (not found) Jan 15 12:09:55 phoenix postfix/smtpd[23518]: dict_mysql_lookup using sql query: select dest from virtual where alias = '[EMAIL PROTECTED]' 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: [EMAIL PROTECTED]: 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: [EMAIL PROTECTED] -> (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=<[EMAIL PROTECTED]> Jan 15 12:10:06 phoenix postfix/smtpd[23518]: input attribute name: status Jan 15 12:10:06 phoenix postfix/qmgr[21606]: 7B7B8DDDE: from=<[EMAIL PROTECTED]>, 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=<[EMAIL PROTECTED]>, 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