Testsuite: fix for possible queue-run misordering
[exim.git] / test / stderr / 0278
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 admin user
6 dropping to exim gid; retaining priv uid
7 seeking password data for user "CALLER": cache not available
8 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
9 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
10 sender address = CALLER@test.ex
11 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
12 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
13 Testing CALLER@test.ex
14 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
15 Considering CALLER@test.ex
16 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17 routing CALLER@test.ex
18 --------> r1 router <--------
19 local_part=CALLER domain=test.ex
20 checking local_parts
21 CALLER in "never"? no (end of list)
22 CALLER in "never1"? no (end of list)
23 CALLER in "CALLER"? yes (matched "CALLER")
24 data from lookup saved for cache for +local_localparts: key 'CALLER' value 'CALLER'
25 CALLER in "+never_localparts : +n1_localparts : ! +local_localparts"? no (matched "! +local_localparts")
26 r1 router skipped: local_parts mismatch
27 --------> r2 router <--------
28 local_part=CALLER domain=test.ex
29 checking local_parts
30 cached no match for +never_localparts
31 cached lookup data = NULL
32 cached no match for +n1_localparts
33 cached lookup data = NULL
34 CALLER in "<; never2 ; +n1_localparts"? no (end of list)
35 cached yes match for +local_localparts
36 cached lookup data = CALLER
37 CALLER in "+never_localparts : +n2_localparts : !+local_localparts"? no (matched "!+local_localparts" - cached)
38 r2 router skipped: local_parts mismatch
39 --------> r3 router <--------
40 local_part=CALLER domain=test.ex
41 checking local_parts
42 cached yes match for +local_localparts
43 cached lookup data = CALLER
44 CALLER in "+local_localparts"? yes (matched "+local_localparts" - cached)
45 checking for local user
46 seeking password data for user "CALLER": using cached result
47 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
48 calling r3 router
49 r3 router called for CALLER@test.ex
50   domain = test.ex
51 set transport t1
52 queued for t1 transport: local_part = CALLER
53 domain = test.ex
54   errors_to=NULL
55   domain_data=NULL local_part_data=CALLER
56 routed by r3 router
57   envelope to: CALLER@test.ex
58   transport: t1
59 search_tidyup called
60 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
61 Exim version x.yz ....
62 changed uid/gid: forcing real = effective
63   uid=uuuu gid=CALLER_GID pid=pppp
64 configuration file is TESTSUITE/test-config
65 admin user
66 changed uid/gid: privilege not needed
67   uid=EXIM_UID gid=EXIM_GID pid=pppp
68 seeking password data for user "CALLER": cache not available
69 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
70 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
71 sender address = CALLER@test.ex
72 set_process_info: pppp accepting a local non-SMTP message from <CALLER@test.ex>
73 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
74 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
75 Sender: CALLER@test.ex
76 Recipients:
77   CALLER@test.ex
78 search_tidyup called
79 >>Headers received:
80
81 rewrite_one_header: type=F:
82   From: CALLER_NAME <CALLER@test.ex>
83 search_tidyup called
84 >>Headers after rewriting and local additions:
85 I Message-Id: <E10HmaX-0005vi-00@myhost.test.ex>
86 F From: CALLER_NAME <CALLER@test.ex>
87   Date: Tue, 2 Mar 1999 09:44:33 +0000
88
89 Data file name: TESTSUITE/spool//input//10HmaX-0005vi-00-D
90 Data file written for message 10HmaX-0005vi-00
91 >>Generated Received: header line
92 P Received: from CALLER by myhost.test.ex with local (Exim x.yz)
93         (envelope-from <CALLER@test.ex>)
94         id 10HmaX-0005vi-00
95         for CALLER@test.ex;
96         Tue, 2 Mar 1999 09:44:33 +0000
97 Writing spool header file: TESTSUITE/spool//input//hdr.10HmaX-0005vi-00
98 DSN: **** SPOOL_OUT - address: <CALLER@test.ex> errorsto: <NULL> orcpt: <NULL> dsn_flags: 0x0
99 Renaming spool header file: TESTSUITE/spool//input//10HmaX-0005vi-00-H
100 Size of headers = sss
101 LOG: MAIN
102   <= CALLER@test.ex U=CALLER P=local S=sss
103 created log directory TESTSUITE/spool/log
104 search_tidyup called
105 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xf7715cfd -MCd local-accept-delivery -odi -Mc 10HmaX-0005vi-00
106 Exim version x.yz ....
107 changed uid/gid: forcing real = effective
108   uid=uuuu gid=EXIM_GID pid=pppp
109 configuration file is TESTSUITE/test-config
110 trusted user
111 admin user
112 dropping to exim gid; retaining priv uid
113 seeking password data for user "CALLER": cache not available
114 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
115 set_process_info: pppp delivering specified messages
116 set_process_info: pppp delivering 10HmaX-0005vi-00
117 Trying spool file TESTSUITE/spool//input//10HmaX-0005vi-00-D
118 reading spool file 10HmaX-0005vi-00-H
119 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=CALLER@test.ex
120 sender_local=1 ident=CALLER
121 Non-recipients:
122  Empty Tree
123 ---- End of tree ----
124 recipients_count=1
125 **** SPOOL_IN - No additional fields
126 body_linecount=0 message_linecount=8
127 DSN: set orcpt:   flags: 0x0
128 Delivery address list:
129   CALLER@test.ex 
130  locking TESTSUITE/spool/db/retry.lockfile
131  locked  TESTSUITE/spool/db/retry.lockfile
132  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
133  returned from EXIM_DBOPEN: (nil)
134  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
135 no retry data available
136 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
137 Considering: CALLER@test.ex
138 unique = CALLER@test.ex
139 no   domain  retry record
140 no   address retry record
141 CALLER@test.ex: queued for routing
142 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
143 routing CALLER@test.ex
144 --------> r1 router <--------
145 local_part=CALLER domain=test.ex
146 checking local_parts
147 CALLER in "never"? no (end of list)
148 CALLER in "never1"? no (end of list)
149 CALLER in "CALLER"? yes (matched "CALLER")
150 data from lookup saved for cache for +local_localparts: key 'CALLER' value 'CALLER'
151 CALLER in "+never_localparts : +n1_localparts : ! +local_localparts"? no (matched "! +local_localparts")
152 r1 router skipped: local_parts mismatch
153 --------> r2 router <--------
154 local_part=CALLER domain=test.ex
155 checking local_parts
156 cached no match for +never_localparts
157 cached lookup data = NULL
158 cached no match for +n1_localparts
159 cached lookup data = NULL
160 CALLER in "<; never2 ; +n1_localparts"? no (end of list)
161 cached yes match for +local_localparts
162 cached lookup data = CALLER
163 CALLER in "+never_localparts : +n2_localparts : !+local_localparts"? no (matched "!+local_localparts" - cached)
164 r2 router skipped: local_parts mismatch
165 --------> r3 router <--------
166 local_part=CALLER domain=test.ex
167 checking local_parts
168 cached yes match for +local_localparts
169 cached lookup data = CALLER
170 CALLER in "+local_localparts"? yes (matched "+local_localparts" - cached)
171 checking for local user
172 seeking password data for user "CALLER": using cached result
173 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
174 calling r3 router
175 r3 router called for CALLER@test.ex
176   domain = test.ex
177 set transport t1
178 queued for t1 transport: local_part = CALLER
179 domain = test.ex
180   errors_to=NULL
181   domain_data=NULL local_part_data=CALLER
182 routed by r3 router
183   envelope to: CALLER@test.ex
184   transport: t1
185 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
186 After routing:
187   Local deliveries:
188     CALLER@test.ex
189   Remote deliveries:
190   Failed addresses:
191   Deferred addresses:
192 search_tidyup called
193 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
194 --------> CALLER@test.ex <--------
195  locking TESTSUITE/spool/db/retry.lockfile
196  locked  TESTSUITE/spool/db/retry.lockfile
197  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
198  returned from EXIM_DBOPEN: (nil)
199  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
200 no retry data available
201 search_tidyup called
202 changed uid/gid: local delivery to CALLER <CALLER@test.ex> transport=t1
203   uid=CALLER_UID gid=CALLER_GID pid=pppp
204   home=CALLER_HOME current=CALLER_HOME
205 set_process_info: pppp delivering 10HmaX-0005vi-00 to CALLER using t1
206 appendfile transport entered
207 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
208   file=/dev/null format=unix
209   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
210   message_suffix=\n
211   maildir_use_size_file=no
212   locking by lockfile fcntl 
213 search_tidyup called
214 journalling CALLER@test.ex
215 t1 transport returned OK for CALLER@test.ex
216 post-process CALLER@test.ex (0)
217 CALLER@test.ex delivered
218 LOG: MAIN
219   => CALLER <CALLER@test.ex> R=r3 T=t1
220 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
221 changed uid/gid: post-delivery tidying
222   uid=EXIM_UID gid=EXIM_GID pid=pppp
223 set_process_info: pppp tidying up after delivering 10HmaX-0005vi-00
224 Processing retry items
225 Succeeded addresses:
226  CALLER@test.ex: no retry items
227 Failed addresses:
228 Deferred addresses:
229 end of retry processing
230 DSN: processing router : r3
231 DSN: processing successful delivery address: CALLER@test.ex
232 DSN: Sender_address: CALLER@test.ex
233 DSN: orcpt: NULL  flags: 0x0
234 DSN: envid: NULL  ret: 0
235 DSN: Final recipient: CALLER@test.ex
236 DSN: Remote SMTP server supports DSN: 0
237 DSN: not sending DSN success message
238 LOG: MAIN
239   Completed
240 end delivery of 10HmaX-0005vi-00
241 search_tidyup called
242 search_tidyup called
243 >>>>>>>>>>>>>>>> Exim pid=pppp (local-accept-delivery) terminating with rc=0 >>>>>>>>>>>>>>>>
244 search_tidyup called
245 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
246 Exim version x.yz ....
247 changed uid/gid: forcing real = effective
248   uid=uuuu gid=CALLER_GID pid=pppp
249 configuration file is TESTSUITE/test-config
250 admin user
251 dropping to exim gid; retaining priv uid
252 seeking password data for user "CALLER": cache not available
253 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
254 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
255 sender address = CALLER@test.ex
256 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
257 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
258 Testing unknown@test.ex
259 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
260 Considering unknown@test.ex
261 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
262 routing unknown@test.ex
263 --------> r1 router <--------
264 local_part=unknown domain=test.ex
265 checking local_parts
266 unknown in "never"? no (end of list)
267 unknown in "never1"? no (end of list)
268 unknown in "CALLER"? no (end of list)
269 unknown in "+never_localparts : +n1_localparts : ! +local_localparts"? yes (end of list)
270 calling r1 router
271 r1 router called for unknown@test.ex
272   domain = test.ex
273 route_item = never
274 test.ex in "never"? no (end of list)
275 r1 router declined for unknown@test.ex
276 --------> r2 router <--------
277 local_part=unknown domain=test.ex
278 checking local_parts
279 cached no match for +never_localparts
280 cached lookup data = NULL
281 cached no match for +n1_localparts
282 cached lookup data = NULL
283 unknown in "<; never2 ; +n1_localparts"? no (end of list)
284 cached no match for +local_localparts
285 cached lookup data = NULL
286 unknown in "+never_localparts : +n2_localparts : !+local_localparts"? yes (end of list)
287 calling r2 router
288 r2 router called for unknown@test.ex
289   domain = test.ex
290 test.ex in "*"? yes (matched "*")
291 DNS lookup of test.ex (MX) using fakens
292 DNS lookup of test.ex (MX) gave NO_DATA
293 returning DNS_NODATA
294 faking res_search(MX) response length as 65535
295  writing neg-cache entry for test.ex-MX-xxxx, ttl 3000
296 test.ex (MX resp) DNSSEC
297 DNS lookup of test.ex (A) using fakens
298 DNS lookup of test.ex (A) gave NO_DATA
299 returning DNS_NODATA
300 faking res_search(A) response length as 65535
301  writing neg-cache entry for test.ex-A-xxxx, ttl 3000
302 r2 router declined for unknown@test.ex
303 --------> r3 router <--------
304 local_part=unknown domain=test.ex
305 checking local_parts
306 cached no match for +local_localparts
307 cached lookup data = NULL
308 unknown in "+local_localparts"? no (end of list)
309 r3 router skipped: local_parts mismatch
310 --------> r4 router <--------
311 local_part=unknown domain=test.ex
312 checking local_parts
313 cached no match for +local_localparts
314 cached lookup data = NULL
315 unknown in "test.ex"? no (end of list)
316 unknown in "unexpanded"? no (end of list)
317 unknown in "+local_localparts : +expanded : +unexpanded"? no (end of list)
318 r4 router skipped: local_parts mismatch
319 --------> r5 router <--------
320 local_part=unknown domain=test.ex
321 checking local_parts
322 cached no match for +local_localparts
323 cached lookup data = NULL
324 unknown in "test.ex"? no (end of list)
325 cached no match for +unexpanded
326 cached lookup data = NULL
327 unknown in "+local_localparts : +expanded : +unexpanded"? no (end of list)
328 r5 router skipped: local_parts mismatch
329 no more routers
330 search_tidyup called
331 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=2 >>>>>>>>>>>>>>>>