e-mails delays exactly 4 minutes to be sent
Hello.... since last week, e-mails are delaying to be sent. Curiously, the time elapsed is exactly 4 minutes.
Can someone help me to solve the problem?
This is the header of one of those e-mails:
Thanks Jaime
Delivered-To: jstuardo@example.com
Received: by 2002:adf:f8ca:0:0:0:0:0 with SMTP id f10-v6csp3145145wrq;
Thu, 11 Oct 2018 13:40:13 -0700 (PDT)
X-Received: by 2002:a62:7f8c:: with SMTP id a134-v6mr2991755pfd.257.1539290173495;
Thu, 11 Oct 2018 13:36:13 -0700 (PDT)
X-Google-Smtp-Source: ACcGV62gcYInESROSxqJitVFaLzzJFtjt9XKKHlLit3Xwm0USU1kGqLpk7O3XIvzLLZdScUDXPQo
X-Received: by 2002:a62:7f8c:: with SMTP id a134-v6mr2991728pfd.257.1539290172884;
Thu, 11 Oct 2018 13:36:12 -0700 (PDT)
ARC-Seal: i=1; a=rsa-sha256; t=1539290172; cv=none;
d=google.com; s=arc-20160816;
b=lwwI4L/kFRijU2JoVgKHD8Ulu5f7AECHLm40rqYvIo4Q4n65QfQdM479SaEVq6XSS8
CAYEMTX3pdbycFj9QBO+ihnok+Nb8loKwRS2M8QC/c53lrW5zFmGq4p76fDqfHtME1RT
Rt4lFUbjljZCI5tgN9bsEkbNsE0NVxaOv5ARRlY9u4sRG5NNapODKdT+8SF0Prgv4VHU
nTKnHbpd/OwaiLUWxSNpt9vZ01x1lUiGnIFycjLDN5v+8hqmV0IoKFWEfx91wNN+xbAJ
Cfm+rxtfETfbjL3601TtNzaDuOQN6v2cQYElNpSrv+UCobfryM04IRWSPh7KVFggJ4qr
4GKQ==
ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816;
h=mime-version:priority:date:subject:to:from:dkim-signature
:message-id;
bh=tRprQRKCwbFnK5jTo9KBvw9yftN5C62LA8HTrgi5n4Q=;
b=ySYmWSio86g9FXF3eOJ0gCbLJY/iad1w3zGT3/CgocczsuO07nm+cgYkLTuuyf7h6o
WgojrAKeeiI6bPtc//TfqsVwsUip5rMrW9roTco4hl0cBHIcflQiBUGR2DrnVJ+uR1gt
NzIa3eKdPt1LFz+tb9Kt6gn72ahIxgkAl7okESWFjzWG+kEpXzQ6UuB/tiQB3JzoFHSh
yTrmus7sD0l/TD15mOCSs+p3NOVHK5KWb5TpkgfGeq/KR26ayEWZAiVJUrfNz3DEJO0c
HRS2ppBggSe49lvtM01ZujdDbg182VDa2yESGhLirPMMDllWir4C/8KiQnttszkvqa5l
gHsw==
ARC-Authentication-Results: i=1; mx.google.com;
dkim=pass header.i=@example.cl header.s=default header.b=Umm9WWX2;
spf=pass (google.com: domain of lean@example.cl designates 50.116.xx.xxx as permitted sender) smtp.mailfrom=lean@example.cl
Return-Path:
Received: from server.example.com (server.example.com. [50.116.xx.xxx])
by mx.google.com with ESMTPS id f9-v6si27984629pgk.594.2018.10.11.13.36.12
for
(version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128);
Thu, 11 Oct 2018 13:36:12 -0700 (PDT)
Received-SPF: pass (google.com: domain of lean@example.cl designates 50.116.xx.xxx as permitted sender) client-ip=50.116.xx.xxx;
Authentication-Results: mx.google.com;
dkim=pass header.i=@example.cl header.s=default header.b=Umm9WWX2;
spf=pass (google.com: domain of lean@example.cl designates 50.116.xx.xxx as permitted sender) smtp.mailfrom=lean@example.cl
Message-Id: <5bbfb43c.1c69fb81.76a89.4988SMTPIN_ADDED_MISSING@mx.google.com>
DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=example.cl;
s=default; h=Content-Type:MIME-Version:Date:Subject:To:From:Sender:Reply-To:
Message-ID:Cc:Content-Transfer-Encoding:Content-ID:Content-Description:
Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID:
In-Reply-To:References:List-Id:List-Help:List-Unsubscribe:List-Subscribe:
List-Post:List-Owner:List-Archive;
bh=tRprQRKCwbFnK5jTo9KBvw9yftN5C62LA8HTrgi5n4Q=; b=Umm9WWX2vGv8s/ZddvAgQxQ1cR
m3NAnyNGzsnORYRdD9VDxOEbMs/GoBEI2pX+uIG6jioMivOmvPm4x4LyoC+sh+htphCYp5UVW2Iif
6f8gF+1LiEvE0mgqzn8thHhqI4twyouhL2jBTf5i2k6u+kUlc4luFZK34PBB2NBworEkB9NBtuvPc
pPXDV3SN7ULADPzqTI80jORaI82izSqcCvVrXD/4rakpz0U/6trcvD7cqQndxOSVcNkCuVu3WqGz9
lr5HqUmqzCgWcr7lUQJhvYJaz5tJoTvrau0/lVLUe/Nt5uNYnPbrNalvpies5xocqW2FJOQ7jdccI
vRApR9XQ==;
Received: from [191.126.xxx.xx] (port=47297 helo=someusr)
by server.example.com with esmtpa (Exim 4.91)
(envelope-from )
id 1gAhgo-0007Ra-1T
for inventarios_lean@example.cl; Thu, 11 Oct 2018 17:36:10 -0300
From: lean@example.cl
To: inventarios_lean@example.cl
Subject: some subject
Date: Fri, 12 Oct 2018 8:35 UT
Priority: Normal
MIME-Version: 1.0
X-Mailer: CSLMail.SMTP
Content-Type: multipart/mixed; boundary="cb4215cf-c296-403b-ac7a-f5a0cd9b761d"
X-AntiAbuse: This header was added to track abuse, please include it with any abuse report
X-AntiAbuse: Primary Hostname - server.example.com
X-AntiAbuse: Original Domain - example.cl
X-AntiAbuse: Originator/Caller UID/GID - [47 12] / [47 12]
X-AntiAbuse: Sender Address Domain - example.cl
X-Get-Message-Sender-Via: server.example.com: authenticated_id: lean@example.cl
X-Authenticated-Sender: server.example.com: lean@example.cl
X-Source:
X-Source-Args:
X-Source-Dir:
X-EsetId: 37303A2925460163657767
Thanks Jaime
-
HI @desytec Based on your profile I assume you have root access. If you could please when you send a mail check the following log files for information: /var/log/exim_mainlog /var/log/maillog
The entire mail transaction should be present in the mainlog and may be helpful in determining why it's taking so much time. Also seeing how much mail is in the queue may be helpful as well:exim -bpc
Thanks!0 -
HI @example Based on your profile I assume you have root access. If you could please when you send a mail check the following log files for information:
/var/log/exim_mainlog /var/log/maillog
The entire mail transaction should be present in the mainlog and may be helpful in determining why it's taking so much time. Also seeing how much mail is in the queue may be helpful as well:exim -bpc
Thanks!
Hello, thanks for your reply. This is the part of "exim_mainlog" concerning a message that delayed to be sent:2018-10-12 09:26:29 SMTP connection from [127.0.0.1]:58676 (TCP/IP connection count = 1) 2018-10-12 09:26:29 SMTP connection from (localhost) [127.0.0.1]:58676 closed by QUIT 2018-10-12 09:26:41 SMTP connection from [45.232.32.216]:3591 (TCP/IP connection count = 1) 2018-10-12 09:26:41 no host name found for IP address 45.232.32.216 2018-10-12 09:26:48 1gAwWk-0007Zy-J1 <= lean@example.cl H=(SkorpioX3) [45.232.32.216]:3591 P=esmtpa A=dovecot_login:lean@example.cl S=3810 T="Achivo generado por JASM?N TRINCADO en la tienda ALTO LAS CONDES con$ 2018-10-12 09:26:48 cwd=/var/spool/exim 3 args: /usr/sbin/exim -Mc 1gAwWk-0007Zy-J1 2018-10-12 09:26:48 1gAwWk-0007Zy-J1 Sender identification U=example1 D=example.cl S=lean@example.cl 2018-10-12 09:26:48 1gAwWk-0007Zy-J1 SMTP connection outbound 1539347208 1gAwWk-0007Zy-J1 example.cl jvasquez@example2.cl 2018-10-12 09:26:49 SMTP connection from (SkorpioX3) [45.232.32.216]:3591 closed by QUIT 2018-10-12 09:26:49 1gAwWk-0007Zy-J1 Sender identification U=example1 D=example.cl S=lean@example.cl 2018-10-12 09:26:49 1gAwWk-0007Zy-J1 SMTP connection outbound 1539347209 1gAwWk-0007Zy-J1 example.cl jstuardo@example.com 2018-10-12 09:26:50 1gAwWk-0007Zy-J1 Sender identification U=example1 D=example.cl S=lean@example.cl 2018-10-12 09:26:50 1gAwWk-0007Zy-J1 SMTP connection outbound 1539347210 1gAwWk-0007Zy-J1 example.cl avasquez@example2.cl 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 => jvasquez@example2.cl (inventarios_lean@example.cl) R=dkim_lookuphost T=dkim_remote_smtp H=aspmx.l.google.com [74.125.135.26] X=TLSv1.2:ECDHE-$ 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 => avasquez@example2.cl (inventarios_lean@example.cl) R=dkim_lookuphost T=dkim_remote_smtp H=aspmx.l.google.com [74.125.142.27] X=TLSv1.2:ECDHE-$ 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 => jstuardo@example.com (inventarios_lean@example.cl) R=dkim_lookuphost T=dkim_remote_smtp H=aspmx.l.google.com [74.125.135.26] X=TLSv1.2:ECDHE$ 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 Completed 2018-10-12 09:30:03 cwd=/home/example1 9 args: /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t -f root 2018-10-12 09:30:03 1gAwZv-0007bW-9L <= root@server.example.com U=example1 P=local S=756 T="Cron /usr/bin/php /home/example1/public_html/support/api/cron.php" for example1 2018-10-12 09:30:03 cwd=/var/spool/exim 4 args: /usr/sbin/exim -odi -Mc 1gAwZv-0007bW-9L 2018-10-12 09:30:04 1gAwZv-0007bW-9L => example1 R=localuser T=dovecot_delivery C="250 2.0.0 sIJFI8uTwFs5cgAADB7UoA Saved" 2018-10-12 09:30:04 1gAwZv-0007bW-9L Completed
This is the "maillog" result around the time where the delayed mail occured:Oct 12 09:26:04 server dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=29086, secured, session= Oct 12 09:26:04 server dovecot: imap(dummy@example.cl): Logged out in=120, out=1240, bytes=120/1240 Oct 12 09:26:08 server dovecot: imap(sleig@example.cl): Logged out in=324, out=1279, bytes=324/1279 Oct 12 09:26:08 server dovecot: imap(sleig@example.cl): Logged out in=309, out=1268, bytes=309/1268 Oct 12 09:26:20 server dovecot: pop3-login: Login: user=, method=PLAIN, rip=34.211.38.79, lip=50.116.xx.xxx, mpid=29089, session= Oct 12 09:26:20 server dovecot: pop3(inventarios_automate@example.cl): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0, bytes=12/43 Oct 12 09:26:27 server spamd[23912]: spamd: connection from localhost [::1]:38762 to port 783, fd 5 Oct 12 09:26:27 server dovecot: pop3-login: Aborted login (no auth attempts in 0 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, secured, session= Oct 12 09:26:28 server spamd[23408]: prefork: child states: I Oct 12 09:26:28 server dovecot: lmtp(29112): Connect from local Oct 12 09:26:28 server dovecot: lmtp(29112): Disconnect from local: Successful quit Oct 12 09:26:28 server dovecot: imap-login: Login: user=<__cpanel__service__auth__imap__hnepraejvk5m5ids21bsytm0sopboefrj6u8_nmk9kg29j...>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=29115, secured, sessi$ Oct 12 09:26:28 server dovecot: imap(__cpanel__service__auth__imap__hnepraejvk5m5ids21bsytm0sopboefrj6u8_nmk9kg29jlegkzkqdfosxzllusa): Logged out in=11, out=476, bytes=11/476 Oct 12 09:27:03 server dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=29162, secured, session= Oct 12 09:27:03 server dovecot: imap(dummy@example.cl): Logged out in=120, out=1248, bytes=120/1248 Oct 12 09:28:03 server dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=29175, secured, session= Oct 12 09:28:03 server dovecot: imap(dummy@example.cl): Logged out in=120, out=1248, bytes=120/1248 Oct 12 09:29:03 server dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=29193, secured, session= Oct 12 09:29:03 server dovecot: imap(dummy@example.cl): Logged out in=120, out=1240, bytes=120/1240 Oct 12 09:30:02 server dovecot: pop3-login: Login: user=, method=PLAIN, rip=50.116.xx.xxx, lip=50.116.xx.xxx, mpid=29231, TLS, session= Oct 12 09:30:03 server dovecot: pop3(support@example.cl): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0, bytes=30/133 Oct 12 09:30:03 server dovecot: pop3-login: Login: user=, method=PLAIN, rip=50.116.xx.xxx, lip=50.116.xx.xxx, mpid=29232, TLS, session= Oct 12 09:30:03 server dovecot: pop3(sales@example.cl): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0, bytes=30/133 Oct 12 09:30:03 server dovecot: pop3-login: Login: user=, method=PLAIN, rip=50.116.xx.xxx, lip=50.116.xx.xxx, mpid=29233, TLS, session= Oct 12 09:30:03 server dovecot: pop3(info@example.cl): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0, bytes=30/133 Oct 12 09:30:03 server dovecot: imap-login: Login: user=, method=PLAIN, rip=::1, lip=::1, mpid=29239, secured, session=<6U8sPwd4DJ0AAAAAAAAAAAAAAAAAAAAB> Oct 12 09:30:03 server dovecot: imap(dummy@example.cl): Logged out in=120, out=1248, bytes=120/1248 Oct 12 09:30:03 server dovecot: lmtp(29241): Connect from local Oct 12 09:30:04 server dovecot: lmtp(example1@server.example.com): msgid=: saved mail to INBOX Oct 12 09:30:04 server dovecot: lmtp(29241): Disconnect from local: Successful quit
Finally, the exim queue is empty. Thanks Jaime0 -
This is the part of "exim_mainlog"
Post edited. Please be sure to always remove any real emails and IP addresses, user and domain names from any output you post to public forums for your own and your clients privacy. ;) Thanks!0 -
Hi @desytec The transactional information in the mainlog shows no indication of the outbound mail transaction taking longer than a few seconds: 2018-10-12 09:26:48 1gAwWk-0007Zy-J1 SMTP connection outbound 1539347208 1gAwWk-0007Zy-J1 example.cl jvasquez@example2.cl 2018-10-12 09:26:49 SMTP connection from (SkorpioX3) [IPREMOVED]:3591 closed by QUIT 2018-10-12 09:26:49 1gAwWk-0007Zy-J1 Sender identification U=example1 D=example.cl S=lean@example.cl 2018-10-12 09:26:49 1gAwWk-0007Zy-J1 SMTP connection outbound 1539347209 1gAwWk-0007Zy-J1 example.cl jstuardo@example.com 2018-10-12 09:26:50 1gAwWk-0007Zy-J1 Sender identification U=example1 D=example.cl S=lean@example.cl 2018-10-12 09:26:50 1gAwWk-0007Zy-J1 SMTP connection outbound 1539347210 1gAwWk-0007Zy-J1 example.cl avasquez@example2.cl 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 => jvasquez@example2.cl (inventarios_lean@example.cl) R=dkim_lookuphost T=dkim_remote_smtp H=aspmx.l.google.com [74.125.135.26] X=TLSv1.2:ECDHE-$ 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 => avasquez@example2.cl (inventarios_lean@example.cl) R=dkim_lookuphost T=dkim_remote_smtp H=aspmx.l.google.com [74.125.142.27] X=TLSv1.2:ECDHE-$ 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 => jstuardo@example.com (inventarios_lean@example.cl) R=dkim_lookuphost T=dkim_remote_smtp H=aspmx.l.google.com [74.125.135.26] X=TLSv1.2:ECDHE$ 2018-10-12 09:26:51 1gAwWk-0007Zy-J1 Completed 2
Outbound connection initiated at 2018-10-12 09:26:48 and completed transaction at 2018-10-12 09:26:510
Please sign in to leave a comment.
Comments
4 comments