Fix heavy-pipeline SMTP command input corruption. Bug 2250
[users/jgh/exim.git] / test / stderr / 0022
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 changed uid/gid: privilege not needed
7   uid=EXIM_UID gid=EXIM_GID pid=pppp
8 seeking password data for user "CALLER": cache not available
9 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
10 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
11 sender address = CALLER@test.ex
12 sender_fullhost = [V4NET.9.8.7]
13 sender_rcvhost = [V4NET.9.8.7]
14 host in hosts_connection_nolog? no (end of list)
15 LOG: smtp_connection MAIN
16   SMTP connection from [V4NET.9.8.7]
17 host in host_lookup? no (option unset)
18 set_process_info: pppp handling incoming connection from [V4NET.9.8.7]
19 host in host_reject_connection? no (option unset)
20 host in sender_unqualified_hosts? no (option unset)
21 host in recipient_unqualified_hosts? no (option unset)
22 host in helo_verify_hosts? no (option unset)
23 host in helo_try_verify_hosts? no (option unset)
24 host in helo_accept_junk_hosts? no (option unset)
25 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
26 smtp_setup_msg entered
27 SMTP<< mail from:<x@y>
28 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
29 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
30 SMTP>> 250 OK
31 SMTP<< rcpt to:<warn_empty@test.ex>
32 using ACL "warn_empty"
33 processing "warn"
34 warn: condition test succeeded in ACL "warn_empty"
35 processing "accept"
36 accept: condition test succeeded in ACL "warn_empty"
37 end of ACL "warn_empty": ACCEPT
38 SMTP>> 250 Accepted
39 DSN: orcpt: NULL  flags: 0
40 SMTP<< data
41 SMTP>> 354 Enter message, ending with "." on a line by itself
42 search_tidyup called
43 >>Headers received:
44
45 search_tidyup called
46 >>Headers after rewriting and local additions:
47
48 Data file name: TESTSUITE/spool//input//10HmbF-0005vi-00-D
49 Data file written for message 10HmbF-0005vi-00
50 >>Generated Received: header line
51 P Received: from [V4NET.9.8.7]
52         by myhost.test.ex with smtp (Exim x.yz)
53         (envelope-from <x@y>)
54         id 10HmbF-0005vi-00
55         for warn_empty@test.ex; Tue, 2 Mar 1999 09:44:33 +0000
56 calling local_scan(); timeout=300
57 local_scan() returned 0 NULL
58 LOG: MAIN
59   <= x@y H=[V4NET.9.8.7] P=smtp S=sss
60 SMTP>> 250 OK id=10HmbF-0005vi-00
61 smtp_setup_msg entered
62 SMTP<< quit
63 SMTP>> 221 myhost.test.ex closing connection
64 LOG: smtp_connection MAIN
65   SMTP connection from [V4NET.9.8.7] closed by QUIT
66 search_tidyup called
67 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
68 Exim version x.yz ....
69 changed uid/gid: forcing real = effective
70   uid=uuuu gid=CALLER_GID pid=pppp
71 configuration file is TESTSUITE/test-config
72 admin user
73 changed uid/gid: privilege not needed
74   uid=EXIM_UID gid=EXIM_GID pid=pppp
75 seeking password data for user "CALLER": cache not available
76 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
77 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
78 sender address = CALLER@test.ex
79 sender_fullhost = [V4NET.9.8.7]
80 sender_rcvhost = [V4NET.9.8.7]
81 host in hosts_connection_nolog? no (end of list)
82 LOG: smtp_connection MAIN
83   SMTP connection from [V4NET.9.8.7]
84 host in host_lookup? no (option unset)
85 set_process_info: pppp handling incoming connection from [V4NET.9.8.7]
86 host in host_reject_connection? no (option unset)
87 host in sender_unqualified_hosts? no (option unset)
88 host in recipient_unqualified_hosts? no (option unset)
89 host in helo_verify_hosts? no (option unset)
90 host in helo_try_verify_hosts? no (option unset)
91 host in helo_accept_junk_hosts? no (option unset)
92 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
93 smtp_setup_msg entered
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:<warn_log@test.ex>
99 using ACL "warn_log"
100 processing "warn"
101 l_message: warn log message
102 warn: condition test succeeded in ACL "warn_log"
103 LOG: MAIN
104   H=[V4NET.9.8.7] Warning: warn log message
105 processing "accept"
106 accept: condition test succeeded in ACL "warn_log"
107 end of ACL "warn_log": ACCEPT
108 SMTP>> 250 Accepted
109 DSN: orcpt: NULL  flags: 0
110 SMTP<< data
111 SMTP>> 354 Enter message, ending with "." on a line by itself
112 search_tidyup called
113 >>Headers received:
114
115 search_tidyup called
116 >>Headers after rewriting and local additions:
117
118 Data file name: TESTSUITE/spool//input//10HmbG-0005vi-00-D
119 Data file written for message 10HmbG-0005vi-00
120 >>Generated Received: header line
121 P Received: from [V4NET.9.8.7]
122         by myhost.test.ex with smtp (Exim x.yz)
123         (envelope-from <x@y>)
124         id 10HmbG-0005vi-00
125         for warn_log@test.ex; Tue, 2 Mar 1999 09:44:33 +0000
126 calling local_scan(); timeout=300
127 local_scan() returned 0 NULL
128 LOG: MAIN
129   <= x@y H=[V4NET.9.8.7] P=smtp S=sss
130 SMTP>> 250 OK id=10HmbG-0005vi-00
131 smtp_setup_msg entered
132 SMTP<< quit
133 SMTP>> 221 myhost.test.ex closing connection
134 LOG: smtp_connection MAIN
135   SMTP connection from [V4NET.9.8.7] closed by QUIT
136 search_tidyup called
137 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
138 Exim version x.yz ....
139 changed uid/gid: forcing real = effective
140   uid=uuuu gid=CALLER_GID pid=pppp
141 configuration file is TESTSUITE/test-config
142 admin user
143 changed uid/gid: privilege not needed
144   uid=EXIM_UID gid=EXIM_GID pid=pppp
145 seeking password data for user "CALLER": cache not available
146 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
147 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
148 sender address = CALLER@test.ex
149 sender_fullhost = [V4NET.9.8.7]
150 sender_rcvhost = [V4NET.9.8.7]
151 host in hosts_connection_nolog? no (end of list)
152 LOG: smtp_connection MAIN
153   SMTP connection from [V4NET.9.8.7]
154 host in host_lookup? no (option unset)
155 set_process_info: pppp handling incoming connection from [V4NET.9.8.7]
156 host in host_reject_connection? no (option unset)
157 host in sender_unqualified_hosts? no (option unset)
158 host in recipient_unqualified_hosts? no (option unset)
159 host in helo_verify_hosts? no (option unset)
160 host in helo_try_verify_hosts? no (option unset)
161 host in helo_accept_junk_hosts? no (option unset)
162 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
163 smtp_setup_msg entered
164 SMTP<< mail from:<x@y>
165 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
166 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
167 SMTP>> 250 OK
168 SMTP<< rcpt to:<warn_user@test.ex>
169 using ACL "warn_user"
170 processing "warn"
171   message: warn user message
172 warn: condition test succeeded in ACL "warn_user"
173 processing "accept"
174 accept: condition test succeeded in ACL "warn_user"
175 end of ACL "warn_user": ACCEPT
176 SMTP>> 250 Accepted
177 DSN: orcpt: NULL  flags: 0
178 SMTP<< data
179 SMTP>> 354 Enter message, ending with "." on a line by itself
180 search_tidyup called
181 >>Headers received:
182
183 search_tidyup called
184 >>Headers after rewriting and local additions:
185
186 Data file name: TESTSUITE/spool//input//10HmbH-0005vi-00-D
187 Data file written for message 10HmbH-0005vi-00
188 >>Generated Received: header line
189 P Received: from [V4NET.9.8.7]
190         by myhost.test.ex with smtp (Exim x.yz)
191         (envelope-from <x@y>)
192         id 10HmbH-0005vi-00
193         for warn_user@test.ex; Tue, 2 Mar 1999 09:44:33 +0000
194 >>Headers added by MAIL or RCPT ACL:
195   X-ACL-Warn: warn user message
196 >>
197 calling local_scan(); timeout=300
198 local_scan() returned 0 NULL
199 LOG: MAIN
200   <= x@y H=[V4NET.9.8.7] P=smtp S=sss
201 SMTP>> 250 OK id=10HmbH-0005vi-00
202 smtp_setup_msg entered
203 SMTP<< quit
204 SMTP>> 221 myhost.test.ex closing connection
205 LOG: smtp_connection MAIN
206   SMTP connection from [V4NET.9.8.7] closed by QUIT
207 search_tidyup called
208 >>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=0 >>>>>>>>>>>>>>>>
209 >>> host in hosts_connection_nolog? no (end of list)
210 LOG: SMTP connection from [V4NET.9.8.7]
211 >>> host in host_lookup? no (option unset)
212 >>> host in host_reject_connection? no (option unset)
213 >>> host in sender_unqualified_hosts? no (option unset)
214 >>> host in recipient_unqualified_hosts? no (option unset)
215 >>> host in helo_verify_hosts? no (option unset)
216 >>> host in helo_try_verify_hosts? no (option unset)
217 >>> host in helo_accept_junk_hosts? no (option unset)
218 >>> using ACL "defer"
219 >>> processing "defer"
220 >>>   message: forcibly deferred
221 >>> defer: condition test succeeded in ACL "defer"
222 >>> end of ACL "defer": DEFER
223 LOG: H=[V4NET.9.8.7] F=<x@y> temporarily rejected RCPT <defer@y>: forcibly deferred
224 >>> using ACL "accept"
225 >>> processing "accept"
226 >>> accept: condition test succeeded in ACL "accept"
227 >>> end of ACL "accept": ACCEPT
228 >>> using ACL "drop"
229 >>> processing "drop"
230 >>>   message: forcibly dropped
231 >>> drop: condition test succeeded in ACL "drop"
232 >>> end of ACL "drop": DROP
233 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <drop@y>: forcibly dropped
234 LOG: SMTP connection from [V4NET.9.8.7] closed by DROP in ACL
235 >>> host in hosts_connection_nolog? no (end of list)
236 LOG: SMTP connection from [V4NET.9.8.7]
237 >>> host in host_lookup? no (option unset)
238 >>> host in host_reject_connection? no (option unset)
239 >>> host in sender_unqualified_hosts? no (option unset)
240 >>> host in recipient_unqualified_hosts? no (option unset)
241 >>> host in helo_verify_hosts? no (option unset)
242 >>> host in helo_try_verify_hosts? no (option unset)
243 >>> host in helo_accept_junk_hosts? no (option unset)
244 >>> using ACL "defer_senders"
245 >>> processing "defer"
246 >>> check senders = :
247 >>>  in ":"? yes (matched "")
248 >>> defer: condition test succeeded in ACL "defer_senders"
249 >>> end of ACL "defer_senders": DEFER
250 LOG: H=[V4NET.9.8.7] F=<> temporarily rejected RCPT <defer_senders@y>
251 LOG: SMTP connection from [V4NET.9.8.7] closed by QUIT
252 >>> host in hosts_connection_nolog? no (end of list)
253 LOG: SMTP connection from [V4NET.9.8.7]
254 >>> host in host_lookup? no (option unset)
255 >>> host in host_reject_connection? no (option unset)
256 >>> host in sender_unqualified_hosts? no (option unset)
257 >>> host in recipient_unqualified_hosts? no (option unset)
258 >>> host in helo_verify_hosts? no (option unset)
259 >>> host in helo_try_verify_hosts? no (option unset)
260 >>> host in helo_accept_junk_hosts? no (option unset)
261 >>> using ACL "delay_accept"
262 >>> processing "accept"
263 >>> check delay = 1s
264 >>> delay modifier requests 1-second delay
265 >>> delay skipped in -bh checking mode
266 >>> accept: condition test succeeded in ACL "delay_accept"
267 >>> end of ACL "delay_accept": ACCEPT
268 >>> using ACL "delay_warn"
269 >>> processing "warn"
270 >>> check delay = 1s
271 >>> delay modifier requests 1-second delay
272 >>> delay skipped in -bh checking mode
273 >>> warn: condition test succeeded in ACL "delay_warn"
274 >>> processing "accept"
275 >>> accept: condition test succeeded in ACL "delay_warn"
276 >>> end of ACL "delay_warn": ACCEPT
277 LOG: SMTP connection from [V4NET.9.8.7] closed by QUIT
278 >>> host in hosts_connection_nolog? no (end of list)
279 LOG: SMTP connection from [V4NET.9.8.7]
280 >>> host in host_lookup? no (option unset)
281 >>> host in host_reject_connection? no (option unset)
282 >>> host in sender_unqualified_hosts? no (option unset)
283 >>> host in recipient_unqualified_hosts? no (option unset)
284 >>> host in helo_verify_hosts? no (option unset)
285 >>> host in helo_try_verify_hosts? no (option unset)
286 >>> host in helo_accept_junk_hosts? no (option unset)
287 >>> using ACL "host_check"
288 >>> processing "deny"
289 >>> check hosts = net-lsearch;TESTSUITE/aux-var/0022.hosts
290 >>> host in "net-lsearch;TESTSUITE/aux-var/0022.hosts"? yes (matched "net-lsearch;TESTSUITE/aux-var/0022.hosts")
291 >>>   message: host data >$host_data<
292 >>> deny: condition test succeeded in ACL "host_check"
293 >>> end of ACL "host_check": DENY
294 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <host_check@y>: host data >A host-specific message<
295 >>> using ACL "host_check"
296 >>> processing "deny"
297 >>> check hosts = net-lsearch;TESTSUITE/aux-var/0022.hosts
298 >>> host in "net-lsearch;TESTSUITE/aux-var/0022.hosts"? yes (matched "net-lsearch;TESTSUITE/aux-var/0022.hosts")
299 >>>   message: host data >$host_data<
300 >>> deny: condition test succeeded in ACL "host_check"
301 >>> end of ACL "host_check": DENY
302 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <host_check@y>: host data >A host-specific message<
303 >>> using ACL "host_check2"
304 >>> processing "deny"
305 >>>   message: host data >$host_data<
306 >>> check hosts = +some_hosts
307 >>> host in "net-lsearch;TESTSUITE/aux-var/0022.hosts"? yes (matched "net-lsearch;TESTSUITE/aux-var/0022.hosts")
308 >>> host in "+some_hosts"? yes (matched "+some_hosts")
309 >>> deny: condition test succeeded in ACL "host_check2"
310 >>> end of ACL "host_check2": DENY
311 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <host_check2@y>: host data >A host-specific message<
312 >>> using ACL "host_check2"
313 >>> processing "deny"
314 >>>   message: host data >$host_data<
315 >>> check hosts = +some_hosts
316 >>> host in "+some_hosts"? yes (matched "+some_hosts" - cached)
317 >>> deny: condition test succeeded in ACL "host_check2"
318 >>> end of ACL "host_check2": DENY
319 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <host_check2@y>: host data >A host-specific message<
320 LOG: SMTP connection from [V4NET.9.8.7] closed by QUIT
321 LOG: smtp_connection MAIN
322   SMTP connection from CALLER
323 LOG: MAIN
324   Connections=0
325 LOG: MAIN
326   <= CALLER@test.ex U=CALLER P=local-smtp S=sss
327 LOG: MAIN
328   frozen by ACL
329 LOG: MAIN
330   <= CALLER@test.ex U=CALLER P=local-smtp S=sss
331 delivering 10HmaY-0005vi-00
332 LOG: MAIN
333   *> accept <accept@y> R=accept T=appendfile
334 LOG: MAIN
335   Completed
336 LOG: MAIN
337   <= CALLER@test.ex U=CALLER P=local-smtp S=sss
338 LOG: delay_delivery MAIN
339   no immediate delivery: queued by ACL
340 LOG: MAIN
341   <= CALLER@test.ex U=CALLER P=local-smtp S=sss
342 delivering 10HmbA-0005vi-00
343 LOG: MAIN
344   *> accept <accept@y> R=accept T=appendfile
345 LOG: MAIN
346   Completed
347 LOG: smtp_connection MAIN
348   SMTP connection from CALLER closed by QUIT
349 >>> host in hosts_connection_nolog? no (end of list)
350 LOG: SMTP connection from [V4NET.9.8.7]
351 >>> host in host_lookup? no (option unset)
352 >>> host in host_reject_connection? no (option unset)
353 >>> host in sender_unqualified_hosts? no (option unset)
354 >>> host in recipient_unqualified_hosts? no (option unset)
355 >>> host in helo_verify_hosts? no (option unset)
356 >>> host in helo_try_verify_hosts? no (option unset)
357 >>> host in helo_accept_junk_hosts? no (option unset)
358 >>> using ACL "nested_drop"
359 >>> processing "accept"
360 >>> check acl = drop
361 >>>  using ACL "drop"
362 >>>  processing "drop"
363 >>>    message: forcibly dropped
364 >>>  drop: condition test succeeded in ACL "drop"
365 >>>  end of ACL "drop": DROP
366 >>> accept: condition test yielded "drop" in ACL "nested_drop"
367 >>> accept: endpass encountered - denying access
368 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <nested_drop@y>: forcibly dropped
369 LOG: SMTP connection from [V4NET.9.8.7] closed by DROP in ACL
370 >>> host in hosts_connection_nolog? no (end of list)
371 LOG: SMTP connection from [V4NET.9.8.7]
372 >>> host in host_lookup? no (option unset)
373 >>> host in host_reject_connection? no (option unset)
374 >>> host in sender_unqualified_hosts? no (option unset)
375 >>> host in recipient_unqualified_hosts? no (option unset)
376 >>> host in helo_verify_hosts? no (option unset)
377 >>> host in helo_try_verify_hosts? no (option unset)
378 >>> host in helo_accept_junk_hosts? no (option unset)
379 >>> using ACL "nested_drop_require"
380 >>> processing "require"
381 >>> check acl = drop
382 >>>  using ACL "drop"
383 >>>  processing "drop"
384 >>>    message: forcibly dropped
385 >>>  drop: condition test succeeded in ACL "drop"
386 >>>  end of ACL "drop": DROP
387 >>> require: condition test yielded "drop" in ACL "nested_drop_require"
388 >>> end of ACL "nested_drop_require": not OK
389 LOG: H=[V4NET.9.8.7] F=<x@y> rejected RCPT <nested_drop_require@y>: forcibly dropped
390 LOG: SMTP connection from [V4NET.9.8.7] closed by DROP in ACL
391
392 ******** SERVER ********