Re: [exim] Need more informations about remote_smtp defer ex…

Top Page
Delete this message
Reply to this message
Author: Simon
Date: 2019-01-08 09:55 -000
To: exim-users
Subject: Re: [exim] Need more informations about remote_smtp defer exim4 log
Yes sure,I'am sorry, I forgot to send you output with exim -d, here is
an example with an message in queue :

#exim -d -M 1ggnQv-00010z-Iu

Exim version 4.84_2 uid=0 gid=0 pid=8781 D=fbb95cfd
Berkeley DB: Berkeley DB 5.3.28: (September  9, 2013)
Support for: crypteq iconv() IPv6 PAM Perl Expand_dlfunc GnuTLS
move_frozen_messages Content_Scanning DKIM Old_Demime PRDR OCSP
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm
dbmjz dbmnz dnsdb dsearch ldap ldapdn ldapm mysql nis nis0 passwd pgsql
sqlite
Authenticators: cram_md5 cyrus_sasl dovecot plaintext spa
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram
redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
Size of off_t: 8
Compiler: GCC [4.9.2]
Library version: GnuTLS: Compile: 3.3.8
                         Runtime: 3.3.8
Library version: Cyrus SASL: Compile: 2.1.26
                             Runtime: 2.1.26 [Cyrus SASL]
Library version: PCRE: Compile: 8.35
                       Runtime: 8.35 2014-04-04
Total 19 lookups
Library version: MySQL: Compile: 5.5.59 [(Debian)]
                        Runtime: 5.5.59
Library version: SQLite: Compile: 3.8.7.1
                         Runtime: 3.8.7.1
WHITELIST_D_MACROS: "OUTGOING"
TRUSTED_CONFIG_LIST: "/etc/exim4/trusted_configs"
changed uid/gid: forcing real = effective
  uid=0 gid=0 pid=8781
  auxiliary group list: <none>
seeking password data for user "root": cache not available
getpwnam() succeeded uid=0 gid=0
changed uid/gid: calling tls_validate_require_cipher
  uid=105 gid=109 pid=8783
  auxiliary group list: <none>
tls_validate_require_cipher child 8783 ended: status=0x0
LOG: MAIN
  Warning: purging the environment.
 Suggested action: use keep_environment.
configuration file is /etc/exim4/exim4.conf
log selectors = 00000ffc 00232001
cwd=/root 4 args: exim -d -M 1ggnQv-00010z-Iu
trusted user
admin user
seeking password data for user "Debian-exim": cache not available
getpwnam() succeeded uid=105 gid=109
set_process_info:  8781 delivering specified messages
set_process_info:  8781 delivering 1ggnQv-00010z-Iu
reading spool file 1ggnQv-00010z-Iu-H
user=Debian-exim uid=105 gid=109 sender=sender_mail@???
sender_fullhost = 177-128-190-109.isp.overthebox.ovh (bureau2)
[109.190.128.177]
sender_rcvhost = 177-128-190-109.isp.overthebox.ovh ([109.190.128.177]
helo=bureau2)
sender_local=0 ident=unset
Non-recipients:
  -->application@??? [0]
-->/home/mails/mboxs/synaptik.fr/application/:application@??? [2]
---- End of tree ----
recipients_count=2
body_linecount=4727 message_linecount=20
Delivery address list:
  mail_to@???
locking /var/spool/exim4/db/retry.lockfile
locked /var/spool/exim4/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim4/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim4/db/retry: flags=O_RDONLY
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

Considering: mail_to@???
unique = mail_to@???
dbfn_read: key=R:orange.fr
dbfn_read: key=R:mail_to@???
dbfn_read: key=R:mail_to@???:<sender_mail@???>
no domain retry record
no address retry record
mail_to@???: queued for routing
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

