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