Bugzilla #1106: Don't pass DKIM compound log line as format string
[exim.git] / test / stderr / 0386
1 Exim version x.yz ....
2 changed uid/gid: forcing real = effective
3   uid=uuuu gid=CALLER_GID pid=pppp
4 seeking password data for user "CALLER": cache not available
5 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
6 configuration file is TESTSUITE/test-config
7 trusted user
8 admin user
9 changed uid/gid: privilege not needed
10   uid=EXIM_UID gid=EXIM_GID pid=pppp
11 seeking password data for user "CALLER": using cached result
12 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
13 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
14 sender address = CALLER@test.ex
15 sender_fullhost = [V4NET.9.8.7]
16 sender_rcvhost = [V4NET.9.8.7]
17 host in hosts_connection_nolog? no (option unset)
18 LOG: smtp_connection MAIN
19   SMTP connection from [V4NET.9.8.7]
20 host in host_lookup? no (option unset)
21 set_process_info: pppp handling incoming connection from [V4NET.9.8.7]
22 host in host_reject_connection? no (option unset)
23 host in sender_unqualified_hosts? no (option unset)
24 host in recipient_unqualified_hosts? no (option unset)
25 host in helo_verify_hosts? no (option unset)
26 host in helo_try_verify_hosts? no (option unset)
27 host in helo_accept_junk_hosts? no (option unset)
28 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
29 smtp_setup_msg entered
30 SMTP<< mail from:<x@y>
31 SMTP>> 250 OK
32 SMTP<< rcpt to:<1@b>
33 read ACL from file TESTSUITE/aux-fixed/0386.acl1
34 processing "accept"
35 check hosts = :
36 host in ":"? no (end of list)
37 accept: condition test failed
38 processing "deny"
39 check local_parts = ^.*[@%!/|]
40 1 in "^.*[@%!/|]"? no (end of list)
41 deny: condition test failed
42 processing "require"
43 check verify = sender/defer_ok
44 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
45 Verifying x@y
46 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
47 Considering x@y
48 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
49 routing x@y
50 --------> r1 router <--------
51 local_part=x domain=y
52 calling r1 router
53 r1 router called for x@y
54   domain = y
55 set transport t1
56 queued for t1 transport: local_part = x
57 domain = y
58   errors_to=NULL
59   domain_data=NULL localpart_data=NULL
60 routed by r1 router
61   envelope to: x@y
62   transport: t1
63 ----------- end verify ------------
64 sender x@y verified ok
65 require: condition test succeeded
66 processing "deny"
67 deny: condition test succeeded
68 SMTP>> 550 No such user here
69 LOG: MAIN REJECT
70   H=[V4NET.9.8.7] F=<x@y> rejected RCPT <1@b>: No such user here
71 SMTP<< rset
72 SMTP>> 250 Reset OK
73 SMTP<< mail from:<x@y>
74 SMTP>> 250 OK
75 SMTP<< rcpt to:<1@b>
76 using ACL "TESTSUITE/aux-fixed/0386.acl1"
77 processing "accept"
78 check hosts = :
79 host in ":"? no (end of list)
80 accept: condition test failed
81 processing "deny"
82 check local_parts = ^.*[@%!/|]
83 1 in "^.*[@%!/|]"? no (end of list)
84 deny: condition test failed
85 processing "require"
86 check verify = sender/defer_ok
87 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
88 Verifying x@y
89 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
90 Considering x@y
91 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
92 routing x@y
93 --------> r1 router <--------
94 local_part=x domain=y
95 calling r1 router
96 r1 router called for x@y
97   domain = y
98 queued for t1 transport: local_part = x
99 domain = y
100   errors_to=NULL
101   domain_data=NULL localpart_data=NULL
102 routed by r1 router
103   envelope to: x@y
104   transport: t1
105 ----------- end verify ------------
106 sender x@y verified ok
107 require: condition test succeeded
108 processing "deny"
109 deny: condition test succeeded
110 SMTP>> 550 No such user here
111 LOG: MAIN REJECT
112   H=[V4NET.9.8.7] F=<x@y> rejected RCPT <1@b>: No such user here
113 SMTP<< quit
114 SMTP>> 221 myhost.test.ex closing connection
115 LOG: smtp_connection MAIN
116   SMTP connection from [V4NET.9.8.7] closed by QUIT
117 search_tidyup called
118 >>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=0 >>>>>>>>>>>>>>>>
119 Exim version x.yz ....
120 changed uid/gid: forcing real = effective
121   uid=uuuu gid=CALLER_GID pid=pppp
122 seeking password data for user "CALLER": cache not available
123 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
124 configuration file is TESTSUITE/test-config
125 trusted user
126 admin user
127 changed uid/gid: privilege not needed
128   uid=EXIM_UID gid=EXIM_GID pid=pppp
129 seeking password data for user "CALLER": using cached result
130 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
131 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
132 sender address = NULL
133 sender_fullhost = [V4NET.11.12.13]
134 sender_rcvhost = [V4NET.11.12.13] (ident=CALLER)
135 set_process_info: pppp handling incoming connection from [V4NET.11.12.13] via -oMa
136 set_process_info: pppp accepting a local SMTP message from <CALLER>
137 host in hosts_connection_nolog? no (option unset)
138 LOG: smtp_connection MAIN
139   SMTP connection from CALLER
140 host in host_lookup? no (option unset)
141 set_process_info: pppp handling incoming connection from [V4NET.11.12.13] U=CALLER
142 host in host_reject_connection? no (option unset)
143 host in sender_unqualified_hosts? no (option unset)
144 host in recipient_unqualified_hosts? no (option unset)
145 host in helo_verify_hosts? no (option unset)
146 host in helo_try_verify_hosts? no (option unset)
147 host in helo_accept_junk_hosts? no (option unset)
148 SMTP>> 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
149 smtp_setup_msg entered
150 SMTP<< mail from:<x@y>
151 SMTP>> 250 OK
152 SMTP<< rcpt to:<2@b>
153 read ACL from file TESTSUITE/aux-fixed/0386.acl2
154 processing "warn"
155 check dnslists = rbl.test.ex 
156 DNS list check: rbl.test.ex
157 new DNS lookup for 13.12.11.V4NET.rbl.test.ex
158 DNS lookup of 13.12.11.V4NET.rbl.test.ex (A) using fakens
159 DNS lookup of 13.12.11.V4NET.rbl.test.ex (A) succeeded
160 DNS lookup for 13.12.11.V4NET.rbl.test.ex succeeded (yielding 127.0.0.2)
161 DNS lookup of 13.12.11.V4NET.rbl.test.ex (TXT) using fakens
162 DNS lookup of 13.12.11.V4NET.rbl.test.ex (TXT) succeeded
163 => that means V4NET.11.12.13 is listed at rbl.test.ex
164 warn: condition test succeeded
165 LOG: MAIN
166   H=[V4NET.11.12.13] U=CALLER Warning: found in rbl.test.ex: This is a test blacklisting message
167 created log directory TESTSUITE/spool/log
168 processing "accept"
169 accept: condition test succeeded
170 SMTP>> 250 Accepted
171 SMTP<< data
172 SMTP>> 354 Enter message, ending with "." on a line by itself
173 search_tidyup called
174 host in ignore_fromline_hosts? no (option unset)
175 >>Headers received:
176
177 search_tidyup called
178 >>Headers after rewriting and local additions:
179
180 Data file written for message 10HmaX-0005vi-00
181 >>Generated Received: header line
182 P Received: from [V4NET.11.12.13] (ident=CALLER)
183         by myhost.test.ex with smtp (Exim x.yz)
184         (envelope-from <x@y>)
185         id 10HmaX-0005vi-00
186         for 2@b; Tue, 2 Mar 1999 09:44:33 +0000
187 >>Headers added by MAIL or RCPT ACL:
188   X-Warning: V4NET.11.12.13 is listed at rbl.test.ex
189   X-Warning: This is a test blacklisting message
190 >>
191 calling local_scan(); timeout=300
192 local_scan() returned 0 NULL
193 Writing spool header file
194 Size of headers = sss
195 LOG: MAIN
196   <= x@y H=[V4NET.11.12.13] U=CALLER P=smtp S=sss
197 SMTP>> 250 OK id=10HmaX-0005vi-00
198 search_tidyup called
199 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xfbb95cfd -odi -Mc 10HmaX-0005vi-00
200 Exim version x.yz ....
201 changed uid/gid: forcing real = effective
202   uid=uuuu gid=EXIM_GID pid=pppp
203 seeking password data for user "CALLER": cache not available
204 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
205 configuration file is TESTSUITE/test-config
206 trusted user
207 admin user
208 seeking password data for user "CALLER": using cached result
209 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
210 set_process_info: pppp delivering specified messages
211 set_process_info: pppp delivering 10HmaX-0005vi-00
212 reading spool file 10HmaX-0005vi-00-H
213 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=x@y
214 sender_fullhost = [V4NET.11.12.13]
215 sender_rcvhost = [V4NET.11.12.13] (ident=CALLER)
216 sender_local=0 ident=CALLER
217 Non-recipients:
218 Empty Tree
219 ---- End of tree ----
220 recipients_count=1
221 body_linecount=1 message_linecount=7
222 Delivery address list:
223   2@b 
224 locking TESTSUITE/spool/db/retry.lockfile
225 locked TESTSUITE/spool/db/retry.lockfile
226 EXIM_DBOPEN(TESTSUITE/spool/db/retry)
227 returned from EXIM_DBOPEN
228 ensuring TESTSUITE/spool/db/retry.lockfile is owned by exim
229 no retry data available
230 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
231 Considering: 2@b
232 unique = 2@b
233 no domain retry record
234 no address retry record
235 2@b: queued for routing
236 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
237 routing 2@b
238 --------> r1 router <--------
239 local_part=2 domain=b
240 calling r1 router
241 r1 router called for 2@b
242   domain = b
243 set transport t1
244 queued for t1 transport: local_part = 2
245 domain = b
246   errors_to=NULL
247   domain_data=NULL localpart_data=NULL
248 routed by r1 router
249   envelope to: 2@b
250   transport: t1
251 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
252 After routing:
253   Local deliveries:
254     2@b
255   Remote deliveries:
256   Failed addresses:
257   Deferred addresses:
258 search_tidyup called
259 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
260 --------> 2@b <--------
261 locking TESTSUITE/spool/db/retry.lockfile
262 locked TESTSUITE/spool/db/retry.lockfile
263 EXIM_DBOPEN(TESTSUITE/spool/db/retry)
264 returned from EXIM_DBOPEN
265 no retry data available
266 search_tidyup called
267 changed uid/gid: local delivery to 2 <2@b> transport=t1
268   uid=CALLER_UID gid=CALLER_GID pid=pppp
269   home=NULL current=/
270 set_process_info: pppp delivering 10HmaX-0005vi-00 to 2 using t1
271 appendfile transport entered
272 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
273   file=TESTSUITE/test-mail/2 format=unix
274   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
275   message_suffix=\n
276   maildir_use_size_file=no
277   locking by lockfile fcntl 
278 lock name: TESTSUITE/test-mail/2.lock
279 hitch name: TESTSUITE/test-mail/2.lock.test.ex.dddddddd.pppppppp
280 lock file created
281 mailbox TESTSUITE/test-mail/2 is locked
282 writing to file TESTSUITE/test-mail/2
283 writing data block fd=dddd size=sss timeout=0
284 writing data block fd=dddd size=sss timeout=0
285 writing data block fd=dddd size=sss timeout=0
286 appendfile yields 0 with errno=dd more_errno=dd
287 search_tidyup called
288 journalling 2@b
289 t1 transport returned OK for 2@b
290 post-process 2@b (0)
291 2@b delivered
292 LOG: MAIN
293   => 2 <2@b> R=r1 T=t1
294 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
295 changed uid/gid: post-delivery tidying
296   uid=EXIM_UID gid=EXIM_GID pid=pppp
297 set_process_info: pppp tidying up after delivering 10HmaX-0005vi-00
298 Processing retry items
299 Succeeded addresses:
300 2@b: no retry items
301 Failed addresses:
302 Deferred addresses:
303 end of retry processing
304 LOG: MAIN
305   Completed
306 end delivery of 10HmaX-0005vi-00
307 search_tidyup called
308 search_tidyup called
309 >>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=0 >>>>>>>>>>>>>>>>
310 smtp_setup_msg entered
311 SMTP<< rset
312 SMTP>> 250 Reset OK
313 SMTP<< mail from:<x@y>
314 SMTP>> 250 OK
315 SMTP<< rcpt to:<2@b>
316 using ACL "TESTSUITE/aux-fixed/0386.acl2"
317 processing "warn"
318 check dnslists = rbl.test.ex 
319 DNS list check: rbl.test.ex
320 using result of previous DNS lookup
321 DNS lookup for 13.12.11.V4NET.rbl.test.ex succeeded (yielding 127.0.0.2)
322 => that means V4NET.11.12.13 is listed at rbl.test.ex
323 warn: condition test succeeded
324 LOG: MAIN
325   H=[V4NET.11.12.13] U=CALLER Warning: found in rbl.test.ex: This is a test blacklisting message
326 processing "accept"
327 accept: condition test succeeded
328 SMTP>> 250 Accepted
329 SMTP<< data
330 SMTP>> 354 Enter message, ending with "." on a line by itself
331 search_tidyup called
332 host in ignore_fromline_hosts? no (option unset)
333 >>Headers received:
334
335 search_tidyup called
336 >>Headers after rewriting and local additions:
337
338 Data file written for message 10HmaY-0005vi-00
339 >>Generated Received: header line
340 P Received: from [V4NET.11.12.13] (ident=CALLER)
341         by myhost.test.ex with smtp (Exim x.yz)
342         (envelope-from <x@y>)
343         id 10HmaY-0005vi-00
344         for 2@b; Tue, 2 Mar 1999 09:44:33 +0000
345 >>Headers added by MAIL or RCPT ACL:
346   X-Warning: V4NET.11.12.13 is listed at rbl.test.ex
347   X-Warning: This is a test blacklisting message
348 >>
349 calling local_scan(); timeout=300
350 local_scan() returned 0 NULL
351 Writing spool header file
352 Size of headers = sss
353 LOG: MAIN
354   <= x@y H=[V4NET.11.12.13] U=CALLER P=smtp S=sss
355 SMTP>> 250 OK id=10HmaY-0005vi-00
356 search_tidyup called
357 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d=0xfbb95cfd -odi -Mc 10HmaY-0005vi-00
358 Exim version x.yz ....
359 changed uid/gid: forcing real = effective
360   uid=uuuu gid=EXIM_GID pid=pppp
361 seeking password data for user "CALLER": cache not available
362 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
363 configuration file is TESTSUITE/test-config
364 trusted user
365 admin user
366 seeking password data for user "CALLER": using cached result
367 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
368 set_process_info: pppp delivering specified messages
369 set_process_info: pppp delivering 10HmaY-0005vi-00
370 reading spool file 10HmaY-0005vi-00-H
371 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=x@y
372 sender_fullhost = [V4NET.11.12.13]
373 sender_rcvhost = [V4NET.11.12.13] (ident=CALLER)
374 sender_local=0 ident=CALLER
375 Non-recipients:
376 Empty Tree
377 ---- End of tree ----
378 recipients_count=1
379 body_linecount=1 message_linecount=7
380 Delivery address list:
381   2@b 
382 locking TESTSUITE/spool/db/retry.lockfile
383 locked TESTSUITE/spool/db/retry.lockfile
384 EXIM_DBOPEN(TESTSUITE/spool/db/retry)
385 returned from EXIM_DBOPEN
386 no retry data available
387 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
388 Considering: 2@b
389 unique = 2@b
390 no domain retry record
391 no address retry record
392 2@b: queued for routing
393 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
394 routing 2@b
395 --------> r1 router <--------
396 local_part=2 domain=b
397 calling r1 router
398 r1 router called for 2@b
399   domain = b
400 set transport t1
401 queued for t1 transport: local_part = 2
402 domain = b
403   errors_to=NULL
404   domain_data=NULL localpart_data=NULL
405 routed by r1 router
406   envelope to: 2@b
407   transport: t1
408 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
409 After routing:
410   Local deliveries:
411     2@b
412   Remote deliveries:
413   Failed addresses:
414   Deferred addresses:
415 search_tidyup called
416 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
417 --------> 2@b <--------
418 locking TESTSUITE/spool/db/retry.lockfile
419 locked TESTSUITE/spool/db/retry.lockfile
420 EXIM_DBOPEN(TESTSUITE/spool/db/retry)
421 returned from EXIM_DBOPEN
422 no retry data available
423 search_tidyup called
424 changed uid/gid: local delivery to 2 <2@b> transport=t1
425   uid=CALLER_UID gid=CALLER_GID pid=pppp
426   home=NULL current=/
427 set_process_info: pppp delivering 10HmaY-0005vi-00 to 2 using t1
428 appendfile transport entered
429 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
430   file=TESTSUITE/test-mail/2 format=unix
431   message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
432   message_suffix=\n
433   maildir_use_size_file=no
434   locking by lockfile fcntl 
435 lock name: TESTSUITE/test-mail/2.lock
436 hitch name: TESTSUITE/test-mail/2.lock.test.ex.dddddddd.pppppppp
437 lock file created
438 mailbox TESTSUITE/test-mail/2 is locked
439 writing to file TESTSUITE/test-mail/2
440 writing data block fd=dddd size=sss timeout=0
441 writing data block fd=dddd size=sss timeout=0
442 writing data block fd=dddd size=sss timeout=0
443 appendfile yields 0 with errno=dd more_errno=dd
444 search_tidyup called
445 journalling 2@b
446 t1 transport returned OK for 2@b
447 post-process 2@b (0)
448 2@b delivered
449 LOG: MAIN
450   => 2 <2@b> R=r1 T=t1
451 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
452 changed uid/gid: post-delivery tidying
453   uid=EXIM_UID gid=EXIM_GID pid=pppp
454 set_process_info: pppp tidying up after delivering 10HmaY-0005vi-00
455 Processing retry items
456 Succeeded addresses:
457 2@b: no retry items
458 Failed addresses:
459 Deferred addresses:
460 end of retry processing
461 LOG: MAIN
462   Completed
463 end delivery of 10HmaY-0005vi-00
464 search_tidyup called
465 search_tidyup called
466 >>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=0 >>>>>>>>>>>>>>>>
467 smtp_setup_msg entered
468 SMTP<< quit
469 SMTP>> 221 myhost.test.ex closing connection
470 LOG: smtp_connection MAIN
471   SMTP connection from CALLER closed by QUIT
472 search_tidyup called
473 >>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=0 >>>>>>>>>>>>>>>>