routing mail_to@???
--------> system_aliases router <--------
local_part=valerie.wallrich domain=orange.fr
checking domains
orange.fr in "/home/mails/configs/domaines_master"? no (end of list)
orange.fr in "+local_domains"? no (end of list)
system_aliases router skipped: domains mismatch
--------> copy_out_mail router <--------
local_part=valerie.wallrich domain=orange.fr
calling copy_out_mail router
rda_interpret (string):
${extract{1}{:}{${lookup{${sender_address_domain}}lsearch{/home/mails/configs/backup_outgoing}{$value}fail}}}
search_open: lsearch "/home/mails/configs/backup_outgoing"
search_find: file="/home/mails/configs/backup_outgoing"
  key="poirot-construction.fr" partial=-1 affix=NULL starflags=0
LRU list:
  :/home/mails/configs/backup_outgoing
  End
internal_search_find: file="/home/mails/configs/backup_outgoing"
  type=lsearch key="poirot-construction.fr"
file lookup required for poirot-construction.fr
  in /home/mails/configs/backup_outgoing
lookup failed
copy_out_mail router declined for mail_to@???
--------> dnslookup_users router <--------
local_part=valerie.wallrich domain=orange.fr
checking domains
cached no match for +local_domains
cached lookup data = NULL
orange.fr in "! +local_domains"? yes (end of list)
checking "condition"
search_open: lsearch "/home/mails/configs/users"
search_find: file="/home/mails/configs/users"
  key="sender_mail@???" partial=-1 affix=NULL
starflags=0
LRU list:
  :/home/mails/configs/users
  :/home/mails/configs/backup_outgoing
  End
internal_search_find: file="/home/mails/configs/users"
  type=lsearch key="sender_mail@???"
file lookup required for sender_mail@???
  in /home/mails/configs/users
lookup yielded: rzQ/.InCTHVLc:Arnaud
JEANNOT:105:109:/home/mails/mboxs/poirot-construction.fr/arnaud/:2000M:y:n:y:y:1:n:::0:Y:0:0:0:1:Votre
conseiller Poirot Constructions Bois:0:0:1432:2:2:1:3
search_open: lsearch "/home/mails/configs/users"
  cached open
search_find: file="/home/mails/configs/users"
  key="sender_mail@???" partial=-1 affix=NULL
starflags=0
LRU list:
  :/home/mails/configs/users
  :/home/mails/configs/backup_outgoing
  End
internal_search_find: file="/home/mails/configs/users"
  type=lsearch key="sender_mail@???"
cached data used for lookup of sender_mail@???
  in /home/mails/configs/users
lookup yielded: rzQ/.InCTHVLc:Arnaud
JEANNOT:105:109:/home/mails/mboxs/poirot-construction.fr/arnaud/:2000M:y:n:y:y:1:n:::0:Y:0:0:0:1:Votre
conseiller Poirot Constructions Bois:0:0:1432:2:2:1:3
calling dnslookup_users router
dnslookup_users router called for mail_to@???
  domain = orange.fr
DNS lookup of orange.fr (MX) succeeded
DNS lookup of smtp-in.orange.fr (AAAA) gave NO_DATA
returning DNS_NODATA
DNS lookup of smtp-in.orange.fr (A) succeeded
80.12.242.9 in "0.0.0.0 : 127.0.0.0/8 : 176.31.234.153"? no (end of list)
193.252.22.65 in "0.0.0.0 : 127.0.0.0/8 : 176.31.234.153"? no (end of list)
fully qualified name = orange.fr
host_find_bydns yield = HOST_FOUND (2); returned hosts:
  smtp-in.orange.fr 80.12.242.9 MX=10
  smtp-in.orange.fr 193.252.22.65 MX=10
set transport remote_smtp
queued for remote_smtp transport: local_part = valerie.wallrich
domain = orange.fr
  errors_to=NULL
  domain_data=NULL localpart_data=NULL
routed by dnslookup_users router
  envelope to: mail_to@???
  transport: remote_smtp
  host smtp-in.orange.fr [80.12.242.9] MX=10
  host smtp-in.orange.fr [193.252.22.65] MX=10
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

After routing:
  Local deliveries:
  Remote deliveries:
    mail_to@???
  Failed addresses:
  Deferred addresses:
search_tidyup called
>>>>>>>>>>>>>>>> Remote deliveries >>>>>>>>>>>>>>>>

