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