Testsuite: delays for debug output ordering (again)
[users/jgh/exim.git] / test / stderr / 0361
1 LOG: MAIN
2   <= CALLER@test.ex U=CALLER P=local S=sss
3 delivering 10HmaX-0005vi-00
4 LOG: MAIN
5   *> miles <miles@thishost.test.ex> R=r4 T=t2
6 LOG: MAIN
7   Completed
8 Exim version x.yz ....
9 changed uid/gid: forcing real = effective
10   uid=uuuu gid=CALLER_GID pid=pppp
11 configuration file is TESTSUITE/test-config
12 admin user
13 changed uid/gid: privilege not needed
14   uid=EXIM_UID gid=EXIM_GID pid=pppp
15 seeking password data for user "CALLER": cache not available
16 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
17 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
18 sender address = CALLER@test.ex
19 set_process_info: pppp accepting a local non-SMTP message from <CALLER@test.ex>
20 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
21 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
22 Sender: CALLER@test.ex
23 Recipients:
24   kilos@recurse.test.ex
25 search_tidyup called
26 >>Headers received:
27
28 rewrite_one_header: type=F:
29   From: CALLER_NAME <CALLER@test.ex>
30 search_tidyup called
31 >>Headers after rewriting and local additions:
32 I Message-Id: <E10HmaY-0005vi-00@the.local.host.name>
33 F From: CALLER_NAME <CALLER@test.ex>
34   Date: Tue, 2 Mar 1999 09:44:33 +0000
35
36 Data file name: TESTSUITE/spool//input//10HmaY-0005vi-00-D
37 Data file written for message 10HmaY-0005vi-00
38 >>Generated Received: header line
39 P Received: from CALLER by the.local.host.name with local (Exim x.yz)
40         (envelope-from <CALLER@test.ex>)
41         id 10HmaY-0005vi-00
42         for kilos@recurse.test.ex; Tue, 2 Mar 1999 09:44:33 +0000
43 calling local_scan(); timeout=300
44 local_scan() returned 0 NULL
45 Writing spool header file: TESTSUITE/spool//input//hdr.pppp
46 DSN: Write SPOOL :-dsn_envid NULL
47 DSN: Write SPOOL :-dsn_ret 0
48 DSN: Flags :0
49 DSN: **** SPOOL_OUT - address: |kilos@recurse.test.ex| errorsto: |NULL| orcpt: |NULL| dsn_flags: 0
50 Renaming spool header file: TESTSUITE/spool//input//10HmaY-0005vi-00-H
51 Size of headers = sss
52 LOG: MAIN
53   <= CALLER@test.ex U=CALLER P=local S=sss
54 search_tidyup called
55 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xfbb95cfd -N -odi -Mc 10HmaY-0005vi-00
56 Exim version x.yz ....
57 changed uid/gid: forcing real = effective
58   uid=uuuu gid=EXIM_GID pid=pppp
59 configuration file is TESTSUITE/test-config
60 trusted user
61 admin user
62 seeking password data for user "CALLER": cache not available
63 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
64 set_process_info: pppp delivering specified messages
65 set_process_info: pppp delivering 10HmaY-0005vi-00
66 Trying spool file TESTSUITE/spool//input//10HmaY-0005vi-00-D
67 reading spool file 10HmaY-0005vi-00-H
68 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=CALLER@test.ex
69 sender_local=1 ident=CALLER
70 Non-recipients:
71 Empty Tree
72 ---- End of tree ----
73 recipients_count=1
74 **** SPOOL_IN - No additional fields
75 body_linecount=0 message_linecount=7
76 DSN: set orcpt: NULL  flags: 0
77 Delivery address list:
78   kilos@recurse.test.ex 
79 locking TESTSUITE/spool/db/retry.lockfile
80 locked  TESTSUITE/spool/db/retry.lockfile
81 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
82 returned from EXIM_DBOPEN: (nil)
83 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
84 no retry data available
85 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
86 Considering: kilos@recurse.test.ex
87 unique = kilos@recurse.test.ex
88 no domain retry record
89 no address retry record
90 kilos@recurse.test.ex: queued for routing
91 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
92 routing kilos@recurse.test.ex
93 --------> r1 router <--------
94 local_part=kilos domain=recurse.test.ex
95 checking domains
96 recurse.test.ex in "!thishost.test.ex : !recurse.test.ex.test.ex"? yes (end of list)
97 calling r1 router
98 r1 router called for kilos@recurse.test.ex
99   domain = recurse.test.ex
100 DNS lookup of recurse.test.ex (MX) using fakens
101 DNS lookup of recurse.test.ex (MX) gave HOST_NOT_FOUND
102 returning DNS_NOMATCH
103 r1 router widened recurse.test.ex to recurse.test.ex.test.ex
104 DNS lookup of recurse.test.ex.test.ex (MX) using fakens
105 DNS lookup of recurse.test.ex.test.ex (MX) gave NO_DATA
106 returning DNS_NODATA
107 DNS lookup of recurse.test.ex.test.ex (A) using fakens
108 DNS lookup of recurse.test.ex.test.ex (A) succeeded
109 fully qualified name = recurse.test.ex.test.ex
110 recurse.test.ex.test.ex V4NET.99.0.2 mx=-1 sort=xx 
111 domain changed to recurse.test.ex.test.ex
112 rewriting header lines
113 rewrite_one_header: type=F:
114   From: CALLER_NAME <CALLER@test.ex>
115 re-routed to kilos@recurse.test.ex.test.ex
116 locking TESTSUITE/spool/db/retry.lockfile
117 locked  TESTSUITE/spool/db/retry.lockfile
118 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
119 returned from EXIM_DBOPEN: (nil)
120 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
121 no retry data available
122 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
123 Considering: kilos@recurse.test.ex.test.ex
124 unique = kilos@recurse.test.ex.test.ex
125 no domain retry record
126 no address retry record
127 kilos@recurse.test.ex.test.ex: queued for routing
128 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
129 routing kilos@recurse.test.ex.test.ex
130 --------> r1 router <--------
131 local_part=kilos domain=recurse.test.ex.test.ex
132 checking domains
133 recurse.test.ex.test.ex in "!thishost.test.ex : !recurse.test.ex.test.ex"? no (matched "!recurse.test.ex.test.ex")
134 r1 router skipped: domains mismatch
135 --------> r2 router <--------
136 local_part=kilos domain=recurse.test.ex.test.ex
137 checking local_parts
138 kilos in "miles"? no (end of list)
139 r2 router skipped: local_parts mismatch
140 --------> r3 router <--------
141 local_part=kilos domain=recurse.test.ex.test.ex
142 checking local_parts
143 kilos in "kilos"? yes (matched "kilos")
144 calling r3 router
145 rda_interpret (string): $local_part@$domain
146 expanded: kilos@recurse.test.ex.test.ex
147 file is not a filter file
148 parse_forward_list: kilos@recurse.test.ex.test.ex
149 extract item: kilos@recurse.test.ex.test.ex
150 r3 router generated kilos@recurse.test.ex.test.ex
151   errors_to=NULL transport=NULL
152   uid=unset gid=unset home=NULL
153 routed by r3 router
154   envelope to: kilos@recurse.test.ex.test.ex
155   transport: <none>
156 locking TESTSUITE/spool/db/retry.lockfile
157 locked  TESTSUITE/spool/db/retry.lockfile
158 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
159 returned from EXIM_DBOPEN: (nil)
160 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
161 no retry data available
162 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
163 Considering: kilos@recurse.test.ex.test.ex
164 unique = \0\kilos@recurse.test.ex.test.ex
165 no domain retry record
166 no address retry record
167 kilos@recurse.test.ex.test.ex: queued for routing
168 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
169 routing kilos@recurse.test.ex.test.ex
170 --------> r1 router <--------
171 local_part=kilos domain=recurse.test.ex.test.ex
172 checking domains
173 recurse.test.ex.test.ex in "!thishost.test.ex : !recurse.test.ex.test.ex"? no (matched "!recurse.test.ex.test.ex")
174 r1 router skipped: domains mismatch
175 --------> r2 router <--------
176 local_part=kilos domain=recurse.test.ex.test.ex
177 checking local_parts
178 kilos in "miles"? no (end of list)
179 r2 router skipped: local_parts mismatch
180 --------> r3 router <--------
181 r3 router skipped: previously routed kilos@recurse.test.ex.test.ex
182 --------> r4 router <--------
183 local_part=kilos domain=recurse.test.ex.test.ex
184 calling r4 router
185 r4 router called for kilos@recurse.test.ex.test.ex
186   domain = recurse.test.ex.test.ex
187 set transport t2
188 queued for t2 transport: local_part = kilos
189 domain = recurse.test.ex.test.ex
190   errors_to=NULL
191   domain_data=NULL localpart_data=NULL
192 routed by r4 router
193   envelope to: kilos@recurse.test.ex.test.ex
194   transport: t2
195 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
196 After routing:
197   Local deliveries:
198     kilos@recurse.test.ex.test.ex
199   Remote deliveries:
200   Failed addresses:
201   Deferred addresses:
202 search_tidyup called
203 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
204 --------> kilos@recurse.test.ex.test.ex <--------
205 locking TESTSUITE/spool/db/retry.lockfile
206 locked  TESTSUITE/spool/db/retry.lockfile
207 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
208 returned from EXIM_DBOPEN: (nil)
209 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
210 no retry data available
211 search_tidyup called
212 changed uid/gid: local delivery to kilos <kilos@recurse.test.ex.test.ex> transport=t2
213   uid=CALLER_UID gid=CALLER_GID pid=pppp
214   home=NULL current=/
215 set_process_info: pppp delivering 10HmaY-0005vi-00 to kilos using t2
216 appendfile transport entered
217 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
218   file=/dev/null format=unix
219   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
220   message_suffix=\n
221   maildir_use_size_file=no
222   locking by lockfile fcntl 
223 *** delivery by t2 transport bypassed by -N option
224 search_tidyup called
225 journalling kilos@recurse.test.ex.test.ex/t2
226 t2 transport returned OK for kilos@recurse.test.ex.test.ex
227 post-process kilos@recurse.test.ex.test.ex (0)
228 kilos@recurse.test.ex.test.ex delivered
229 kilos@recurse.test.ex.test.ex: children all complete
230 kilos@recurse.test.ex: children all complete
231 LOG: MAIN
232   *> kilos <kilos@recurse.test.ex> R=r4 T=t2
233 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
234 changed uid/gid: post-delivery tidying
235   uid=EXIM_UID gid=EXIM_GID pid=pppp
236 set_process_info: pppp tidying up after delivering 10HmaY-0005vi-00
237 DSN: processing router : r4
238 DSN: processing successful delivery address: kilos@recurse.test.ex.test.ex
239 DSN: Sender_address: CALLER@test.ex
240 DSN: orcpt: NULL  flags: 0
241 DSN: envid: NULL  ret: 0
242 DSN: Final recipient: kilos@recurse.test.ex.test.ex
243 DSN: Remote SMTP server supports DSN: 0
244 DSN: not sending DSN success message
245 DSN: processing router : r3
246 DSN: processing successful delivery address: kilos@recurse.test.ex.test.ex
247 DSN: Sender_address: CALLER@test.ex
248 DSN: orcpt: NULL  flags: 0
249 DSN: envid: NULL  ret: 0
250 DSN: Final recipient: kilos@recurse.test.ex.test.ex
251 DSN: Remote SMTP server supports DSN: 0
252 DSN: not sending DSN success message
253 LOG: MAIN
254   Completed
255 end delivery of 10HmaY-0005vi-00
256 search_tidyup called
257 search_tidyup called
258 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
259 search_tidyup called
260 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>