Log failures to extract envelope addresses from message headers. Bug 2351
[users/jgh/exim.git] / test / stderr / 2610
1 Exim version x.yz ....
2 configuration file is TESTSUITE/test-config
3 admin user
4 search_open: mysql "NULL"
5 search_find: file="NULL"
6   key="select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
7 LRU list:
8 internal_search_find: file="NULL"
9   type=mysql key="select name from them where id='ph10';"
10 database lookup required for select name from them where id='ph10';
11 MySQL query: select name from them where id='ph10';
12 MYSQL new connection: host=127.0.0.1 port=1223 socket=NULL database=test user=root
13 lookup yielded: Philip Hazel
14 search_open: mysql "NULL"
15   cached open
16 search_find: file="NULL"
17   key="select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
18 LRU list:
19 internal_search_find: file="NULL"
20   type=mysql key="select name from them where id='ph10';"
21 cached data used for lookup of select name from them where id='ph10';
22 lookup yielded: Philip Hazel
23 search_open: mysql "NULL"
24   cached open
25 search_find: file="NULL"
26   key="select name from them where id='xxxx';" partial=-1 affix=NULL starflags=0
27 LRU list:
28 internal_search_find: file="NULL"
29   type=mysql key="select name from them where id='xxxx';"
30 database lookup required for select name from them where id='xxxx';
31 MySQL query: select name from them where id='xxxx';
32 MYSQL using cached connection for 127.0.0.1:1223/test/root
33 MYSQL: no data found
34 lookup failed
35 search_open: mysql "NULL"
36   cached open
37 search_find: file="NULL"
38   key="select name from them where id='nothing';" partial=-1 affix=NULL starflags=0
39 LRU list:
40 internal_search_find: file="NULL"
41   type=mysql key="select name from them where id='nothing';"
42 database lookup required for select name from them where id='nothing';
43 MySQL query: select name from them where id='nothing';
44 MYSQL using cached connection for 127.0.0.1:1223/test/root
45 lookup yielded: 
46 search_open: mysql "NULL"
47   cached open
48 search_find: file="NULL"
49   key="select id,name from them where id='nothing';" partial=-1 affix=NULL starflags=0
50 LRU list:
51 internal_search_find: file="NULL"
52   type=mysql key="select id,name from them where id='nothing';"
53 database lookup required for select id,name from them where id='nothing';
54 MySQL query: select id,name from them where id='nothing';
55 MYSQL using cached connection for 127.0.0.1:1223/test/root
56 lookup yielded: id=nothing name="" 
57 search_open: mysql "NULL"
58   cached open
59 search_find: file="NULL"
60   key="delete from them where id='nonexist';" partial=-1 affix=NULL starflags=0
61 LRU list:
62 internal_search_find: file="NULL"
63   type=mysql key="delete from them where id='nonexist';"
64 database lookup required for delete from them where id='nonexist';
65 MySQL query: delete from them where id='nonexist';
66 MYSQL using cached connection for 127.0.0.1:1223/test/root
67 MYSQL: query was not one that returns data
68 lookup forced cache cleanup
69 lookup yielded: 0
70 search_open: mysql "NULL"
71   cached open
72 search_find: file="NULL"
73   key="select * from them where id='quote';" partial=-1 affix=NULL starflags=0
74 LRU list:
75 internal_search_find: file="NULL"
76   type=mysql key="select * from them where id='quote';"
77 database lookup required for select * from them where id='quote';
78 MySQL query: select * from them where id='quote';
79 MYSQL using cached connection for 127.0.0.1:1223/test/root
80 MYSQL: no data found
81 lookup failed
82 search_open: mysql "NULL"
83   cached open
84 search_find: file="NULL"
85   key="select * from them where id='filter';" partial=-1 affix=NULL starflags=0
86 LRU list:
87 internal_search_find: file="NULL"
88   type=mysql key="select * from them where id='filter';"
89 database lookup required for select * from them where id='filter';
90 MySQL query: select * from them where id='filter';
91 MYSQL using cached connection for 127.0.0.1:1223/test/root
92 MYSQL: no data found
93 lookup failed
94 search_open: mysql "NULL"
95   cached open
96 search_find: file="NULL"
97   key="select * from them where id='quote2';" partial=-1 affix=NULL starflags=0
98 LRU list:
99 internal_search_find: file="NULL"
100   type=mysql key="select * from them where id='quote2';"
101 database lookup required for select * from them where id='quote2';
102 MySQL query: select * from them where id='quote2';
103 MYSQL using cached connection for 127.0.0.1:1223/test/root
104 lookup yielded: name="\"stquot" id=quote2 
105 search_open: mysql "NULL"
106   cached open
107 search_find: file="NULL"
108   key="select * from them where id='nlonly';" partial=-1 affix=NULL starflags=0
109 LRU list:
110 internal_search_find: file="NULL"
111   type=mysql key="select * from them where id='nlonly';"
112 database lookup required for select * from them where id='nlonly';
113 MySQL query: select * from them where id='nlonly';
114 MYSQL using cached connection for 127.0.0.1:1223/test/root
115 MYSQL: no data found
116 lookup failed
117 search_open: mysql "NULL"
118   cached open
119 search_find: file="NULL"
120   key="servers=x:127.0.0.1::1223; select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
121 LRU list:
122 internal_search_find: file="NULL"
123   type=mysql key="servers=x:127.0.0.1::1223; select name from them where id='ph10';"
124 database lookup required for servers=x:127.0.0.1::1223; select name from them where id='ph10';
125 MySQL query: servers=x:127.0.0.1::1223; select name from them where id='ph10';
126 lookup deferred: MySQL server "x" not found in mysql_servers
127 search_open: mysql "NULL"
128   cached open
129 search_find: file="NULL"
130   key="servers=127.0.0.1::1223:x; select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
131 LRU list:
132 internal_search_find: file="NULL"
133   type=mysql key="servers=127.0.0.1::1223:x; select name from them where id='ph10';"
134 database lookup required for servers=127.0.0.1::1223:x; select name from them where id='ph10';
135 MySQL query: servers=127.0.0.1::1223:x; select name from them where id='ph10';
136 MYSQL using cached connection for 127.0.0.1:1223/test/root
137 lookup yielded: Philip Hazel
138 search_open: mysql "NULL"
139   cached open
140 search_find: file="NULL"
141   key="servers=127.0.0.1::1223/test/root/:x; select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
142 LRU list:
143 internal_search_find: file="NULL"
144   type=mysql key="servers=127.0.0.1::1223/test/root/:x; select name from them where id='ph10';"
145 database lookup required for servers=127.0.0.1::1223/test/root/:x; select name from them where id='ph10';
146 MySQL query: servers=127.0.0.1::1223/test/root/:x; select name from them where id='ph10';
147 MYSQL using cached connection for 127.0.0.1:1223/test/root
148 lookup yielded: Philip Hazel
149 search_open: mysql "NULL"
150   cached open
151 search_find: file="NULL"
152   key="servers=ip4.ip4.ip4.ip4::1223/test/root/:127.0.0.1::1223; select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
153 LRU list:
154 internal_search_find: file="NULL"
155   type=mysql key="servers=ip4.ip4.ip4.ip4::1223/test/root/:127.0.0.1::1223; select name from them where id='ph10';"
156 database lookup required for servers=ip4.ip4.ip4.ip4::1223/test/root/:127.0.0.1::1223; select name from them where id='ph10';
157 MySQL query: servers=ip4.ip4.ip4.ip4::1223/test/root/:127.0.0.1::1223; select name from them where id='ph10';
158 MYSQL new connection: host=ip4.ip4.ip4.ip4 port=1223 socket=NULL database=test user=root
159 lookup yielded: Philip Hazel
160 search_open: mysql "NULL"
161   cached open
162 search_find: file="NULL"
163   key="servers=localhost(TESTSUITE/mysql/sock)/test/root/; select name from them where id='ph10';" partial=-1 affix=NULL starflags=0
164 LRU list:
165 internal_search_find: file="NULL"
166   type=mysql key="servers=localhost(TESTSUITE/mysql/sock)/test/root/; select name from them where id='ph10';"
167 database lookup required for servers=localhost(TESTSUITE/mysql/sock)/test/root/; select name from them where id='ph10';
168 MySQL query: servers=localhost(TESTSUITE/mysql/sock)/test/root/; select name from them where id='ph10';
169 MYSQL new connection: host=localhost port=0 socket=TESTSUITE/mysql/sock database=test user=root
170 lookup yielded: Philip Hazel
171 search_open: mysql "NULL"
172   cached open
173 search_find: file="NULL"
174   key="SELECT name FROM them WHERE id IN ('ph10', 'aaaa');" partial=-1 affix=NULL starflags=0
175 LRU list:
176 internal_search_find: file="NULL"
177   type=mysql key="SELECT name FROM them WHERE id IN ('ph10', 'aaaa');"
178 database lookup required for SELECT name FROM them WHERE id IN ('ph10', 'aaaa');
179 MySQL query: SELECT name FROM them WHERE id IN ('ph10', 'aaaa');
180 MYSQL using cached connection for 127.0.0.1:1223/test/root
181 lookup yielded: Philip Hazel
182 Aristotle
183 search_open: mysql "NULL"
184   cached open
185 search_find: file="NULL"
186   key="SELECT *    FROM them WHERE id IN ('ph10', 'aaaa');" partial=-1 affix=NULL starflags=0
187 LRU list:
188 internal_search_find: file="NULL"
189   type=mysql key="SELECT *    FROM them WHERE id IN ('ph10', 'aaaa');"
190 database lookup required for SELECT *    FROM them WHERE id IN ('ph10', 'aaaa');
191 MySQL query: SELECT *    FROM them WHERE id IN ('ph10', 'aaaa');
192 MYSQL using cached connection for 127.0.0.1:1223/test/root
193 lookup yielded: name="Philip Hazel" id=ph10 
194 name=Aristotle id=aaaa 
195 search_open: mysql "NULL"
196   cached open
197 search_find: file="NULL"
198   key="delete from them where id='aaaa'" partial=-1 affix=NULL starflags=0
199 LRU list:
200 internal_search_find: file="NULL"
201   type=mysql key="delete from them where id='aaaa'"
202 database lookup required for delete from them where id='aaaa'
203 MySQL query: delete from them where id='aaaa'
204 MYSQL using cached connection for 127.0.0.1:1223/test/root
205 MYSQL: query was not one that returns data
206 lookup forced cache cleanup
207 lookup yielded: 1
208 search_tidyup called
209 close MYSQL connection: localhost(TESTSUITE/mysql/sock)/test/root
210 close MYSQL connection: ip4.ip4.ip4.ip4:1223/test/root
211 close MYSQL connection: 127.0.0.1:1223/test/root
212 >>>>>>>>>>>>>>>> Exim pid=pppp (main: expansion test) terminating with rc=0 >>>>>>>>>>>>>>>>
213 Exim version x.yz ....
214 changed uid/gid: forcing real = effective
215   uid=uuuu gid=CALLER_GID pid=pppp
216 configuration file is TESTSUITE/test-config
217 admin user
218 changed uid/gid: privilege not needed
219   uid=EXIM_UID gid=EXIM_GID pid=pppp
220 seeking password data for user "CALLER": cache not available
221 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
222 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
223 sender address = CALLER@myhost.test.ex
224 sender_fullhost = [10.0.0.0]
225 sender_rcvhost = [10.0.0.0]
226 host in hosts_connection_nolog? no (option unset)
227 LOG: smtp_connection MAIN
228   SMTP connection from [10.0.0.0]
229 host in host_lookup? no (option unset)
230 set_process_info: pppp handling incoming connection from [10.0.0.0]
231 host in host_reject_connection? no (option unset)
232 host in sender_unqualified_hosts? no (option unset)
233 host in recipient_unqualified_hosts? no (option unset)
234 host in helo_verify_hosts? no (option unset)
235 host in helo_try_verify_hosts? no (option unset)
236 host in helo_accept_junk_hosts? no (option unset)
237 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
238 smtp_setup_msg entered
239 SMTP<< mail from:<a@b>
240 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
241 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
242 SMTP>> 250 OK
243 SMTP<< rcpt to:<c@d>
244 using ACL "check_recipient"
245 processing "accept"
246 check domains = +local_domains
247 d in "@"? no (end of list)
248 d in "+local_domains"? no (end of list)
249 accept: condition test failed in ACL "check_recipient"
250 processing "accept"
251 check hosts = +relay_hosts
252 search_open: mysql "NULL"
253 search_find: file="NULL"
254   key="select * from them where id='10.0.0.0'" partial=-1 affix=NULL starflags=0
255 LRU list:
256 internal_search_find: file="NULL"
257   type=mysql key="select * from them where id='10.0.0.0'"
258 database lookup required for select * from them where id='10.0.0.0'
259 MySQL query: select * from them where id='10.0.0.0'
260 MYSQL new connection: host=127.0.0.1 port=1223 socket=NULL database=test user=root
261 MYSQL: no data found
262 lookup failed
263 host in "net-mysql;select * from them where id='10.0.0.0'"? no (end of list)
264 host in "+relay_hosts"? no (end of list)
265 accept: condition test failed in ACL "check_recipient"
266 processing "deny"
267   message: relay not permitted
268 deny: condition test succeeded in ACL "check_recipient"
269 end of ACL "check_recipient": DENY
270 SMTP>> 550 relay not permitted
271 LOG: MAIN REJECT
272   H=[10.0.0.0] F=<a@b> rejected RCPT <c@d>: relay not permitted
273 SMTP<< quit
274 SMTP>> 221 myhost.test.ex closing connection
275 LOG: smtp_connection MAIN
276   SMTP connection from [10.0.0.0] closed by QUIT
277 search_tidyup called
278 close MYSQL connection: 127.0.0.1:1223/test/root
279 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
280 Exim version x.yz ....
281 changed uid/gid: forcing real = effective
282   uid=uuuu gid=CALLER_GID pid=pppp
283 configuration file is TESTSUITE/test-config
284 admin user
285 changed uid/gid: privilege not needed
286   uid=EXIM_UID gid=EXIM_GID pid=pppp
287 seeking password data for user "CALLER": cache not available
288 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
289 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
290 sender address = CALLER@myhost.test.ex
291 set_process_info: pppp accepting a local non-SMTP message from <CALLER@myhost.test.ex>
292 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
293 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
294 Sender: CALLER@myhost.test.ex
295 Recipients:
296   ph10
297 search_tidyup called
298 >>Headers received:
299
300 rewrite_one_header: type=F:
301   From: CALLER_NAME <CALLER@myhost.test.ex>
302 search_tidyup called
303 >>Headers after rewriting and local additions:
304 I Message-Id: <E10HmaX-0005vi-00@myhost.test.ex>
305 F From: CALLER_NAME <CALLER@myhost.test.ex>
306   Date: Tue, 2 Mar 1999 09:44:33 +0000
307
308 Data file name: TESTSUITE/spool//input//10HmaX-0005vi-00-D
309 Data file written for message 10HmaX-0005vi-00
310 >>Generated Received: header line
311 P Received: from CALLER by myhost.test.ex with local (Exim x.yz)
312         (envelope-from <CALLER@myhost.test.ex>)
313         id 10HmaX-0005vi-00
314         for ph10@myhost.test.ex; Tue, 2 Mar 1999 09:44:33 +0000
315 Writing spool header file: TESTSUITE/spool//input//hdr.pppp
316 DSN: Write SPOOL :-dsn_envid NULL
317 DSN: Write SPOOL :-dsn_ret 0
318 DSN: Flags :0
319 DSN: **** SPOOL_OUT - address: |ph10@myhost.test.ex| errorsto: |NULL| orcpt: |NULL| dsn_flags: 0
320 Renaming spool header file: TESTSUITE/spool//input//10HmaX-0005vi-00-H
321 Size of headers = sss
322 LOG: MAIN
323   <= CALLER@myhost.test.ex U=CALLER P=local S=sss
324 created log directory TESTSUITE/spool/log
325 search_tidyup called
326 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xf7715cfd -odi -Mc 10HmaX-0005vi-00
327 Exim version x.yz ....
328 changed uid/gid: forcing real = effective
329   uid=uuuu gid=EXIM_GID pid=pppp
330 configuration file is TESTSUITE/test-config
331 trusted user
332 admin user
333 seeking password data for user "CALLER": cache not available
334 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
335 set_process_info: pppp delivering specified messages
336 set_process_info: pppp delivering 10HmaX-0005vi-00
337 Trying spool file TESTSUITE/spool//input//10HmaX-0005vi-00-D
338 reading spool file 10HmaX-0005vi-00-H
339 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=CALLER@myhost.test.ex
340 sender_local=1 ident=CALLER
341 Non-recipients:
342 Empty Tree
343 ---- End of tree ----
344 recipients_count=1
345 **** SPOOL_IN - No additional fields
346 body_linecount=1 message_linecount=7
347 DSN: set orcpt:   flags: 0
348 Delivery address list:
349   ph10@myhost.test.ex 
350  locking TESTSUITE/spool/db/retry.lockfile
351  locked  TESTSUITE/spool/db/retry.lockfile
352  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
353  returned from EXIM_DBOPEN: (nil)
354  ensuring TESTSUITE/spool/db/retry.lockfile is owned by exim
355  failed to open DB file TESTSUITE/spool/db/retry.lockfile: No such file or directory
356 no retry data available
357 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
358 Considering: ph10@myhost.test.ex
359 unique = ph10@myhost.test.ex
360 no   domain  retry record
361 no   address retry record
362 ph10@myhost.test.ex: queued for routing
363 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
364 routing ph10@myhost.test.ex
365 --------> r1 router <--------
366 local_part=ph10 domain=myhost.test.ex
367 processing address_data
368 search_open: mysql "NULL"
369 search_find: file="NULL"
370   key="select name from them where id='ph10'" partial=-1 affix=NULL starflags=0
371 LRU list:
372 internal_search_find: file="NULL"
373   type=mysql key="select name from them where id='ph10'"
374 database lookup required for select name from them where id='ph10'
375 MySQL query: select name from them where id='ph10'
376 MYSQL new connection: host=127.0.0.1 port=1223 socket=NULL database=test user=root
377 lookup yielded: Philip Hazel
378 calling r1 router
379 r1 router called for ph10@myhost.test.ex
380   domain = myhost.test.ex
381 set transport t1
382 queued for t1 transport: local_part = ph10
383 domain = myhost.test.ex
384   errors_to=NULL
385   domain_data=NULL localpart_data=NULL
386 routed by r1 router
387   envelope to: ph10@myhost.test.ex
388   transport: t1
389 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
390 After routing:
391   Local deliveries:
392     ph10@myhost.test.ex
393   Remote deliveries:
394   Failed addresses:
395   Deferred addresses:
396 search_tidyup called
397 close MYSQL connection: 127.0.0.1:1223/test/root
398 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
399 --------> ph10@myhost.test.ex <--------
400  locking TESTSUITE/spool/db/retry.lockfile
401  locked  TESTSUITE/spool/db/retry.lockfile
402  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
403  returned from EXIM_DBOPEN: (nil)
404  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
405 no retry data available
406 search_tidyup called
407 changed uid/gid: local delivery to ph10 <ph10@myhost.test.ex> transport=t1
408   uid=CALLER_UID gid=CALLER_GID pid=pppp
409   home=NULL current=/
410 set_process_info: pppp delivering 10HmaX-0005vi-00 to ph10 using t1
411 appendfile transport entered
412 search_open: mysql "NULL"
413 search_find: file="NULL"
414   key="select id from them where id='ph10'" partial=-1 affix=NULL starflags=0
415 LRU list:
416 internal_search_find: file="NULL"
417   type=mysql key="select id from them where id='ph10'"
418 database lookup required for select id from them where id='ph10'
419 MySQL query: select id from them where id='ph10'
420 MYSQL new connection: host=127.0.0.1 port=1223 socket=NULL database=test user=root
421 lookup yielded: ph10
422 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
423   file=TESTSUITE/test-mail/ph10 format=unix
424   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
425   message_suffix=\n
426   maildir_use_size_file=no
427   locking by lockfile fcntl 
428 lock name: TESTSUITE/test-mail/ph10.lock
429 hitch name: TESTSUITE/test-mail/ph10.lock.test.ex.dddddddd.pppppppp
430 lock file created
431 mailbox TESTSUITE/test-mail/ph10 is locked
432 writing to file TESTSUITE/test-mail/ph10
433 writing data block fd=dddd size=sss timeout=0
434 cannot use sendfile for body: spoolfile not wireformat
435 writing data block fd=dddd size=sss timeout=0
436 writing data block fd=dddd size=sss timeout=0
437 appendfile yields 0 with errno=dd more_errno=dd
438 search_tidyup called
439 close MYSQL connection: 127.0.0.1:1223/test/root
440 journalling ph10@myhost.test.ex
441 t1 transport returned OK for ph10@myhost.test.ex
442 post-process ph10@myhost.test.ex (0)
443 ph10@myhost.test.ex delivered
444 LOG: MAIN
445   => ph10 <ph10@myhost.test.ex> R=r1 T=t1
446 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
447 changed uid/gid: post-delivery tidying
448   uid=EXIM_UID gid=EXIM_GID pid=pppp
449 set_process_info: pppp tidying up after delivering 10HmaX-0005vi-00
450 Processing retry items
451 Succeeded addresses:
452  ph10@myhost.test.ex: no retry items
453 Failed addresses:
454 Deferred addresses:
455 end of retry processing
456 DSN: processing router : r1
457 DSN: processing successful delivery address: ph10@myhost.test.ex
458 DSN: Sender_address: CALLER@myhost.test.ex
459 DSN: orcpt: NULL  flags: 0
460 DSN: envid: NULL  ret: 0
461 DSN: Final recipient: ph10@myhost.test.ex
462 DSN: Remote SMTP server supports DSN: 0
463 DSN: not sending DSN success message
464 LOG: MAIN
465   Completed
466 end delivery of 10HmaX-0005vi-00
467 search_tidyup called
468 search_tidyup called
469 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
470 search_tidyup called
471 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>