--------> mail_to@??? <--------
search_tidyup called
set_process_info:  8781 delivering 1ggnQv-00010z-Iu: waiting for a
remote delivery subprocess to finish
selecting on subprocess pipes
changed uid/gid: remote delivery to mail_to@??? with
transport=remote_smtp
  uid=105 gid=109 pid=8785
  auxiliary group list: <none>
set_process_info:  8785 delivering 1ggnQv-00010z-Iu using remote_smtp
remote_smtp transport entered
  mail_to@???
checking status of smtp-in.orange.fr
locking /var/spool/exim4/db/retry.lockfile
locked /var/spool/exim4/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim4/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim4/db/retry: flags=O_RDONLY
dbfn_read: key=T:smtp-in.orange.fr:80.12.242.9
dbfn_read: key=T:smtp-in.orange.fr:80.12.242.9:1ggnQv-00010z-Iu
no message retry record
smtp-in.orange.fr [80.12.242.9] status = usable
80.12.242.9 in serialize_hosts? no (option unset)
delivering 1ggnQv-00010z-Iu to smtp-in.orange.fr [80.12.242.9]
(mail_to@???)
set_process_info:  8785 delivering 1ggnQv-00010z-Iu to smtp-in.orange.fr
[80.12.242.9] (mail_to@???)
Connecting to smtp-in.orange.fr [80.12.242.9]:25 from 176.31.234.153 ...
unable to bind outgoing SMTP call to 176.31.234.153: Address already in
usefailed: Address already in use
LOG: MAIN
  smtp-in.orange.fr [80.12.242.9] Address already in use
set_process_info:  8785 delivering 1ggnQv-00010z-Iu: just tried
smtp-in.orange.fr [80.12.242.9] for mail_to@???: result DEFER
added retry item for T:smtp-in.orange.fr:80.12.242.9: errno=98
more_errno=0,M flags=2
address match test: subject=*@smtp-in.orange.fr pattern=*
smtp-in.orange.fr in "*"? yes (matched "*")
*@smtp-in.orange.fr in "*"? yes (matched "*")
checking status of smtp-in.orange.fr
locking /var/spool/exim4/db/retry.lockfile
locked /var/spool/exim4/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim4/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim4/db/retry: flags=O_RDONLY
dbfn_read: key=T:smtp-in.orange.fr:193.252.22.65
dbfn_read: key=T:smtp-in.orange.fr:193.252.22.65:1ggnQv-00010z-Iu
no message retry record
smtp-in.orange.fr [193.252.22.65] status = usable
193.252.22.65 in serialize_hosts? no (option unset)
delivering 1ggnQv-00010z-Iu to smtp-in.orange.fr [193.252.22.65]
(mail_to@???)
set_process_info:  8785 delivering 1ggnQv-00010z-Iu to smtp-in.orange.fr
[193.252.22.65] (mail_to@???)
Connecting to smtp-in.orange.fr [193.252.22.65]:25 from 176.31.234.153
... unable to bind outgoing SMTP call to 176.31.234.153: Address already
in usefailed: Address already in use
LOG: MAIN
  smtp-in.orange.fr [193.252.22.65] Address already in use
