Tweak debug output
[exim.git] / test / stderr / 0386
1 Exim version x.yz ....
2 changed uid/gid: forcing real = effective
3   uid=uuuu gid=CALLER_GID pid=p1234
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=p1234
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<< helo test
31 test in helo_lookup_domains? no (end of list)
32 sender_fullhost = (test) [V4NET.9.8.7]
33 sender_rcvhost = [V4NET.9.8.7] (helo=test)
34 set_process_info: pppp handling incoming connection from (test) [V4NET.9.8.7]
35 SMTP>> 250 myhost.test.ex Hello test [V4NET.9.8.7]
36 SMTP<< mail from:<x@y>
37 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
38 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
39 SMTP>> 250 OK
40 SMTP<< rcpt to:<1@b>
41 using ACL "chk_rcpt"
42 processing "accept" (TESTSUITE/test-config 18)
43 check local_parts = 1
44 1 in "1"? yes (matched "1")
45 check acl = TESTSUITE/aux-fixed/0386.acl1
46  read ACL from file TESTSUITE/aux-fixed/0386.acl1
47  processing "accept" (TESTSUITE/test-config 44)
48  check hosts = :
49   host in ":"? no (end of list)
50  accept: condition test failed in ACL "TESTSUITE/aux-fixed/0386.acl1"
51  processing "deny" (TESTSUITE/test-config 44)
52  check local_parts = ^.*[@%!/|]
53  compiled caseless RE '^.*[@%!/|]' not found in local cache
54  compiled RE '^.*[@%!/|]' saved in local cache
55  1 in "^.*[@%!/|]"? no (end of list)
56  deny: condition test failed in ACL "TESTSUITE/aux-fixed/0386.acl1"
57  processing "require" (TESTSUITE/test-config 44)
58  l_message: Invalid sender
59    message: Couldn't verify the sender
60  check verify = sender/defer_ok
61 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
62 Verifying x@y
63 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
64 Considering x@y
65 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
66 routing x@y
67 --------> r1 router <--------
68 local_part=x domain=y
69 calling r1 router
70 r1 router called for x@y
71   domain = y
72 set transport t1
73 queued for t1 transport: local_part = x
74 domain = y
75   errors_to=NULL
76   domain_data=NULL local_part_data=NULL
77 routed by r1 router
78   envelope to: x@y
79   transport: t1
80  ----------- end verify ------------
81  sender x@y verified ok
82  require: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl1"
83  processing "deny" (TESTSUITE/test-config 44)
84    message: No such user here
85  deny: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl1"
86  end of ACL "TESTSUITE/aux-fixed/0386.acl1": DENY
87 accept: condition test failed in ACL "chk_rcpt"
88 accept: endpass encountered - denying access
89 SMTP>> 550 No such user here
90 LOG: MAIN REJECT
91   H=(test) [V4NET.9.8.7] F=<x@y> rejected RCPT <1@b>: No such user here
92 SMTP<< rset
93 SMTP>> 250 Reset OK
94 SMTP<< mail from:<x@y>
95 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
96 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
97 SMTP>> 250 OK
98 SMTP<< rcpt to:<1@b>
99 using ACL "chk_rcpt"
100 processing "accept" (TESTSUITE/test-config 18)
101 check local_parts = 1
102 1 in "1"? yes (matched "1")
103 check acl = TESTSUITE/aux-fixed/0386.acl1
104  using ACL "TESTSUITE/aux-fixed/0386.acl1"
105  processing "accept" (TESTSUITE/test-config 44)
106  check hosts = :
107   host in ":"? no (end of list)
108  accept: condition test failed in ACL "TESTSUITE/aux-fixed/0386.acl1"
109  processing "deny" (TESTSUITE/test-config 44)
110  check local_parts = ^.*[@%!/|]
111  compiled caseless RE '^.*[@%!/|]' found in local cache
112  1 in "^.*[@%!/|]"? no (end of list)
113  deny: condition test failed in ACL "TESTSUITE/aux-fixed/0386.acl1"
114  processing "require" (TESTSUITE/test-config 44)
115  l_message: Invalid sender
116    message: Couldn't verify the sender
117  check verify = sender/defer_ok
118 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
119 Verifying x@y
120 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
121 Considering x@y
122 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
123 routing x@y
124 --------> r1 router <--------
125 local_part=x domain=y
126 calling r1 router
127 r1 router called for x@y
128   domain = y
129 queued for t1 transport: local_part = x
130 domain = y
131   errors_to=NULL
132   domain_data=NULL local_part_data=NULL
133 routed by r1 router
134   envelope to: x@y
135   transport: t1
136  ----------- end verify ------------
137  sender x@y verified ok
138  require: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl1"
139  processing "deny" (TESTSUITE/test-config 44)
140    message: No such user here
141  deny: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl1"
142  end of ACL "TESTSUITE/aux-fixed/0386.acl1": DENY
143 accept: condition test failed in ACL "chk_rcpt"
144 accept: endpass encountered - denying access
145 SMTP>> 550 No such user here
146 LOG: MAIN REJECT
147   H=(test) [V4NET.9.8.7] F=<x@y> rejected RCPT <1@b>: No such user here
148 SMTP<< quit
149 SMTP>> 221 myhost.test.ex closing connection
150 LOG: smtp_connection MAIN
151   SMTP connection from (test) [V4NET.9.8.7] closed by QUIT
152 search_tidyup called
153 >>>>>>>>>>>>>>>> Exim pid=p1234 (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
154 Exim version x.yz ....
155 changed uid/gid: forcing real = effective
156   uid=uuuu gid=CALLER_GID pid=p1235
157 seeking password data for user "CALLER": cache not available
158 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
159 configuration file is TESTSUITE/test-config
160 trusted user
161 admin user
162 changed uid/gid: privilege not needed
163   uid=EXIM_UID gid=EXIM_GID pid=p1235
164 seeking password data for user "CALLER": using cached result
165 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
166 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
167 sender address = NULL
168 sender_fullhost = [V4NET.11.12.13]
169 sender_rcvhost = [V4NET.11.12.13] (ident=CALLER)
170 set_process_info: pppp handling incoming connection from [V4NET.11.12.13] via -oMa
171 set_process_info: pppp accepting a local SMTP message from <CALLER>
172 host in hosts_connection_nolog? no (option unset)
173 LOG: smtp_connection MAIN
174   SMTP connection from CALLER
175 host in host_lookup? no (option unset)
176 set_process_info: pppp handling incoming connection from [V4NET.11.12.13] U=CALLER
177 host in host_reject_connection? no (option unset)
178 host in sender_unqualified_hosts? no (option unset)
179 host in recipient_unqualified_hosts? no (option unset)
180 host in helo_verify_hosts? no (option unset)
181 host in helo_try_verify_hosts? no (option unset)
182 host in helo_accept_junk_hosts? no (option unset)
183 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
184 smtp_setup_msg entered
185 SMTP<< helo test
186 test in helo_lookup_domains? no (end of list)
187 sender_fullhost = (test) [V4NET.11.12.13]
188 sender_rcvhost = [V4NET.11.12.13] (helo=test ident=CALLER)
189 set_process_info: pppp handling incoming connection from (test) [V4NET.11.12.13] U=CALLER
190 SMTP>> 250 myhost.test.ex Hello CALLER at test [V4NET.11.12.13]
191 SMTP<< mail from:<x@y>
192 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
193 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
194 SMTP>> 250 OK
195 SMTP<< rcpt to:<2@b>
196 using ACL "chk_rcpt"
197 processing "accept" (TESTSUITE/test-config 18)
198 check local_parts = 1
199 2 in "1"? no (end of list)
200 accept: condition test failed in ACL "chk_rcpt"
201 processing "accept" (TESTSUITE/test-config 21)
202 check local_parts = 2
203 2 in "2"? yes (matched "2")
204 check acl = TESTSUITE/aux-fixed/0386.acl2
205  read ACL from file TESTSUITE/aux-fixed/0386.acl2
206  processing "warn" (TESTSUITE/test-config 44)
207    message: X-Warning: $sender_host_address is listed at $dnslist_domain\nX-Warning: $dnslist_text
208  l_message: found in $dnslist_domain: $dnslist_text
209  check dnslists = rbl.test.ex 
210 dnslists check: rbl.test.ex
211 new DNS lookup for 13.12.11.V4NET.rbl.test.ex
212 DNS lookup of 13.12.11.V4NET.rbl.test.ex (A) using fakens
213 DNS lookup of 13.12.11.V4NET.rbl.test.ex (A) succeeded
214 dnslists: wrote cache entry, ttl=3
215 DNS lookup for 13.12.11.V4NET.rbl.test.ex succeeded (yielding 127.0.0.2)
216 DNS lookup of 13.12.11.V4NET.rbl.test.ex (TXT) using fakens
217 DNS lookup of 13.12.11.V4NET.rbl.test.ex (TXT) succeeded
218 => that means V4NET.11.12.13 is listed at rbl.test.ex
219  warn: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl2"
220 LOG: MAIN
221   H=(test) [V4NET.11.12.13] U=CALLER Warning: found in rbl.test.ex: This is a test blacklisting message
222 created log directory TESTSUITE/spool/log
223  processing "accept" (TESTSUITE/test-config 44)
224  accept: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl2"
225  end of ACL "TESTSUITE/aux-fixed/0386.acl2": ACCEPT
226 accept: condition test succeeded in ACL "chk_rcpt"
227 end of ACL "chk_rcpt": ACCEPT
228 SMTP>> 250 Accepted
229 SMTP<< data
230 SMTP>> 354 Enter message, ending with "." on a line by itself
231 search_tidyup called
232 >>Headers received:
233
234 qualify & rewrite recipients list
235 global rewrite rules
236 rewrite headers
237 search_tidyup called
238 >>Headers after rewriting and local additions:
239
240 Data file name: TESTSUITE/spool//input//10HmaX-0005vi-00-D
241 Data file written for message 10HmaX-0005vi-00
242 >>Generated Received: header line
243 P Received: from [V4NET.11.12.13] (helo=test ident=CALLER)
244         by myhost.test.ex with smtp (Exim x.yz)
245         (envelope-from <x@y>)
246         id 10HmaX-0005vi-00
247         for 2@b;
248         Tue, 2 Mar 1999 09:44:33 +0000
249 >>Headers added by MAIL or RCPT ACL:
250   X-Warning: V4NET.11.12.13 is listed at rbl.test.ex
251   X-Warning: This is a test blacklisting message
252 >>
253 Writing spool header file: TESTSUITE/spool//input//hdr.10HmaX-0005vi-00
254 DSN: **** SPOOL_OUT - address: <2@b> errorsto: <NULL> orcpt: <NULL> dsn_flags: 0x0
255 Renaming spool header file: TESTSUITE/spool//input//10HmaX-0005vi-00-H
256 Size of headers = sss
257 LOG: MAIN
258   <= x@y H=(test) [V4NET.11.12.13] U=CALLER P=smtp S=sss
259 SMTP>> 250 OK id=10HmaX-0005vi-00
260 search_tidyup called
261 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xf7715cfd -MCd local-accept-delivery -odi -Mc 10HmaX-0005vi-00
262 Exim version x.yz ....
263 changed uid/gid: forcing real = effective
264   uid=uuuu gid=EXIM_GID pid=p1236
265 seeking password data for user "CALLER": cache not available
266 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
267 configuration file is TESTSUITE/test-config
268 trusted user
269 admin user
270 dropping to exim gid; retaining priv uid
271 seeking password data for user "CALLER": using cached result
272 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
273 set_process_info: pppp delivering specified messages
274 set_process_info: pppp delivering 10HmaX-0005vi-00
275 Trying spool file TESTSUITE/spool//input//10HmaX-0005vi-00-D
276 reading spool file 10HmaX-0005vi-00-H
277 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=x@y
278 sender_fullhost = (test) [V4NET.11.12.13]
279 sender_rcvhost = [V4NET.11.12.13] (helo=test ident=CALLER)
280 sender_local=0 ident=CALLER
281 Non-recipients:
282  Empty Tree
283 ---- End of tree ----
284 recipients_count=1
285 **** SPOOL_IN - No additional fields
286 body_linecount=1 message_linecount=8
287 DSN: set orcpt:   flags: 0x0
288 Delivery address list:
289   2@b 
290  locking TESTSUITE/spool/db/retry.lockfile
291  locked  TESTSUITE/spool/db/retry.lockfile
292  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
293  returned from EXIM_DBOPEN: (nil)
294  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
295 no retry data available
296 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
297 Considering: 2@b
298 unique = 2@b
299 no   domain  retry record
300 no   address retry record
301 2@b: queued for routing
302 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
303 routing 2@b
304 --------> r1 router <--------
305 local_part=2 domain=b
306 calling r1 router
307 r1 router called for 2@b
308   domain = b
309 set transport t1
310 queued for t1 transport: local_part = 2
311 domain = b
312   errors_to=NULL
313   domain_data=NULL local_part_data=NULL
314 routed by r1 router
315   envelope to: 2@b
316   transport: t1
317 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
318 After routing:
319   Local deliveries:
320     2@b
321   Remote deliveries:
322   Failed addresses:
323   Deferred addresses:
324 search_tidyup called
325 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
326 --------> 2@b <--------
327  locking TESTSUITE/spool/db/retry.lockfile
328  locked  TESTSUITE/spool/db/retry.lockfile
329  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
330  returned from EXIM_DBOPEN: (nil)
331  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
332 no retry data available
333 search_tidyup called
334 changed uid/gid: local delivery to 2 <2@b> transport=t1
335   uid=CALLER_UID gid=CALLER_GID pid=p1237
336   home=NULL current=/
337 set_process_info: pppp delivering 10HmaX-0005vi-00 to 2 using t1
338 appendfile transport entered
339 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
340   file=TESTSUITE/test-mail/2 format=unix
341   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
342   message_suffix=\n
343   maildir_use_size_file=no
344   locking by lockfile fcntl 
345 de-tainting path 'TESTSUITE/test-mail/2'
346 lock name: TESTSUITE/test-mail/2.lock
347 hitch name: TESTSUITE/test-mail/2.lock.test.ex.dddddddd.pppppppp
348 lock file created
349 mailbox TESTSUITE/test-mail/2 is locked
350 writing to file TESTSUITE/test-mail/2
351 writing data block fd=dddd size=sss timeout=0
352 cannot use sendfile for body: spoolfile not wireformat
353 writing data block fd=dddd size=sss timeout=0
354 writing data block fd=dddd size=sss timeout=0
355 appendfile yields 0 with errno=dd more_errno=dd
356 search_tidyup called
357 journalling 2@b
358 t1 transport returned OK for 2@b
359 post-process 2@b (0)
360 2@b delivered
361 LOG: MAIN
362   => 2 <2@b> R=r1 T=t1
363 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
364 changed uid/gid: post-delivery tidying
365   uid=EXIM_UID gid=EXIM_GID pid=p1236
366 set_process_info: pppp tidying up after delivering 10HmaX-0005vi-00
367 Processing retry items
368 Succeeded addresses:
369  2@b: no retry items
370 Failed addresses:
371 Deferred addresses:
372 end of retry processing
373 DSN: processing router : r1
374 DSN: processing successful delivery address: 2@b
375 DSN: Sender_address: x@y
376 DSN: orcpt: NULL  flags: 0x0
377 DSN: envid: NULL  ret: 0
378 DSN: Final recipient: 2@b
379 DSN: Remote SMTP server supports DSN: 0
380 DSN: not sending DSN success message
381 LOG: MAIN
382   Completed
383 end delivery of 10HmaX-0005vi-00
384 search_tidyup called
385 search_tidyup called
386 >>>>>>>>>>>>>>>> Exim pid=p1236 (local-accept-delivery) terminating with rc=0 >>>>>>>>>>>>>>>>
387 smtp_setup_msg entered
388 SMTP<< rset
389 SMTP>> 250 Reset OK
390 SMTP<< mail from:<x@y>
391 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
392 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
393 SMTP>> 250 OK
394 SMTP<< rcpt to:<2@b>
395 using ACL "chk_rcpt"
396 processing "accept" (TESTSUITE/test-config 18)
397 check local_parts = 1
398 2 in "1"? no (end of list)
399 accept: condition test failed in ACL "chk_rcpt"
400 processing "accept" (TESTSUITE/test-config 21)
401 check local_parts = 2
402 2 in "2"? yes (matched "2")
403 check acl = TESTSUITE/aux-fixed/0386.acl2
404  using ACL "TESTSUITE/aux-fixed/0386.acl2"
405  processing "warn" (TESTSUITE/test-config 44)
406    message: X-Warning: $sender_host_address is listed at $dnslist_domain\nX-Warning: $dnslist_text
407  l_message: found in $dnslist_domain: $dnslist_text
408  check dnslists = rbl.test.ex 
409 dnslists check: rbl.test.ex
410 dnslists: using result of previous lookup
411 DNS lookup for 13.12.11.V4NET.rbl.test.ex succeeded (yielding 127.0.0.2)
412 => that means V4NET.11.12.13 is listed at rbl.test.ex
413  warn: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl2"
414 LOG: MAIN
415   H=(test) [V4NET.11.12.13] U=CALLER Warning: found in rbl.test.ex: This is a test blacklisting message
416  processing "accept" (TESTSUITE/test-config 44)
417  accept: condition test succeeded in ACL "TESTSUITE/aux-fixed/0386.acl2"
418  end of ACL "TESTSUITE/aux-fixed/0386.acl2": ACCEPT
419 accept: condition test succeeded in ACL "chk_rcpt"
420 end of ACL "chk_rcpt": ACCEPT
421 SMTP>> 250 Accepted
422 SMTP<< data
423 SMTP>> 354 Enter message, ending with "." on a line by itself
424 search_tidyup called
425 >>Headers received:
426
427 qualify & rewrite recipients list
428 global rewrite rules
429 rewrite headers
430 search_tidyup called
431 >>Headers after rewriting and local additions:
432
433 Data file name: TESTSUITE/spool//input//10HmaY-0005vi-00-D
434 Data file written for message 10HmaY-0005vi-00
435 >>Generated Received: header line
436 P Received: from [V4NET.11.12.13] (helo=test ident=CALLER)
437         by myhost.test.ex with smtp (Exim x.yz)
438         (envelope-from <x@y>)
439         id 10HmaY-0005vi-00
440         for 2@b;
441         Tue, 2 Mar 1999 09:44:33 +0000
442 >>Headers added by MAIL or RCPT ACL:
443   X-Warning: V4NET.11.12.13 is listed at rbl.test.ex
444   X-Warning: This is a test blacklisting message
445 >>
446 Writing spool header file: TESTSUITE/spool//input//hdr.10HmaY-0005vi-00
447 DSN: **** SPOOL_OUT - address: <2@b> errorsto: <NULL> orcpt: <NULL> dsn_flags: 0x0
448 Renaming spool header file: TESTSUITE/spool//input//10HmaY-0005vi-00-H
449 Size of headers = sss
450 LOG: MAIN
451   <= x@y H=(test) [V4NET.11.12.13] U=CALLER P=smtp S=sss
452 SMTP>> 250 OK id=10HmaY-0005vi-00
453 search_tidyup called
454 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xf7715cfd -MCd local-accept-delivery -odi -Mc 10HmaY-0005vi-00
455 Exim version x.yz ....
456 changed uid/gid: forcing real = effective
457   uid=uuuu gid=EXIM_GID pid=p1238
458 seeking password data for user "CALLER": cache not available
459 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
460 configuration file is TESTSUITE/test-config
461 trusted user
462 admin user
463 dropping to exim gid; retaining priv uid
464 seeking password data for user "CALLER": using cached result
465 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
466 set_process_info: pppp delivering specified messages
467 set_process_info: pppp delivering 10HmaY-0005vi-00
468 Trying spool file TESTSUITE/spool//input//10HmaY-0005vi-00-D
469 reading spool file 10HmaY-0005vi-00-H
470 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=x@y
471 sender_fullhost = (test) [V4NET.11.12.13]
472 sender_rcvhost = [V4NET.11.12.13] (helo=test ident=CALLER)
473 sender_local=0 ident=CALLER
474 Non-recipients:
475  Empty Tree
476 ---- End of tree ----
477 recipients_count=1
478 **** SPOOL_IN - No additional fields
479 body_linecount=1 message_linecount=8
480 DSN: set orcpt:   flags: 0x0
481 Delivery address list:
482   2@b 
483  locking TESTSUITE/spool/db/retry.lockfile
484  locked  TESTSUITE/spool/db/retry.lockfile
485  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
486  returned from EXIM_DBOPEN: (nil)
487  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
488 no retry data available
489 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
490 Considering: 2@b
491 unique = 2@b
492 no   domain  retry record
493 no   address retry record
494 2@b: queued for routing
495 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
496 routing 2@b
497 --------> r1 router <--------
498 local_part=2 domain=b
499 calling r1 router
500 r1 router called for 2@b
501   domain = b
502 set transport t1
503 queued for t1 transport: local_part = 2
504 domain = b
505   errors_to=NULL
506   domain_data=NULL local_part_data=NULL
507 routed by r1 router
508   envelope to: 2@b
509   transport: t1
510 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
511 After routing:
512   Local deliveries:
513     2@b
514   Remote deliveries:
515   Failed addresses:
516   Deferred addresses:
517 search_tidyup called
518 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
519 --------> 2@b <--------
520  locking TESTSUITE/spool/db/retry.lockfile
521  locked  TESTSUITE/spool/db/retry.lockfile
522  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
523  returned from EXIM_DBOPEN: (nil)
524  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
525 no retry data available
526 search_tidyup called
527 changed uid/gid: local delivery to 2 <2@b> transport=t1
528   uid=CALLER_UID gid=CALLER_GID pid=p1239
529   home=NULL current=/
530 set_process_info: pppp delivering 10HmaY-0005vi-00 to 2 using t1
531 appendfile transport entered
532 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
533   file=TESTSUITE/test-mail/2 format=unix
534   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
535   message_suffix=\n
536   maildir_use_size_file=no
537   locking by lockfile fcntl 
538 de-tainting path 'TESTSUITE/test-mail/2'
539 lock name: TESTSUITE/test-mail/2.lock
540 hitch name: TESTSUITE/test-mail/2.lock.test.ex.dddddddd.pppppppp
541 lock file created
542 mailbox TESTSUITE/test-mail/2 is locked
543 writing to file TESTSUITE/test-mail/2
544 writing data block fd=dddd size=sss timeout=0
545 cannot use sendfile for body: spoolfile not wireformat
546 writing data block fd=dddd size=sss timeout=0
547 writing data block fd=dddd size=sss timeout=0
548 appendfile yields 0 with errno=dd more_errno=dd
549 search_tidyup called
550 journalling 2@b
551 t1 transport returned OK for 2@b
552 post-process 2@b (0)
553 2@b delivered
554 LOG: MAIN
555   => 2 <2@b> R=r1 T=t1
556 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
557 changed uid/gid: post-delivery tidying
558   uid=EXIM_UID gid=EXIM_GID pid=p1238
559 set_process_info: pppp tidying up after delivering 10HmaY-0005vi-00
560 Processing retry items
561 Succeeded addresses:
562  2@b: no retry items
563 Failed addresses:
564 Deferred addresses:
565 end of retry processing
566 DSN: processing router : r1
567 DSN: processing successful delivery address: 2@b
568 DSN: Sender_address: x@y
569 DSN: orcpt: NULL  flags: 0x0
570 DSN: envid: NULL  ret: 0
571 DSN: Final recipient: 2@b
572 DSN: Remote SMTP server supports DSN: 0
573 DSN: not sending DSN success message
574 LOG: MAIN
575   Completed
576 end delivery of 10HmaY-0005vi-00
577 search_tidyup called
578 search_tidyup called
579 >>>>>>>>>>>>>>>> Exim pid=p1238 (local-accept-delivery) terminating with rc=0 >>>>>>>>>>>>>>>>
580 smtp_setup_msg entered
581 SMTP<< quit
582 SMTP>> 221 myhost.test.ex closing connection
583 LOG: smtp_connection MAIN
584   SMTP connection from CALLER closed by QUIT
585 search_tidyup called
586 >>>>>>>>>>>>>>>> Exim pid=p1235 (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>