Re: [Exim] Exim/MySql socket closing bug?

Top Page
Delete this message
Reply to this message
Author: robert rotman
Date:  
To: Ross West
CC: exim-users
Subject: Re: [Exim] Exim/MySql socket closing bug?
Hi!

I've the same problem and i once mailed Phillipp about this but
he was not able to find the missing mysq_close()
(or did not find the time)...

did you try to patch the mysql-code?
I'm not that familiar with the exim-code to do this.

But's really a problem for me because it makes 100 of Mb's log-enties each
day and then it's hard to find "real" errors in this logs...

robert

On Mon, 9 Jul 2001, Ross West wrote:

> Hi there,
>
> I think I've found a bug in the MySql portion of the code when it is
> being used in an appendfile transport.
>
> Quick info:
>         exim v3.30, compiled with gcc 3.0, solaris 8.

>
> Plain description of the problem:
> Exim will open a tcp connection to the MySQL server and then forget the
> close the socket when finished delivery and exiting causing an warning
> error on the mysql server to be generated/logged and delayed shutdown
> of the corresponding process.
>
> More in depth description:
> What I've been able to determine (I haven't gone through code yet),
> Exim will correctly do the entire open/query/close process with the
> MySQL server when dealing with a director/router. Ie: when specifing
> the "search_type = mysql" option with a corresponding "query = ..." line
> in the configuration. But when using a $lookup statement, exim doesn't
> close the connection properly (search_tidyup doesn't know of the new
> connection). Normally not really a problem, but MySQL daemon will
> generate a line in it's logfile as well as take ~30 seconds to timeout
> the connection, which causes a partial DOS against the database if enough
> queries are generated (which we found out when stress testing it. :-)
>
> See end of the message for a complete -d9 dump of a test message being
> generated on the commandline.
>
> Hopefully it's enough to find the problem. If you have any questions,
> don't hestiate to email me: westr@???
>
> PS: Noted that exim doesn't use the internal database cache between
> queries either.
>
> Cheers,
> Ross.
>
> Here's a clip from the configuration file of a good director:
>
> -=- Start
> pop3_user:
> driver = aliasfile
> search_type = mysql
> query = "select spoolfile from pop3 where UID='$local_part' and
> active='1'"
> transport = local_delivery
> -=- End
>
> And here's the clip of the ${lookup... statement
>
> -=- Start
> local_delivery:
> driver = appendfile
> file = ${lookup mysql{select spoolfile from pop3 where
> UID='$local_part' and active='1'}{$value}fail}
> delivery_date_add
> envelope_to_add
> return_path_add
> user = exim
> group = mail
> mode = 0660
> -=- End
>
>
> Note: Server+password sanitized, but work correctly.
>
> -=- exim -d9 westr@???
> Exim version 3.30 debug level 9 uid=101 gid=14
> probably ndbm
> Caller is an admin user
> originator: uid=101 gid=14 login=westr name=
> sender address = westr@???
> set_process_info: 4328 accepting a local non-SMTP message from <westr@???>
> Sender: westr@???
> Recipients:
> westr@???
> search_tidyup called
> >>Original headers (size=69):
> From: <westr@???>
> To: <westr@???>
> Subject: Exim Test 2
>
> rewrite_one_header: type=F:
>   From: <westr@???>
> rewrite_one_header: type=T:
>   To: <westr@???>
> >>Final headers:
> P Received: from westr by blinky with local (Exim 3.30 #15)
>         id 15JiB1-00017o-00
>         for westr@???; Mon, 09 Jul 2001 17:03:11 -0400
> F From: <westr@???>
> T To: <westr@???>
>   Subject: Exim Test 2
> I Message-Id: <E15JiB1-00017o-00@blinky>
>   Date: Mon, 09 Jul 2001 17:03:11 -0400

>
> search_tidyup called
> Data file written for message 15JiB1-00017o-00
> Writing spool header file
> Size of headers = 280
> LOG: 0 MAIN
>   <= westr@??? U=westr P=local S=324
> search_tidyup called
> exec /usr/local/bin/exim -d9 -Mc 15JiB1-00017o-00      
> Exim version 3.30 debug level 9 uid=50 gid=50
> probably ndbm
> Caller is an admin user
> Caller is a trusted user
> set_process_info:  4329 delivering specified messages
> delivering message 15JiB1-00017o-00
> set_process_info:  4329 delivering 15JiB1-00017o-00
> Opened spool file 15JiB1-00017o-00-H
> user=westr uid=101 gid=14 sender=westr@???
> sender_local=1 resent=no ident=westr
> Non-recipients:
> Empty Tree
> ---- End of tree ----
> recipients_count=1
> body_linecount=5 message_linecount=8
> Delivery address list:
>   westr@??? 
> locked /remote/spool0/blinky/db/retry.lockfile
> opened DB file /remote/spool0/blinky/db/retry: flags=0

> >>>>>>>>>>>>>>>>>>>>>>>>
> Considering: westr@???
> pipeman.ca in local_domains? yes (matched pipeman.ca)
> pipeman.ca in percent_hack_domains? no (end of list)
> unique = westr@???
> dbfn_read: key=D:westr@???
> westr@???: queued for directing
> >>>>>>>>>>>>>>>>>>>>>>>>
> directing westr@???
> calling domain_aliases director
> df_lookup entered: search type = mysql
> domain_aliases director: mysql query=select destination from exim where
> email='westr@???'
> search_open: mysql "NULL"
> search_find: file="NULL"
> key="select destination from exim where email='westr@???'" partial=-1
> LRU list:
> internal_search_find: file="NULL"
> type=mysql key="select destination from exim where email='westr@???'"
> database lookup required for select destination from exim where email='westr@???'
> MYSQL query: select destination from exim where email='westr@???'
> MYSQL new connection: ***Connection INfo Removed***
> lookup yielded: westr
> parse_extract_addresses: westr
> extract item: westr
> domain_aliases director generated westr@???
> errors_to=NULL transport=NULL
> uid=unset gid=unset home=NULL
> domain_aliases director succeeded for westr
> locked /remote/spool0/blinky/db/retry.lockfile
> opened DB file /remote/spool0/blinky/db/retry: flags=0
> >>>>>>>>>>>>>>>>>>>>>>>>
> Considering: westr@???
> pipeman.ca in local_domains? yes (matched pipeman.ca)
> pipeman.ca in percent_hack_domains? no (end of list)
> unique = \westr@???
> dbfn_read: key=D:westr@???
> westr@???: queued for directing
> >>>>>>>>>>>>>>>>>>>>>>>>
> directing westr@???
> domain_aliases director skipped: previously directed westr@???
> calling domain_aliases_catchall director
> df_lookup entered: search type = mysql
> domain_aliases_catchall director: mysql query=select destination from exim where
> email='*@pipeman.ca'
> search_open: mysql "NULL"
> cached open
> search_find: file="NULL"
> key="select destination from exim where email='*@pipeman.ca'" partial=-1
> LRU list:
> internal_search_find: file="NULL"
> type=mysql key="select destination from exim where email='*@pipeman.ca'"
> database lookup required for select destination from exim where email='*@pipeman.ca'
> MYSQL query: select destination from exim where email='*@pipeman.ca'
> MYSQL using cached connection for ***Connection Info Removed***
> MYSQL: no data found
> lookup failed
> domain_aliases_catchall director declined for westr: MYSQL: no data found
> westr in "postmaster"? no (end of list)
> force_postmaster director skipped: local part mismatch
> calling pop3_user director
> df_lookup entered: search type = mysql
> pop3_user director: mysql query=select spoolfile from pop3 where UID='westr' and active='1'
> search_open: mysql "NULL"
> cached open
> search_find: file="NULL"
> key="select spoolfile from pop3 where UID='westr' and active='1'" partial=-1
> LRU list:
> internal_search_find: file="NULL"
> type=mysql key="select spoolfile from pop3 where UID='westr' and active='1'"
> database lookup required for select spoolfile from pop3 where UID='westr' and active='1'
> MYSQL query: select spoolfile from pop3 where UID='westr' and active='1'
> MYSQL using cached connection for ***Connection info removed***
> lookup yielded: /remote/mail0/pipeman.ca/westr
> queued for local_delivery transport: local_part=westr domain=pipeman.ca
> errors_to=NULL
> domain_data=NULL local_part_data=NULL
> pop3_user director succeeded for westr
> >>>>>>>>>>>>>>>>>>>>>>>>
> After directing:
>   Local deliveries:
>     westr@???
>   Remote deliveries:
>   Failed addresses:
>   Addresses to be routed:
>   Deferred addresses:
> search_tidyup called
> close MYSQL connection: *** Connection INFO removed ***
> >>>>>> Local deliveries >>>>>>
> locked /remote/spool0/blinky/db/retry.lockfile
> opened DB file /remote/spool0/blinky/db/retry: flags=0
> dbfn_read: key=T:westr@???
> delivering westr@??? as westr using local_delivery:
>   uid=50 gid=6 home=NULL current=/
>   auxiliary group list: <none>
> set_process_info:  4330 delivering 15JiB1-00017o-00 to westr using local_delivery
> appendfile transport entered
> search_open: mysql "NULL"
> search_find: file="NULL"
>   key="select spoolfile from pop3 where UID='westr' and active='1'" partial=-1
> LRU list:
> internal_search_find: file="NULL"
>   type=mysql key="select spoolfile from pop3 where UID='westr' and active='1'"
> database lookup required for select spoolfile from pop3 where UID='westr' and active='1'
> MYSQL query: select spoolfile from pop3 where UID='westr' and active='1'
> MYSQL new connection: ***Connection INFO removed***
> lookup yielded: /remote/mail0/pipeman.ca/westr
> appendfile: mode=660 notify_comsat=0 quota=0
>   file=/remote/mail0/pipeman.ca/westr format=unix
>   prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
>   suffix=\n
>   locking by lockfile fcntl 
> lock name: /remote/mail0/pipeman.ca/westr.lock
> hitch name: /remote/mail0/pipeman.ca/westr.lock.blinky.3b4a1c1a.000010ea
> lock file created
> mailbox /remote/mail0/pipeman.ca/westr is locked
> writing to file /remote/mail0/pipeman.ca/westr
> writing data block fd=7 size=47 timeout=0
> writing data block fd=7 size=462 timeout=0
> writing data block fd=7 size=1 timeout=0
> appendfile yields 0 with errno=0 more_errno=0
> journalled \westr@???
> local_delivery transport returned OK for westr@???
> post-process westr@??? (0)
> westr@??? succeeded: adding to nonrecipients list
> westr@???: children all complete
> LOG: 0 MAIN
>   => westr <westr@???> D=pop3_user T=local_delivery
> search_tidyup called
> set_process_info:  4329 tidying up after delivering 15JiB1-00017o-00
> Processing retry items
> Succeeded addresses:
> westr@???: no retry items
> westr@???: no retry items
> westr@???: no retry items
> Failed addresses:
> Deferred addresses:
> end of retry processing
> LOG: 0 MAIN
>   Completed
> end delivery of 15JiB1-00017o-00
> search_tidyup called
> search_tidyup called
> -=- End

>
>
>
> --
> ## List details at http://www.exim.org/mailman/listinfo/exim-users Exim details at http://www.exim.org/ ##
>


---
di. robert rotman                                   inode.graz
phone -> ++43-(0)316 813141       ++43-(0)316 818600/15 <- fax
rotman@???                      http://www.graz.inode.at/
--
while (!sleep) { $sheep++ }