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