Testsuite: output changes resulting
[exim.git] / test / stderr / 0551
1 14:07:56 7857 Exim version x.yz uid=CALLER_UID gid=CALLER_GID pid=pppp D=fffdffff
2 14:07:56 7857 Total 20 lookups
3 14:07:56 7857 changed uid/gid: forcing real = effective
4 14:07:56 7857 uid=uuuu gid=CALLER_GID pid=pppp
5 14:07:56.452 7857 configuration file is TESTSUITE/test-config
6 14:07:56.452 7857 log selectors = 00000ffc 0c64c60a
7 14:07:56.452 7857 cwd=TESTSUITE 8 args: TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -C TESTSUITE/test-config -d+all -DLOG_SELECTOR=+queue_time+queue_time_overall+deliver_time+millisec -odi userx@test.ex
8 14:07:56.452 7857 admin user
9 14:07:56.453 7857 changed uid/gid: privilege not needed
10 14:07:56.453 7857 uid=EXIM_UID gid=EXIM_GID pid=pppp
11 14:07:56.453 7857 DSN: r1 propagating DSN
12 14:07:56.453 7857 seeking password data for user "CALLER": cache not available
13 14:07:56.453 7857 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
14 14:07:56.453 7857 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
15 14:07:56.453 7857 sender address = CALLER@myhost.test.ex
16 14:07:56.453 7857 set_process_info: pppp accepting a local non-SMTP message from <CALLER@myhost.test.ex>
17 14:07:56.453 7857 spool directory space = 157852648K inodes = 26802407 check_space = 10240K inodes = 100 msg_size = 0
18 14:07:56.453 7857 log directory space = 157852648K inodes = 26802407 check_space = 10240K inodes = 100
19 14:07:56.453 7857 Sender: CALLER@myhost.test.ex
20 14:07:56.453 7857 Recipients:
21 14:07:56.453 7857 userx@test.ex
22 14:07:56.453 7857 search_tidyup called
23 14:07:56.453 7857 >>Headers received:
24 14:07:56.453 7857
25 14:07:56.453 7857 rewrite_one_header: type=F:
26 14:07:56.453 7857 From: CALLER_NAME <CALLER@myhost.test.ex>
27 14:07:56.453 7857 search_tidyup called
28 14:07:56.453 7857 >>Headers after rewriting and local additions:
29 14:07:56.453 7857 I Message-Id: <E10HmaZ-0005vi-00@myhost.test.ex>
30 14:07:56.453 7857 F From: CALLER_NAME <CALLER@myhost.test.ex>
31 14:07:56.453 7857 Date: Tue, 2 Mar 1999 09:44:33 +0000
32 14:07:56.453 7857
33 14:07:56.453 7857 Data file name: TESTSUITE/spool//input//10HmaZ-0005vi-00-D
34 14:07:56.455 7857 Data file written for message 10HmaZ-0005vi-00
35 14:07:56.455 7857 ┌considering: ${tod_full}
36 14:07:56.455 7857 ├──expanding: ${tod_full}
37 14:07:56.455 7857 └─────result: Tue, 2 Mar 1999 09:44:33 +0000
38 14:07:56.455 7857 ┌considering: Received: ${if def:sender_rcvhost {from $sender_rcvhost
39 14:07:56.455 7857 }{${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
40 14:07:56.455 7857 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857}} (Exim $version_number)
41 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
42 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
43 14:07:56.455 7857 for $received_for}}
44 14:07:56.455 7857 ├──condition: def:sender_rcvhost
45 14:07:56.455 7857 ├─────result: false
46 14:07:56.455 7857 ┌───scanning: from $sender_rcvhost
47 14:07:56.455 7857 }{${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
48 14:07:56.455 7857 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857}} (Exim $version_number)
49 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
50 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
51 14:07:56.455 7857 for $received_for}}
52 14:07:56.455 7857 ├──expanding: from $sender_rcvhost
53 14:07:56.455 7857
54 14:07:56.455 7857 ├─────result: from
55 14:07:56.455 7857
56 14:07:56.455 7857 └───skipping: result is not used
57 14:07:56.455 7857 ┌considering: ${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
58 14:07:56.455 7857 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857}} (Exim $version_number)
59 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
60 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
61 14:07:56.455 7857 for $received_for}}
62 14:07:56.455 7857 ├──condition: def:sender_ident
63 14:07:56.455 7857 ├─────result: true
64 14:07:56.455 7857 ┌considering: from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
65 14:07:56.455 7857 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857}} (Exim $version_number)
66 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
67 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
68 14:07:56.455 7857 for $received_for}}
69 14:07:56.455 7857 ╎┌considering: $sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
70 14:07:56.455 7857 ╎ }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857 ╎}} (Exim $version_number)
71 14:07:56.455 7857 ╎ ${if def:sender_address {(envelope-from <$sender_address>)
72 14:07:56.455 7857 ╎ }}id $message_exim_id${if def:received_for {
73 14:07:56.455 7857 ╎ for $received_for}}
74 14:07:56.455 7857 ╎├──expanding: $sender_ident
75 14:07:56.455 7857 ╎└─────result: CALLER
76 14:07:56.455 7857 ├──expanding: from ${quote_local_part:$sender_ident}
77 14:07:56.455 7857 └─────result: from CALLER
78 14:07:56.455 7857 ├──condition: def:sender_helo_name
79 14:07:56.455 7857 ├─────result: false
80 14:07:56.455 7857 ┌───scanning: (helo=$sender_helo_name)
81 14:07:56.455 7857 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857}} (Exim $version_number)
82 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
83 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
84 14:07:56.455 7857 for $received_for}}
85 14:07:56.455 7857 ├──expanding: (helo=$sender_helo_name)
86 14:07:56.455 7857
87 14:07:56.455 7857 ├─────result: (helo=)
88 14:07:56.455 7857
89 14:07:56.455 7857 └───skipping: result is not used
90 14:07:56.455 7857 ├──expanding: ${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
91 14:07:56.455 7857 }}
92 14:07:56.455 7857 └─────result: from CALLER
93 14:07:56.455 7857 ├──condition: def:received_protocol
94 14:07:56.455 7857 ├─────result: true
95 14:07:56.455 7857 ┌considering: with $received_protocol14:07:56.455 7857}} (Exim $version_number)
96 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
97 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
98 14:07:56.455 7857 for $received_for}}
99 14:07:56.455 7857 ├──expanding: with $received_protocol
100 14:07:56.455 7857 └─────result: with local
101 14:07:56.455 7857 ├──condition: def:tls_cipher
102 14:07:56.455 7857 ├─────result: false
103 14:07:56.455 7857 ┌───scanning: ($tls_cipher)
104 14:07:56.455 7857 }}(Exim $version_number)
105 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
106 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
107 14:07:56.455 7857 for $received_for}}
108 14:07:56.455 7857 ├──expanding: ($tls_cipher)
109 14:07:56.455 7857
110 14:07:56.455 7857 ├─────result: ()
111 14:07:56.455 7857
112 14:07:56.455 7857 └───skipping: result is not used
113 14:07:56.455 7857 ├──condition: def:sender_address
114 14:07:56.455 7857 ├─────result: true
115 14:07:56.455 7857 ┌considering: (envelope-from <$sender_address>)
116 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
117 14:07:56.455 7857 for $received_for}}
118 14:07:56.455 7857 ├──expanding: (envelope-from <$sender_address>)
119 14:07:56.455 7857
120 14:07:56.455 7857 └─────result: (envelope-from <CALLER@myhost.test.ex>)
121 14:07:56.455 7857
122 14:07:56.455 7857 ├──condition: def:received_for
123 14:07:56.455 7857 ├─────result: true
124 14:07:56.455 7857 ┌considering:
125 14:07:56.455 7857 for $received_for}}
126 14:07:56.455 7857 ├──expanding:
127 14:07:56.455 7857 for $received_for
128 14:07:56.455 7857 └─────result:
129 14:07:56.455 7857 for userx@test.ex
130 14:07:56.455 7857 ├──expanding: Received: ${if def:sender_rcvhost {from $sender_rcvhost
131 14:07:56.455 7857 }{${if def:sender_ident {from ${quote_local_part:$sender_ident} }}${if def:sender_helo_name {(helo=$sender_helo_name)
132 14:07:56.455 7857 }}}}by $primary_hostname ${if def:received_protocol {with $received_protocol14:07:56.455 7857}} (Exim $version_number)
133 14:07:56.455 7857 ${if def:sender_address {(envelope-from <$sender_address>)
134 14:07:56.455 7857 }}id $message_exim_id${if def:received_for {
135 14:07:56.455 7857 for $received_for}}
136 14:07:56.455 7857 └─────result: Received: from CALLER by myhost.test.ex with local (Exim x.yz)
137 14:07:56.455 7857 (envelope-from <CALLER@myhost.test.ex>)
138 14:07:56.455 7857 id 10HmaZ-0005vi-00
139 14:07:56.455 7857 for userx@test.ex
140 14:07:56.455 7857 >>Generated Received: header line
141 14:07:56.455 7857 P Received: from CALLER by myhost.test.ex with local (Exim x.yz)
142 14:07:56.455 7857 (envelope-from <CALLER@myhost.test.ex>)
143 14:07:56.455 7857 id 10HmaZ-0005vi-00
144 14:07:56.455 7857 for userx@test.ex; Tue, 2 Mar 1999 09:44:33 +0000
145 14:07:56.455 7857 calling local_scan(); timeout=300
146 14:07:56.455 7857 local_scan() returned 0 NULL
147 14:07:56.455 7857 ┌considering: ${tod_full}
148 14:07:56.455 7857 ├──expanding: ${tod_full}
149 14:07:56.455 7857 └─────result: Tue, 2 Mar 1999 09:44:33 +0000
150 14:07:56.455 7857 Writing spool header file: TESTSUITE/spool//input//hdr.7857
151 14:07:56.455 7857 DSN: Write SPOOL :-dsn_envid NULL
152 14:07:56.455 7857 DSN: Write SPOOL :-dsn_ret 0
153 14:07:56.455 7857 DSN: Flags :0
154 14:07:56.455 7857 DSN: **** SPOOL_OUT - address: |userx@test.ex| errorsto: |NULL| orcpt: |NULL| dsn_flags: 0
155 14:07:56.457 7857 Renaming spool header file: TESTSUITE/spool//input//10HmaZ-0005vi-00-H
156 14:07:56.459 7857 Size of headers = sss
157 14:07:56.459 7857 LOG: MAIN
158 14:07:56.459 7857 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
159 14:07:56.459 7857 search_tidyup called
160 14:07:56.459 7858 exec TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -DLOG_SELECTOR=+queue_time+queue_time_overall+deliver_time+millisec -C TESTSUITE/test-config -d=0xfffdffff -odi -Mc 10HmaZ-0005vi-00
161 14:07:56 7858 Exim version x.yz uid=EXIM_UID gid=EXIM_GID pid=pppp D=fffdffff
162 14:07:56 7858 Total 20 lookups
163 14:07:56 7858 changed uid/gid: forcing real = effective
164 14:07:56 7858 uid=uuuu gid=EXIM_GID pid=pppp
165 14:07:56.565 7858 configuration file is TESTSUITE/test-config
166 14:07:56.565 7858 log selectors = 00000ffc 0c64c60a
167 14:07:56.565 7858 cwd=TESTSUITE/spool 9 args: TESTSUITE/eximdir/exim -DEXIM_PATH=TESTSUITE/eximdir/exim -DLOG_SELECTOR=+queue_time+queue_time_overall+deliver_time+millisec -C TESTSUITE/test-config -d=0xfffdffff -odi -Mc 10HmaZ-0005vi-00
168 14:07:56.565 7858 trusted user
169 14:07:56.565 7858 admin user
170 14:07:56.565 7858 DSN: r1 propagating DSN
171 14:07:56.565 7858 seeking password data for user "CALLER": cache not available
172 14:07:56.565 7858 getpwnam() succeeded uid=CALLER_UID gid=CALLER_GID
173 14:07:56.565 7858 set_process_info: pppp delivering specified messages
174 14:07:56.565 7858 set_process_info: pppp delivering 10HmaZ-0005vi-00
175 14:07:56.565 7858 Trying spool file TESTSUITE/spool//input//10HmaZ-0005vi-00-D
176 14:07:56.565 7858 reading spool file 10HmaZ-0005vi-00-H
177 14:07:56.565 7858 user=CALLER uid=CALLER_UID gid=CALLER_GID sender=CALLER@myhost.test.ex
178 14:07:56.565 7858 sender_local=1 ident=CALLER
179 14:07:56.565 7858 Non-recipients:
180 14:07:56.565 7858 Empty Tree
181 14:07:56.565 7858 ---- End of tree ----
182 14:07:56.565 7858 recipients_count=1
183 14:07:56.565 7858 **** SPOOL_IN - No additional fields
184 14:07:56.565 7858 body_linecount=1 message_linecount=7
185 14:07:56.565 7858 DSN: set orcpt: NULL flags: 0
186 14:07:56.565 7858 Delivery address list:
187 14:07:56.565 7858 userx@test.ex
188 14:07:56.566 7858 locking TESTSUITE/spool/db/retry.lockfile
189 14:07:56.566 7858 locked TESTSUITE/spool/db/retry.lockfile
190 14:07:56.566 7858 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags 0x0
191 14:07:56.566 7858 returned from EXIM_DBOPEN: (nil)
192 14:07:56.566 7858 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
193 14:07:56.566 7858 no retry data available
194 14:07:56.566 7858 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
195 14:07:56.566 7858 Considering: userx@test.ex
196 14:07:56.566 7858 unique = userx@test.ex
197 14:07:56.566 7858 no domain retry record
198 14:07:56.566 7858 no address retry record
199 14:07:56.566 7858 userx@test.ex: queued for routing
200 14:07:56.566 7858 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
201 14:07:56.566 7858 routing userx@test.ex
202 14:07:56.566 7858 --------> r1 router <--------
203 14:07:56.566 7858 local_part=userx domain=test.ex
204 14:07:56.566 7858 calling r1 router
205 14:07:56.566 7858 r1 router called for userx@test.ex
206 14:07:56.566 7858 domain = test.ex
207 14:07:56.566 7858 set transport t1
208 14:07:56.566 7858 queued for t1 transport: local_part = userx
209 14:07:56.566 7858 domain = test.ex
210 14:07:56.566 7858 errors_to=NULL
211 14:07:56.566 7858 domain_data=NULL localpart_data=NULL
212 14:07:56.566 7858 routed by r1 router
213 14:07:56.566 7858 envelope to: userx@test.ex
214 14:07:56.566 7858 transport: t1
215 14:07:56.566 7858 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
216 14:07:56.566 7858 After routing:
217 14:07:56.566 7858 Local deliveries:
218 14:07:56.566 7858 userx@test.ex
219 14:07:56.566 7858 Remote deliveries:
220 14:07:56.566 7858 Failed addresses:
221 14:07:56.566 7858 Deferred addresses:
222 14:07:56.566 7858 search_tidyup called
223 14:07:56.566 7858 >>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
224 14:07:56.566 7858 --------> userx@test.ex <--------
225 14:07:56.566 7858 locking TESTSUITE/spool/db/retry.lockfile
226 14:07:56.566 7858 locked TESTSUITE/spool/db/retry.lockfile
227 14:07:56.566 7858 EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags 0x0
228 14:07:56.566 7858 returned from EXIM_DBOPEN: (nil)
229 14:07:56.566 7858 failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
230 14:07:56.566 7858 no retry data available
231 14:07:56.566 7858 search_tidyup called
232 14:07:56.566 7859 changed uid/gid: local delivery to userx <userx@test.ex> transport=t1
233 14:07:56.566 7859 uid=CALLER_UID gid=CALLER_GID pid=pppp
234 14:07:56.566 7859 home=NULL current=/
235 14:07:56.566 7859 set_process_info: pppp delivering 10HmaZ-0005vi-00 to userx using t1
236 14:07:56.566 7859 appendfile transport entered
237 14:07:56.566 7859 ┌considering: TESTSUITE/test-mail/$local_part
238 14:07:56.566 7859 ├──expanding: TESTSUITE/test-mail/$local_part
239 14:07:56.566 7859 └─────result: TESTSUITE/test-mail/userx
240 14:07:56.566 7859 appendfile: mode=600 notify_comsat=0 quota=0 warning=0
241 14:07:56.566 7859 file=TESTSUITE/test-mail/userx format=unix
242 14:07:56.566 7859 message_prefix=From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}\n
243 14:07:56.566 7859 message_suffix=\n
244 14:07:56.566 7859 maildir_use_size_file=no
245 14:07:56.566 7859 locking by lockfile fcntl
246 14:07:56.566 7859 lock name: TESTSUITE/test-mail/userx.lock
247 14:07:56.566 7859 hitch name: TESTSUITE/test-mail/userx.lock.test.ex.dddddddd.pppppppp
248 14:07:56.566 7859 lock file created
249 14:07:56.566 7859 mailbox TESTSUITE/test-mail/userx is locked
250 14:07:56.566 7859 writing to file TESTSUITE/test-mail/userx
251 14:07:56.566 7859 ┌considering: From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}
252 14:07:56.566 7859
253 14:07:56.566 7859 ├──condition: def:return_path
254 14:07:56.566 7859 ├─────result: true
255 14:07:56.566 7859 ┌considering: $return_path}{MAILER-DAEMON}} ${tod_bsdinbox}
256 14:07:56.566 7859
257 14:07:56.566 7859 ├──expanding: $return_path
258 14:07:56.566 7859 └─────result: CALLER@myhost.test.ex
259 14:07:56.566 7859 ┌───scanning: MAILER-DAEMON}} ${tod_bsdinbox}
260 14:07:56.566 7859
261 14:07:56.566 7859 ├──expanding: MAILER-DAEMON
262 14:07:56.566 7859 ├─────result: MAILER-DAEMON
263 14:07:56.566 7859 └───skipping: result is not used
264 14:07:56.566 7859 ├──expanding: From ${if def:return_path{$return_path}{MAILER-DAEMON}} ${tod_bsdinbox}
265 14:07:56.566 7859
266 14:07:56.566 7859 └─────result: From CALLER@myhost.test.ex Tue Mar 02 09:44:33 1999
267 14:07:56.566 7859
268 14:07:56.566 7859 writing data block fd=6 size=sss timeout=0
269 14:07:56.567 7859 cannot use sendfile for body: spoolfile not wireformat
270 14:07:56.567 7859 writing data block fd=6 size=sss timeout=0
271 14:07:56.567 7859 writing data block fd=6 size=sss timeout=0
272 14:07:56.568 7859 appendfile yields 0 with errno=dd more_errno=dd
273 14:07:56.568 7859 search_tidyup called
274 14:07:56.868 7858 journalling userx@test.ex
275 14:07:56.871 7858 t1 transport returned OK for userx@test.ex
276 14:07:56.871 7858 post-process userx@test.ex (0)
277 14:07:56.871 7858 userx@test.ex delivered
278 14:07:56.871 7858 LOG: MAIN
279 14:07:56.871 7858 => userx <userx@test.ex> R=r1 T=t1 QT=q.qqqs DT=q.qqqs
280 14:07:56.871 7858 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
281 14:07:56.871 7858 changed uid/gid: post-delivery tidying
282 14:07:56.871 7858 uid=EXIM_UID gid=EXIM_GID pid=pppp
283 14:07:56.871 7858 set_process_info: pppp tidying up after delivering 10HmaZ-0005vi-00
284 14:07:56.871 7858 Processing retry items
285 14:07:56.871 7858 Succeeded addresses:
286 14:07:56.871 7858 userx@test.ex: no retry items
287 14:07:56.871 7858 Failed addresses:
288 14:07:56.871 7858 Deferred addresses:
289 14:07:56.871 7858 end of retry processing
290 14:07:56.871 7858 DSN: processing router : r1
291 14:07:56.871 7858 DSN: processing successful delivery address: userx@test.ex
292 14:07:56.871 7858 DSN: Sender_address: CALLER@myhost.test.ex
293 14:07:56.871 7858 DSN: orcpt: NULL flags: 0
294 14:07:56.871 7858 DSN: envid: NULL ret: 0
295 14:07:56.871 7858 DSN: Final recipient: userx@test.ex
296 14:07:56.871 7858 DSN: Remote SMTP server supports DSN: 0
297 14:07:56.871 7858 DSN: not sending DSN success message
298 14:07:56.871 7858 LOG: MAIN
299 14:07:56.871 7858 Completed QT=q.qqqs
300 14:07:56.871 7858 end delivery of 10HmaZ-0005vi-00
301 14:07:56.871 7858 search_tidyup called
302 14:07:56.871 7858 search_tidyup called
303 14:07:56.871 7858 >>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=0 >>>>>>>>>>>>>>>>
304 14:07:56.871 7857 search_tidyup called
305 14:07:56.871 7857 >>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=0 >>>>>>>>>>>>>>>>