Debug: build a summary string tracking transport SMTP commands & responses
[exim.git] / test / stderr / 0432
1 >>> host in hosts_connection_nolog? no (option unset)
2 >>> host in host_lookup? no (option unset)
3 >>> host in host_reject_connection? no (option unset)
4 >>> host in sender_unqualified_hosts? no (option unset)
5 >>> host in recipient_unqualified_hosts? no (option unset)
6 >>> host in helo_verify_hosts? no (option unset)
7 >>> host in helo_try_verify_hosts? no (option unset)
8 >>> host in helo_accept_junk_hosts? no (option unset)
9 >>> test in helo_lookup_domains? no (end of list)
10 >>> using ACL "mail"
11 >>> processing "accept" (TESTSUITE/test-config 20)
12 >>> check verify = sender/callout=1s,maxwait=1s
13 >>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
14 >>> routing x@y
15 >>> calling r1 router
16 >>> routed by r1 router
17 >>> local host found for non-MX address
18 MUNGED: ::1 will be omitted in what follows
19 >>> get[host|ipnode]byname[2] looked up these IP addresses:
20 >>>   name=127.0.0.1 address=127.0.0.1
21 >>> Attempting full verification using callout
22 >>> ... callout omitted by default when host testing
23 >>> (Use -bhc if you want the callouts to happen.)
24 >>> ----------- end verify ------------
25 >>> accept: condition test succeeded in ACL "mail"
26 >>> end of ACL "mail": ACCEPT
27 Exim version x.yz ....
28 changed uid/gid: forcing real = effective
29   uid=uuuu gid=CALLER_GID pid=pppp
30 configuration file is TESTSUITE/test-config
31 admin user
32 changed uid/gid: privilege not needed
33   uid=EXIM_UID gid=EXIM_GID pid=pppp
34 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
35 sender address = CALLER@myhost.test.ex
36 sender_fullhost = [1.2.3.4]
37 sender_rcvhost = [1.2.3.4]
38 host in hosts_connection_nolog? no (option unset)
39 LOG: smtp_connection MAIN
40   SMTP connection from [1.2.3.4]
41 host in host_lookup? no (option unset)
42 set_process_info: pppp handling incoming connection from [1.2.3.4]
43 host in host_reject_connection? no (option unset)
44 host in sender_unqualified_hosts? no (option unset)
45 host in recipient_unqualified_hosts? no (option unset)
46 host in helo_verify_hosts? no (option unset)
47 host in helo_try_verify_hosts? no (option unset)
48 host in helo_accept_junk_hosts? no (option unset)
49 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
50 smtp_setup_msg entered
51 SMTP<< helo test
52 test in helo_lookup_domains? no (end of list)
53 sender_fullhost = (test) [1.2.3.4]
54 sender_rcvhost = [1.2.3.4] (helo=test)
55 set_process_info: pppp handling incoming connection from (test) [1.2.3.4]
56 SMTP>> 250 myhost.test.ex Hello test [1.2.3.4]
57 SMTP<< mail from:<x@y>
58 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
59 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
60 using ACL "mail"
61 processing "accept" (TESTSUITE/test-config 20)
62 check verify = sender/callout=1s,maxwait=1s
63 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
64 Verifying x@y
65 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
66 Considering x@y
67 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
68 routing x@y
69 --------> r1 router <--------
70 local_part=x domain=y
71 calling r1 router
72 r1 router called for x@y
73   domain = y
74 set transport t1
75 queued for t1 transport: local_part = x
76 domain = y
77   errors_to=NULL
78   domain_data=NULL local_part_data=NULL
79 routed by r1 router
80   envelope to: x@y
81   transport: t1
82 using host_fake_gethostbyname for 127.0.0.1 (IPv4)
83 local host found for non-MX address
84 MUNGED: ::1 will be omitted in what follows
85 get[host|ipnode]byname[2] looked up these IP addresses:
86   name=127.0.0.1 address=127.0.0.1
87 Attempting full verification using callout
88  locking TESTSUITE/spool/db/callout.lockfile
89  locked  TESTSUITE/spool/db/callout.lockfile
90  EXIM_DBOPEN: file <TESTSUITE/spool/db/callout> dir <TESTSUITE/spool/db> flags=O_RDWR
91  returned from EXIM_DBOPEN: 0xAAAAAAAA
92  opened hints database TESTSUITE/spool/db/callout: flags=O_RDWR
93  dbfn_read: key=y
94  callout cache: no domain record found for y
95  dbfn_read: key=x@y
96  callout cache: no address record found for x@y
97  EXIM_DBCLOSE(0xAAAAAAAA)
98  closed hints database and lockfile
99 interface=NULL port=1224
100 Connecting to 127.0.0.1 [127.0.0.1]:1224 ...  connected
101   SMTP<< 220 server ready
102 127.0.0.1 in hosts_avoid_esmtp? no (option unset)
103   SMTP>> EHLO myhost.test.ex
104 cmd buf flush ddd bytes
105   SMTP<< 250 OK
106 not using PIPELINING
107 not using DSN
108 127.0.0.1 in hosts_require_auth? no (option unset)
109   SMTP>> MAIL FROM:<>
110 cmd buf flush ddd bytes
111   SMTP<< 250 OK
112   SMTP>> RCPT TO:<x@y>
113 cmd buf flush ddd bytes
114 sync_responses expect rcpt for x@y
115   SMTP<< 250 OK
116   SMTP>> QUIT
117 cmd buf flush ddd bytes
118   SMTP<< 220 OK
119   SMTP(close)>>
120 cmdlog: '220:EHLO:250:MAIL:250:RCPT:250:QUIT:220'
121  locking TESTSUITE/spool/db/callout.lockfile
122  locked  TESTSUITE/spool/db/callout.lockfile
123  EXIM_DBOPEN: file <TESTSUITE/spool/db/callout> dir <TESTSUITE/spool/db> flags=O_RDWR|O_CREAT
124  returned from EXIM_DBOPEN: 0xAAAAAAAA
125  opened hints database TESTSUITE/spool/db/callout: flags=O_RDWR|O_CREAT
126  dbfn_write: key=y
127  wrote callout cache domain record for y:
128    result=1 postmaster=0 random=0
129  dbfn_write: key=x@y
130  wrote positive callout cache address record for x@y
131  EXIM_DBCLOSE(0xAAAAAAAA)
132  closed hints database and lockfile
133 ----------- end verify ------------
134 sender x@y verified ok
135 accept: condition test succeeded in ACL "mail"
136 end of ACL "mail": ACCEPT
137 SMTP>> 250 OK
138 SMTP<< quit
139 SMTP>> 221 myhost.test.ex closing connection
140 LOG: smtp_connection MAIN
141   SMTP connection from (test) [1.2.3.4] closed by QUIT
142 search_tidyup called
143 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
144 Exim version x.yz ....
145 changed uid/gid: forcing real = effective
146   uid=uuuu gid=CALLER_GID pid=pppp
147 configuration file is TESTSUITE/test-config
148 admin user
149 changed uid/gid: privilege not needed
150   uid=EXIM_UID gid=EXIM_GID pid=pppp
151 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
152 sender address = CALLER@myhost.test.ex
153 sender_fullhost = [1.2.3.4]
154 sender_rcvhost = [1.2.3.4]
155 host in hosts_connection_nolog? no (option unset)
156 LOG: smtp_connection MAIN
157   SMTP connection from [1.2.3.4]
158 host in host_lookup? no (option unset)
159 set_process_info: pppp handling incoming connection from [1.2.3.4]
160 host in host_reject_connection? no (option unset)
161 host in sender_unqualified_hosts? no (option unset)
162 host in recipient_unqualified_hosts? no (option unset)
163 host in helo_verify_hosts? no (option unset)
164 host in helo_try_verify_hosts? no (option unset)
165 host in helo_accept_junk_hosts? no (option unset)
166 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
167 smtp_setup_msg entered
168 SMTP<< helo test
169 test in helo_lookup_domains? no (end of list)
170 sender_fullhost = (test) [1.2.3.4]
171 sender_rcvhost = [1.2.3.4] (helo=test)
172 set_process_info: pppp handling incoming connection from (test) [1.2.3.4]
173 SMTP>> 250 myhost.test.ex Hello test [1.2.3.4]
174 SMTP<< mail from:<x@y>
175 spool directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100 msg_size = 0
176 log directory space = nnnnnK inodes = nnnnn check_space = 10240K inodes = 100
177 using ACL "mail"
178 processing "accept" (TESTSUITE/test-config 20)
179 check verify = sender/callout=1s,maxwait=1s
180 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
181 Verifying x@y
182 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
183 Considering x@y
184 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
185 routing x@y
186 --------> r1 router <--------
187 local_part=x domain=y
188 calling r1 router
189 r1 router called for x@y
190   domain = y
191 set transport t1
192 queued for t1 transport: local_part = x
193 domain = y
194   errors_to=NULL
195   domain_data=NULL local_part_data=NULL
196 routed by r1 router
197   envelope to: x@y
198   transport: t1
199 using host_fake_gethostbyname for 127.0.0.1 (IPv4)
200 local host found for non-MX address
201 MUNGED: ::1 will be omitted in what follows
202 get[host|ipnode]byname[2] looked up these IP addresses:
203   name=127.0.0.1 address=127.0.0.1
204 Attempting full verification using callout
205  locking TESTSUITE/spool/db/callout.lockfile
206  locked  TESTSUITE/spool/db/callout.lockfile
207  EXIM_DBOPEN: file <TESTSUITE/spool/db/callout> dir <TESTSUITE/spool/db> flags=O_RDWR
208  returned from EXIM_DBOPEN: 0xAAAAAAAA
209  opened hints database TESTSUITE/spool/db/callout: flags=O_RDWR
210  dbfn_read: key=y
211  callout cache: found domain record for y
212  dbfn_read: key=x@y
213  callout cache: found address record for x@y
214  callout cache: address record is positive
215  EXIM_DBCLOSE(0xAAAAAAAA)
216  closed hints database and lockfile
217 ----------- end verify ------------
218 sender x@y verified ok
219 accept: condition test succeeded in ACL "mail"
220 end of ACL "mail": ACCEPT
221 SMTP>> 250 OK
222 SMTP<< quit
223 SMTP>> 221 myhost.test.ex closing connection
224 LOG: smtp_connection MAIN
225   SMTP connection from (test) [1.2.3.4] closed by QUIT
226 search_tidyup called
227 >>>>>>>>>>>>>>>> Exim pid=pppp (fresh-exec) terminating with rc=0 >>>>>>>>>>>>>>>>
228 >>> host in hosts_connection_nolog? no (option unset)
229 >>> host in host_lookup? no (option unset)
230 >>> host in host_reject_connection? no (option unset)
231 >>> host in sender_unqualified_hosts? no (option unset)
232 >>> host in recipient_unqualified_hosts? no (option unset)
233 >>> host in helo_verify_hosts? no (option unset)
234 >>> host in helo_try_verify_hosts? no (option unset)
235 >>> host in helo_accept_junk_hosts? no (option unset)
236 >>> test in helo_lookup_domains? no (end of list)
237 >>> using ACL "mail"
238 >>> processing "accept" (TESTSUITE/test-config 20)
239 >>> check verify = sender/callout=1s,maxwait=1s
240 >>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
241 >>> routing x@y
242 >>> calling r1 router
243 >>> routed by r1 router
244 >>> local host found for non-MX address
245 MUNGED: ::1 will be omitted in what follows
246 >>> get[host|ipnode]byname[2] looked up these IP addresses:
247 >>>   name=127.0.0.1 address=127.0.0.1
248 >>> Attempting full verification using callout
249 >>> callout cache: found domain record for y
250 >>> callout cache: found address record for x@y
251 >>> callout cache: address record is positive
252 >>> ----------- end verify ------------
253 >>> accept: condition test succeeded in ACL "mail"
254 >>> end of ACL "mail": ACCEPT
255 >>> host in hosts_connection_nolog? no (option unset)
256 >>> host in host_lookup? no (option unset)
257 >>> host in host_reject_connection? no (option unset)
258 >>> host in sender_unqualified_hosts? no (option unset)
259 >>> host in recipient_unqualified_hosts? no (option unset)
260 >>> host in helo_verify_hosts? no (option unset)
261 >>> host in helo_try_verify_hosts? no (option unset)
262 >>> host in helo_accept_junk_hosts? no (option unset)
263 >>> test in helo_lookup_domains? no (end of list)
264 >>> using ACL "mail"
265 >>> processing "accept" (TESTSUITE/test-config 20)
266 >>> check verify = sender/callout=1s,maxwait=1s
267 >>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
268 >>> routing a@b
269 >>> calling r1 router
270 >>> routed by r1 router
271 >>> local host found for non-MX address
272 MUNGED: ::1 will be omitted in what follows
273 >>> get[host|ipnode]byname[2] looked up these IP addresses:
274 >>>   name=127.0.0.1 address=127.0.0.1
275 >>> Attempting full verification using callout
276 >>> callout cache: no domain record found for b
277 >>> callout cache: no address record found for a@b
278 >>> interface=NULL port=1224
279 >>> Connecting to 127.0.0.1 [127.0.0.1]:1224 ...  connected
280 >>>   SMTP<< 220 server ready
281 >>> 127.0.0.1 in hosts_avoid_esmtp? no (option unset)
282 >>>   SMTP>> EHLO myhost.test.ex
283 >>> cmd buf flush 21 bytes
284 >>>   SMTP<< 250 OK
285 >>> 127.0.0.1 in hosts_require_auth? no (option unset)
286 >>>   SMTP>> MAIL FROM:<>
287 >>> cmd buf flush 14 bytes
288 >>>   SMTP<< 250 OK
289 >>>   SMTP>> RCPT TO:<a@b>
290 >>> cmd buf flush 15 bytes
291 >>>   SMTP<< 250 OK
292 >>>   SMTP>> QUIT
293 >>> cmd buf flush 6 bytes
294 >>>   SMTP<< 220 OK
295 >>>   SMTP(close)>>
296 >>> cmdlog: '220:EHLO:250:MAIL:250:RCPT:250:QUIT:220'
297 >>> wrote callout cache domain record for b:
298 >>>   result=1 postmaster=0 random=0
299 >>> wrote positive callout cache address record for a@b
300 >>> ----------- end verify ------------
301 >>> accept: condition test succeeded in ACL "mail"
302 >>> end of ACL "mail": ACCEPT
303 >>> host in hosts_connection_nolog? no (option unset)
304 >>> host in host_lookup? no (option unset)
305 >>> host in host_reject_connection? no (option unset)
306 >>> host in sender_unqualified_hosts? no (option unset)
307 >>> host in recipient_unqualified_hosts? no (option unset)
308 >>> host in helo_verify_hosts? no (option unset)
309 >>> host in helo_try_verify_hosts? no (option unset)
310 >>> host in helo_accept_junk_hosts? no (option unset)
311 >>> test in helo_lookup_domains? no (end of list)
312 >>> using ACL "mail"
313 >>> processing "accept" (TESTSUITE/test-config 20)
314 >>> check verify = sender/callout=1s,maxwait=1s
315 >>> >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
316 >>> routing p1@q
317 >>> calling r1 router
318 >>> routed by r1 router
319 >>> local host found for non-MX address
320 MUNGED: ::1 will be omitted in what follows
321 >>> get[host|ipnode]byname[2] looked up these IP addresses:
322 >>>   name=127.0.0.1 address=127.0.0.1
323 >>> Attempting full verification using callout
324 >>> callout cache: no domain record found for q
325 >>> callout cache: no address record found for p1@q
326 >>> interface=NULL port=1224
327 >>> Connecting to 127.0.0.1 [127.0.0.1]:1224 ...  connected
328 >>>   SMTP<< 220 server ready
329 >>> 127.0.0.1 in hosts_avoid_esmtp? no (option unset)
330 >>>   SMTP>> EHLO myhost.test.ex
331 >>> cmd buf flush 21 bytes
332 >>>   SMTP(close)>>
333 >>> cmdlog: '220:EHLO'
334 >>> SMTP timeout
335 >>> ----------- end verify ------------
336 >>> accept: condition test deferred in ACL "mail"
337 LOG: H=(test) [1.2.3.4] sender verify defer for <p1@q>: Could not complete sender verify callout: 127.0.0.1 [127.0.0.1] : SMTP timeout after EHLO myhost.test.ex
338 LOG: H=(test) [1.2.3.4] temporarily rejected MAIL <p1@q>: Could not complete sender verify callout