set_process_info:  8785 delivering 1ggnQv-00010z-Iu: just tried
smtp-in.orange.fr [193.252.22.65] for mail_to@???: result DEFER
added retry item for T:smtp-in.orange.fr:193.252.22.65: errno=98
more_errno=0,M flags=2
all IP addresses skipped or deferred at least one address
updating wait-remote_smtp database
locking /var/spool/exim4/db/wait-remote_smtp.lockfile
locked /var/spool/exim4/db/wait-remote_smtp.lockfile
EXIM_DBOPEN(/var/spool/exim4/db/wait-remote_smtp)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim4/db/wait-remote_smtp: flags=O_RDWR
dbfn_read: key=smtp-in.orange.fr
already listed for smtp-in.orange.fr
Leaving remote_smtp transport
set_process_info:  8785 delivering 1ggnQv-00010z-Iu (just run
remote_smtp for mail_to@??? in subprocess)
search_tidyup called
header write id:H,subid:0,size:14,final:H000014
reading pipe for subprocess 8785 (not ended)
read() yielded 21
header read id:H,subid:0,size:00014,required:21,remaining:21,unfinished:0
selecting on subprocess pipes
header write id:H,subid:0,size:16,final:H000016
reading pipe for subprocess 8785 (not ended)
read() yielded 23
header read id:H,subid:0,size:00016,required:23,remaining:23,unfinished:0
selecting on subprocess pipes
header write id:S,subid:0,size:4,final:S000004
reading pipe for subprocess 8785 (not ended)
read() yielded 11
header read id:S,subid:0,size:00004,required:11,remaining:11,unfinished:0
selecting on subprocess pipes
header write id:R,subid:0,size:44,final:R000044
reading pipe for subprocess 8785 (not ended)
read() yielded 51
header read id:R,subid:0,size:00044,required:51,remaining:51,unfinished:0
reading retry information for T:smtp-in.orange.fr:193.252.22.65 from
subprocess
  added retry item
selecting on subprocess pipes
header write id:R,subid:0,size:42,final:R000042
reading pipe for subprocess 8785 (not ended)
read() yielded 49
header read id:R,subid:0,size:00042,required:49,remaining:49,unfinished:0
reading retry information for T:smtp-in.orange.fr:80.12.242.9 from
subprocess
  added retry item
selecting on subprocess pipes
header write id:A,subid:0,size:15,final:A000015
reading pipe for subprocess 8785 (not ended)
read() yielded 22
header read id:A,subid:0,size:00015,required:22,remaining:22,unfinished:0
selecting on subprocess pipes
header write id:Z,subid:0,size:1,final:Z000001
reading pipe for subprocess 8785 (not ended)
read() yielded 8
header read id:Z,subid:0,size:00001,required:8,remaining:8,unfinished:0
Z00 item read
remote delivery process 8785 ended
set_process_info:  8781 delivering 1ggnQv-00010z-Iu
post-process mail_to@??? (1)
LOG: MAIN
  == mail_to@??? R=dnslookup_users T=remote_smtp defer (98):
Address already in use
>>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>

changed uid/gid: post-delivery tidying
  uid=105 gid=109 pid=8781
  auxiliary group list: <none>
set_process_info:  8781 tidying up after delivering 1ggnQv-00010z-Iu
Processing retry items
Succeeded addresses:
Failed addresses:
Deferred addresses:
mail_to@???
locking /var/spool/exim4/db/retry.lockfile
locked /var/spool/exim4/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim4/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim4/db/retry: flags=O_RDWR
address match test: subject=*@smtp-in.orange.fr pattern=*
smtp-in.orange.fr in "*"? yes (matched "*")
*@smtp-in.orange.fr in "*"? yes (matched "*")
retry for T:smtp-in.orange.fr:80.12.242.9 (orange.fr) = * 0 0
dbfn_read: key=T:smtp-in.orange.fr:80.12.242.9
failing_interval=11656 message_age=2040
Writing retry data for T:smtp-in.orange.fr:80.12.242.9
  first failed=1546929129 last try=1546940785 next try=1546944385 expired=0
  errno=98 more_errno=0,M Address already in use
dbfn_write: key=T:smtp-in.orange.fr:80.12.242.9
address match test: subject=*@smtp-in.orange.fr pattern=*
smtp-in.orange.fr in "*"? yes (matched "*")
*@smtp-in.orange.fr in "*"? yes (matched "*")
retry for T:smtp-in.orange.fr:193.252.22.65 (orange.fr) = * 0 0
dbfn_read: key=T:smtp-in.orange.fr:193.252.22.65
failing_interval=903 message_age=2040
Writing retry data for T:smtp-in.orange.fr:193.252.22.65
  first failed=1546939882 last try=1546940785 next try=1546941685 expired=0
  errno=98 more_errno=0,M Address already in use
