Debug: clarify SMTP DATA ops in transport
[exim.git] / test / stderr / 0275
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 userx@test.ex
14 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
15 Considering userx@test.ex
16 test.ex in "! *.ex"? no (matched "! *.ex")
17 test.ex in "test.ex"? yes (matched "test.ex")
18 test.ex in percent_hack_domains? yes (matched "+not_queue_domains")
19 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
20 routing userx@test.ex
21 --------> r00 router <--------
22 local_part=userx domain=test.ex
23 checking domains
24 test.ex in "userx"? no (end of list)
25 test.ex in "+nocache"? no (end of list)
26 r00 router skipped: domains mismatch
27 --------> r01 router <--------
28 local_part=userx domain=test.ex
29 checking domains
30 test.ex in "userx"? no (end of list)
31 test.ex in "+nocache"? no (end of list)
32 r01 router skipped: domains mismatch
33 --------> r02 router <--------
34 local_part=userx domain=test.ex
35 checking domains
36 test.ex in "userx"? no (end of list)
37 test.ex in "+nocache"? no (end of list)
38 test.ex in "+nocache2"? no (end of list)
39 r02 router skipped: domains mismatch
40 --------> r03 router <--------
41 local_part=userx domain=test.ex
42 checking domains
43 test.ex in "userx"? no (end of list)
44 test.ex in "+nocache"? no (end of list)
45 test.ex in "+nocache2"? no (end of list)
46 r03 router skipped: domains mismatch
47 --------> r04 router <--------
48 local_part=userx domain=test.ex
49 checking domains
50 test.ex in "userx"? no (end of list)
51 test.ex in "+forcecache"? no (end of list)
52 r04 router skipped: domains mismatch
53 --------> r05 router <--------
54 local_part=userx domain=test.ex
55 checking domains
56 cached no match for +forcecache
57 cached lookup data = NULL
58 test.ex in "+forcecache"? no (end of list)
59 r05 router skipped: domains mismatch
60 --------> r1 router <--------
61 local_part=userx domain=test.ex
62 checking domains
63 test.ex in "never.ex"? no (end of list)
64 test.ex in "never1.ex"? no (end of list)
65 test.ex in "test.ex"? yes (matched "test.ex")
66 data from lookup saved for cache for +local_domains: key 'test.ex' value 'test.ex'
67 test.ex in "+never_domains : +n1_domains : ! +local_domains"? no (matched "! +local_domains")
68 r1 router skipped: domains mismatch
69 --------> r2 router <--------
70 local_part=userx domain=test.ex
71 checking domains
72 cached no match for +never_domains
73 cached lookup data = NULL
74 cached no match for +n1_domains
75 cached lookup data = NULL
76 test.ex in "<; never2.ex ; +n1_domains"? no (end of list)
77 cached yes match for +local_domains
78 cached lookup data = test.ex
79 test.ex in "+never_domains : +n2_domains : !+local_domains"? no (matched "!+local_domains" - cached)
80 r2 router skipped: domains mismatch
81 --------> r3 router <--------
82 local_part=userx domain=test.ex
83 checking domains
84 cached yes match for +local_domains
85 cached lookup data = test.ex
86 test.ex in "+local_domains"? yes (matched "+local_domains" - cached)
87 checking local_parts
88 userx in "userx"? yes (matched "userx")
89 calling r3 router
90 r3 router called for userx@test.ex
91   domain = test.ex
92 set transport t1
93 queued for t1 transport: local_part = userx
94 domain = test.ex
95   errors_to=NULL
96   domain_data=test.ex local_part_data=userx
97 routed by r3 router
98   envelope to: userx@test.ex
99   transport: t1
100 search_tidyup called
101 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
102 Exim version x.yz ....
103 changed uid/gid: forcing real = effective
104   uid=uuuu gid=CALLER_GID pid=pppp
105 configuration file is TESTSUITE/test-config
106 admin user
107 changed uid/gid: privilege not needed
108   uid=EXIM_UID gid=EXIM_GID pid=pppp
109 seeking password data for user "CALLER": cache not available
110 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
111 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
112 sender address = CALLER@test.ex
113 set_process_info: pppp accepting a local non-SMTP message from <CALLER@test.ex>
114 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
115 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
116 Sender: CALLER@test.ex
117 Recipients:
118   userx@test.ex
119 search_tidyup called
120 >>Headers received:
121
122 qualify & rewrite recipients list
123 global rewrite rules
124 rewrite headers
125  rewrite_one_header: type=F:
126    From: CALLER_NAME <CALLER@test.ex>
127 search_tidyup called
128 >>Headers after rewriting and local additions:
129 I Message-Id: <E10HmaX-0005vi-00@myhost.test.ex>
130 F From: CALLER_NAME <CALLER@test.ex>
131   Date: Tue, 2 Mar 1999 09:44:33 +0000
132
133 Data file name: TESTSUITE/spool//input//10HmaX-0005vi-00-D
134 Data file written for message 10HmaX-0005vi-00
135 >>Generated Received: header line
136 P Received: from CALLER by myhost.test.ex with local (Exim x.yz)
137         (envelope-from <CALLER@test.ex>)
138         id 10HmaX-0005vi-00
139         for userx@test.ex;
140         Tue, 2 Mar 1999 09:44:33 +0000
141 Writing spool header file: TESTSUITE/spool//input//hdr.10HmaX-0005vi-00
142 DSN: **** SPOOL_OUT - address: <userx@test.ex> errorsto: <NULL> orcpt: <NULL> dsn_flags: 0x0
143 Renaming spool header file: TESTSUITE/spool//input//10HmaX-0005vi-00-H
144 Size of headers = sss
145 LOG: MAIN
146   <= CALLER@test.ex U=CALLER P=local S=sss
147 created log directory TESTSUITE/spool/log
148 search_tidyup called
149 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xf7715cfd -MCd local-accept-delivery -odi -Mc 10HmaX-0005vi-00
150 Exim version x.yz ....
151 changed uid/gid: forcing real = effective
152   uid=uuuu gid=EXIM_GID pid=pppp
153 configuration file is TESTSUITE/test-config
154 trusted user
155 admin user
156 dropping to exim gid; retaining priv uid
157 seeking password data for user "CALLER": cache not available
158 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
159 set_process_info: pppp delivering specified messages
160 set_process_info: pppp delivering 10HmaX-0005vi-00
161 Trying spool file TESTSUITE/spool//input//10HmaX-0005vi-00-D
162 reading spool file 10HmaX-0005vi-00-H
163 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=CALLER@test.ex
164 sender_local=1 ident=CALLER
165 Non-recipients:
166  Empty Tree
167 ---- End of tree ----
168 recipients_count=1
169 **** SPOOL_IN - No additional fields
170 body_linecount=0 message_linecount=8
171 DSN: set orcpt:   flags: 0x0
172 Delivery address list:
173   userx@test.ex 
174  locking TESTSUITE/spool/db/retry.lockfile
175  locked  TESTSUITE/spool/db/retry.lockfile
176  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
177  returned from EXIM_DBOPEN: (nil)
178  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
179 no retry data available
180 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
181 Considering: userx@test.ex
182 test.ex in "! *.ex"? no (matched "! *.ex")
183 test.ex in "test.ex"? yes (matched "test.ex")
184 test.ex in percent_hack_domains? yes (matched "+not_queue_domains")
185 cached no match for +hold_domains
186 test.ex in hold_domains? no (end of list)
187 unique = userx@test.ex
188 no   domain  retry record
189 no   address retry record
190 userx@test.ex: queued for routing
191 cached yes match for +not_queue_domains
192 test.ex in queue_domains? no (matched "!+not_queue_domains" - cached)
193 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
194 routing userx@test.ex
195 --------> r00 router <--------
196 local_part=userx domain=test.ex
197 checking domains
198 test.ex in "userx"? no (end of list)
199 test.ex in "+nocache"? no (end of list)
200 r00 router skipped: domains mismatch
201 --------> r01 router <--------
202 local_part=userx domain=test.ex
203 checking domains
204 test.ex in "userx"? no (end of list)
205 test.ex in "+nocache"? no (end of list)
206 r01 router skipped: domains mismatch
207 --------> r02 router <--------
208 local_part=userx domain=test.ex
209 checking domains
210 test.ex in "userx"? no (end of list)
211 test.ex in "+nocache"? no (end of list)
212 test.ex in "+nocache2"? no (end of list)
213 r02 router skipped: domains mismatch
214 --------> r03 router <--------
215 local_part=userx domain=test.ex
216 checking domains
217 test.ex in "userx"? no (end of list)
218 test.ex in "+nocache"? no (end of list)
219 test.ex in "+nocache2"? no (end of list)
220 r03 router skipped: domains mismatch
221 --------> r04 router <--------
222 local_part=userx domain=test.ex
223 checking domains
224 test.ex in "userx"? no (end of list)
225 test.ex in "+forcecache"? no (end of list)
226 r04 router skipped: domains mismatch
227 --------> r05 router <--------
228 local_part=userx domain=test.ex
229 checking domains
230 cached no match for +forcecache
231 cached lookup data = NULL
232 test.ex in "+forcecache"? no (end of list)
233 r05 router skipped: domains mismatch
234 --------> r1 router <--------
235 local_part=userx domain=test.ex
236 checking domains
237 test.ex in "never.ex"? no (end of list)
238 test.ex in "never1.ex"? no (end of list)
239 test.ex in "test.ex"? yes (matched "test.ex")
240 data from lookup saved for cache for +local_domains: key 'test.ex' value 'test.ex'
241 test.ex in "+never_domains : +n1_domains : ! +local_domains"? no (matched "! +local_domains")
242 r1 router skipped: domains mismatch
243 --------> r2 router <--------
244 local_part=userx domain=test.ex
245 checking domains
246 cached no match for +never_domains
247 cached lookup data = NULL
248 cached no match for +n1_domains
249 cached lookup data = NULL
250 test.ex in "<; never2.ex ; +n1_domains"? no (end of list)
251 cached yes match for +local_domains
252 cached lookup data = test.ex
253 test.ex in "+never_domains : +n2_domains : !+local_domains"? no (matched "!+local_domains" - cached)
254 r2 router skipped: domains mismatch
255 --------> r3 router <--------
256 local_part=userx domain=test.ex
257 checking domains
258 cached yes match for +local_domains
259 cached lookup data = test.ex
260 test.ex in "+local_domains"? yes (matched "+local_domains" - cached)
261 checking local_parts
262 userx in "userx"? yes (matched "userx")
263 calling r3 router
264 r3 router called for userx@test.ex
265   domain = test.ex
266 set transport t1
267 queued for t1 transport: local_part = userx
268 domain = test.ex
269   errors_to=NULL
270   domain_data=test.ex local_part_data=userx
271 routed by r3 router
272   envelope to: userx@test.ex
273   transport: t1
274 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
275 After routing:
276   Local deliveries:
277     userx@test.ex
278   Remote deliveries:
279   Failed addresses:
280   Deferred addresses:
281 search_tidyup called
282 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
283 --------> userx@test.ex <--------
284  locking TESTSUITE/spool/db/retry.lockfile
285  locked  TESTSUITE/spool/db/retry.lockfile
286  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
287  returned from EXIM_DBOPEN: (nil)
288  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
289 no retry data available
290 search_tidyup called
291 changed uid/gid: local delivery to userx <userx@test.ex> transport=t1
292   uid=CALLER_UID gid=CALLER_GID pid=pppp
293   home=NULL current=/
294 set_process_info: pppp delivering 10HmaX-0005vi-00 to userx using t1
295 appendfile transport entered
296 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
297   file=/dev/null format=unix
298   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
299   message_suffix=\n
300   maildir_use_size_file=no
301   locking by lockfile fcntl 
302 search_tidyup called
303 journalling userx@test.ex
304 t1 transport returned OK for userx@test.ex
305 post-process userx@test.ex (0)
306 userx@test.ex delivered
307 LOG: MAIN
308   => userx <userx@test.ex> R=r3 T=t1
309 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
310 changed uid/gid: post-delivery tidying
311   uid=EXIM_UID gid=EXIM_GID pid=pppp
312 set_process_info: pppp tidying up after delivering 10HmaX-0005vi-00
313 Processing retry items
314 Succeeded addresses:
315  userx@test.ex: no retry items
316 Failed addresses:
317 Deferred addresses:
318 end of retry processing
319 DSN: processing router : r3
320 DSN: processing successful delivery address: userx@test.ex
321 DSN: Sender_address: CALLER@test.ex
322 DSN: orcpt: NULL  flags: 0x0
323 DSN: envid: NULL  ret: 0
324 DSN: Final recipient: userx@test.ex
325 DSN: Remote SMTP server supports DSN: 0
326 DSN: not sending DSN success message
327 LOG: MAIN
328   Completed
329 end delivery of 10HmaX-0005vi-00
330 search_tidyup called
331 search_tidyup called
332 >>>>>>>>>>>>>>>> Exim pid=pppp (local-accept-delivery) terminating with rc=0 >>>>>>>>>>>>>>>>
333 search_tidyup called
334 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
335 Exim version x.yz ....
336 changed uid/gid: forcing real = effective
337   uid=uuuu gid=CALLER_GID pid=pppp
338 configuration file is TESTSUITE/test-config
339 admin user
340 changed uid/gid: privilege not needed
341   uid=EXIM_UID gid=EXIM_GID pid=pppp
342 seeking password data for user "CALLER": cache not available
343 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
344 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
345 sender address = CALLER@test.ex
346 sender_fullhost = [127.0.0.1]
347 sender_rcvhost = [127.0.0.1]
348 host in hosts_connection_nolog? no (option unset)
349 LOG: smtp_connection MAIN
350   SMTP connection from [127.0.0.1]
351 host in host_lookup? no (option unset)
352 set_process_info: pppp handling incoming connection from [127.0.0.1]
353 host in host_reject_connection? no (option unset)
354 host in sender_unqualified_hosts? no (option unset)
355 host in recipient_unqualified_hosts? no (option unset)
356 host in helo_verify_hosts? no (option unset)
357 host in helo_try_verify_hosts? no (option unset)
358 host in helo_accept_junk_hosts? no (option unset)
359 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
360 smtp_setup_msg entered
361 SMTP<< HELO test
362 test in helo_lookup_domains? no (end of list)
363 sender_fullhost = (test) [127.0.0.1]
364 sender_rcvhost = [127.0.0.1] (helo=test)
365 set_process_info: pppp handling incoming connection from (test) [127.0.0.1]
366 SMTP>> 250 myhost.test.ex Hello test [127.0.0.1]
367 SMTP<< MAIL FROM:<test@test.ex>
368 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
369 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
370 SMTP>> 250 OK
371 SMTP<< RCPT TO:<error@test.ex>
372 test.ex in "! *.ex"? no (matched "! *.ex")
373 test.ex in "test.ex"? yes (matched "test.ex")
374 test.ex in percent_hack_domains? yes (matched "+not_queue_domains")
375 processing "accept" (TESTSUITE/test-config 102)
376 check verify = recipient
377 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
378 Verifying error@test.ex
379 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
380 Considering error@test.ex
381 cached no match for +hold_domains
382 cached yes match for +not_queue_domains
383 test.ex in percent_hack_domains? yes (matched "+not_queue_domains" - cached)
384 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
385 routing error@test.ex
386 --------> r0f router <--------
387 local_part=error domain=test.ex
388 checking domains
389 LOG: MAIN PANIC
390   unknown named domain list "+no_such_list"
391 domains check lookup or other defer
392 ----------- end verify ------------
393 accept: condition test deferred in inline ACL
394 SMTP>> 451 Temporary local problem - please try later
395 LOG: MAIN REJECT
396   H=(test) [127.0.0.1] F=<test@test.ex> temporarily rejected RCPT <error@test.ex>: domains check lookup or other defer
397 SMTP<< QUIT
398 SMTP>> 221 myhost.test.ex closing connection
399 LOG: smtp_connection MAIN
400   SMTP connection from (test) [127.0.0.1] closed by QUIT
401 search_tidyup called
402 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>