Add `receive_time` to list of log_selector values
[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 calling local_scan(); timeout=300
316 local_scan() returned 0 NULL
317 Writing spool header file: TESTSUITE/spool//input//hdr.pppp
318 DSN: Write SPOOL :-dsn_envid NULL
319 DSN: Write SPOOL :-dsn_ret 0
320 DSN: Flags :0
321 DSN: **** SPOOL_OUT - address: |ph10@myhost.test.ex| errorsto: |NULL| orcpt: |NULL| dsn_flags: 0
322 Renaming spool header file: TESTSUITE/spool//input//10HmaX-0005vi-00-H
323 Size of headers = sss
324 LOG: MAIN
325   <= CALLER@myhost.test.ex U=CALLER P=local S=sss
326 created log directory TESTSUITE/spool/log
327 search_tidyup called
328 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xfbb95cfd -odi -Mc 10HmaX-0005vi-00
329 Exim version x.yz ....
330 changed uid/gid: forcing real = effective
331   uid=uuuu gid=EXIM_GID pid=pppp
332 configuration file is TESTSUITE/test-config
333 trusted user
334 admin user
335 seeking password data for user "CALLER": cache not available
336 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
337 set_process_info: pppp delivering specified messages
338 set_process_info: pppp delivering 10HmaX-0005vi-00
339 Trying spool file TESTSUITE/spool//input//10HmaX-0005vi-00-D
340 reading spool file 10HmaX-0005vi-00-H
341 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=CALLER@myhost.test.ex
342 sender_local=1 ident=CALLER
343 Non-recipients:
344 Empty Tree
345 ---- End of tree ----
346 recipients_count=1
347 **** SPOOL_IN - No additional fields
348 body_linecount=1 message_linecount=7
349 DSN: set orcpt:   flags: 0
350 Delivery address list:
351   ph10@myhost.test.ex 
352 locking TESTSUITE/spool/db/retry.lockfile
353 locked  TESTSUITE/spool/db/retry.lockfile
354 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
355 returned from EXIM_DBOPEN: (nil)
356 ensuring TESTSUITE/spool/db/retry.lockfile is owned by exim
357 failed to open DB file TESTSUITE/spool/db/retry.lockfile: No such file or directory
358 no retry data available
359 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
360 Considering: ph10@myhost.test.ex
361 unique = ph10@myhost.test.ex
362 no domain retry record
363 no address retry record
364 ph10@myhost.test.ex: queued for routing
365 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
366 routing ph10@myhost.test.ex
367 --------> r1 router <--------
368 local_part=ph10 domain=myhost.test.ex
369 processing address_data
370 search_open: mysql "NULL"
371 search_find: file="NULL"
372   key="select name from them where id='ph10'" partial=-1 affix=NULL starflags=0
373 LRU list:
374 internal_search_find: file="NULL"
375   type=mysql key="select name from them where id='ph10'"
376 database lookup required for select name from them where id='ph10'
377 MySQL query: select name from them where id='ph10'
378 MYSQL new connection: host=127.0.0.1 port=1223 socket=NULL database=test user=root
379 lookup yielded: Philip Hazel
380 calling r1 router
381 r1 router called for ph10@myhost.test.ex
382   domain = myhost.test.ex
383 set transport t1
384 queued for t1 transport: local_part = ph10
385 domain = myhost.test.ex
386   errors_to=NULL
387   domain_data=NULL localpart_data=NULL
388 routed by r1 router
389   envelope to: ph10@myhost.test.ex
390   transport: t1
391 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
392 After routing:
393   Local deliveries:
394     ph10@myhost.test.ex
395   Remote deliveries:
396   Failed addresses:
397   Deferred addresses:
398 search_tidyup called
399 close MYSQL connection: 127.0.0.1:1223/test/root
400 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
401 --------> ph10@myhost.test.ex <--------
402 locking TESTSUITE/spool/db/retry.lockfile
403 locked  TESTSUITE/spool/db/retry.lockfile
404 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
405 returned from EXIM_DBOPEN: (nil)
406 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
407 no retry data available
408 search_tidyup called
409 changed uid/gid: local delivery to ph10 <ph10@myhost.test.ex> transport=t1
410   uid=CALLER_UID gid=CALLER_GID pid=pppp
411   home=NULL current=/
412 set_process_info: pppp delivering 10HmaX-0005vi-00 to ph10 using t1
413 appendfile transport entered
414 search_open: mysql "NULL"
415 search_find: file="NULL"
416   key="select id from them where id='ph10'" partial=-1 affix=NULL starflags=0
417 LRU list:
418 internal_search_find: file="NULL"
419   type=mysql key="select id from them where id='ph10'"
420 database lookup required for select id from them where id='ph10'
421 MySQL query: select id from them where id='ph10'
422 MYSQL new connection: host=127.0.0.1 port=1223 socket=NULL database=test user=root
423 lookup yielded: ph10
424 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
425   file=TESTSUITE/test-mail/ph10 format=unix
426   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
427   message_suffix=\n
428   maildir_use_size_file=no
429   locking by lockfile fcntl 
430 lock name: TESTSUITE/test-mail/ph10.lock
431 hitch name: TESTSUITE/test-mail/ph10.lock.test.ex.dddddddd.pppppppp
432 lock file created
433 mailbox TESTSUITE/test-mail/ph10 is locked
434 writing to file TESTSUITE/test-mail/ph10
435 writing data block fd=dddd size=sss timeout=0
436 cannot use sendfile for body: spoolfile not wireformat
437 writing data block fd=dddd size=sss timeout=0
438 writing data block fd=dddd size=sss timeout=0
439 appendfile yields 0 with errno=dd more_errno=dd
440 search_tidyup called
441 close MYSQL connection: 127.0.0.1:1223/test/root
442 journalling ph10@myhost.test.ex
443 t1 transport returned OK for ph10@myhost.test.ex
444 post-process ph10@myhost.test.ex (0)
445 ph10@myhost.test.ex delivered
446 LOG: MAIN
447   => ph10 <ph10@myhost.test.ex> R=r1 T=t1
448 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
449 changed uid/gid: post-delivery tidying
450   uid=EXIM_UID gid=EXIM_GID pid=pppp
451 set_process_info: pppp tidying up after delivering 10HmaX-0005vi-00
452 Processing retry items
453 Succeeded addresses:
454  ph10@myhost.test.ex: no retry items
455 Failed addresses:
456 Deferred addresses:
457 end of retry processing
458 DSN: processing router : r1
459 DSN: processing successful delivery address: ph10@myhost.test.ex
460 DSN: Sender_address: CALLER@myhost.test.ex
461 DSN: orcpt: NULL  flags: 0
462 DSN: envid: NULL  ret: 0
463 DSN: Final recipient: ph10@myhost.test.ex
464 DSN: Remote SMTP server supports DSN: 0
465 DSN: not sending DSN success message
466 LOG: MAIN
467   Completed
468 end delivery of 10HmaX-0005vi-00
469 search_tidyup called
470 search_tidyup called
471 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
472 search_tidyup called
473 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>