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