dbfn_write: key=T:smtp-in.orange.fr:193.252.22.65
end of retry processing
time on queue = 34m
warning counts: required 0 done 0
delivery deferred: update_spool=0 header_rewritten=0
end delivery of 1ggnQv-00010z-Iu
search_tidyup called
search_tidyup called
>>>>>>>>>>>>>>>> Exim pid=8781 terminating with rc=0 >>>>>>>>>>>>>>>>


two interesting things in this log, first :
mail_to@??? R=dnslookup_users T=remote_smtp defer (98): Address
already in use
and second :
Connecting to smtp-in.orange.fr [80.12.242.9]:25 from 176.31.234.153 ...
unable to bind outgoing SMTP call to 176.31.234.153: Address already in
usefailed: Address already in use

And here is output with strace

#strace -e network -f exim -M 1ggnQv-00010z-Iu

socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
connect(4, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) =
-1 ENOENT (No such file or directory)
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
connect(4, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) =
-1 ENOENT (No such file or directory)
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
connect(4, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) =
-1 ENOENT (No such file or directory)
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
connect(4, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) =
-1 ENOENT (No such file or directory)
Process 16478 attached
[pid 16478] +++ exited with 0 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=16478,
si_uid=105, si_status=0, si_utime=0, si_stime=0} ---
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 9
connect(9, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("127.0.0.1")}, 16) = 0
sendto(9, "\r\204\1\0\0\1\0\0\0\0\0\0\6orange\2fr\0\0\17\0\1", 27,
MSG_NOSIGNAL, NULL, 0) = 27
recvfrom(9,
"\r\204\201\200\0\1\0\1\0\2\0\4\6orange\2fr\0\0\17\0\1\300\f\0\17\0"...,
2048, 0, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 175
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 9
connect(9, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("127.0.0.1")}, 16) = 0
sendto(9, "\25>\1\0\0\1\0\0\0\0\0\0\7smtp-in\6orange\2fr\0\0"..., 35,
MSG_NOSIGNAL, NULL, 0) = 35
recvfrom(9, "\25>\201\200\0\1\0\0\0\1\0\0\7smtp-in\6orange\2fr\0\0"...,
2048, 0, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 86
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 9
connect(9, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("127.0.0.1")}, 16) = 0
sendto(9, "a\235\1\0\0\1\0\0\0\0\0\0\7smtp-in\6orange\2fr\0\0"..., 35,
MSG_NOSIGNAL, NULL, 0) = 35
recvfrom(9, "a\235\201\200\0\1\0\2\0\2\0\2\7smtp-in\6orange\2fr\0\0"...,
2048, 0, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 159
Process 16479 attached
[pid 16479] socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 8
[pid 16479] connect(8, {sa_family=AF_LOCAL,
sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or
directory)
[pid 16479] socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 8
[pid 16479] connect(8, {sa_family=AF_LOCAL,
sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or
directory)
[pid 16479] socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 8
[pid 16479] setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
[pid 16479] bind(8, {sa_family=AF_INET, sin_port=htons(0),
sin_addr=inet_addr("176.31.234.153")}, 16) = -1 EADDRINUSE (Address
already in use)
[pid 16479] socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 8
[pid 16479] setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
[pid 16479] bind(8, {sa_family=AF_INET, sin_port=htons(0),
sin_addr=inet_addr("176.31.234.153")}, 16) = -1 EADDRINUSE (Address
already in use)
[pid 16479] +++ exited with 0 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=16479,
si_uid=105, si_status=0, si_utime=0, si_stime=1} ---
+++ exited with 0 +++


Le 07/01/2019 à 17:12, Evgeniy Berdnikov via Exim-users a écrit :
> On Mon, Jan 07, 2019 at 09:17:28AM +0100, Simon via Exim-users wrote:
>> When I try to send message with this command *exim -d -M <exim-message-id>
>> *sometimes message sent and sometimes I have again *remote_smtp defer
>> (98).*||||
> If you run exim with "-d", there may be some relevant information,
> but you did not post it.
>
> What "strace -e network -f exim -M <exim-message-id>" shows on error?