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