Could not open file
Could not open file
Hello and thank you for all the fine work you have done over the years
I have a lot of messages like this in E.F.A. 4
May 18 00:34:14 mx03 MailScanner[14583]: Could not open file +</var/spool/MailScanner/milterout/temp-21076-4FkXSw63ryz4xJn0: No such file or directory
May 18 08:09:01 mx03 MailScanner[24307]: Could not open file +</var/spool/MailScanner/milterout/4FkkYn1LZsz5C1T: No such file or directory
May 18 08:15:08 mx03 MailScanner[4271]: Could not open file +</var/spool/MailScanner/milterout/temp-15181-4FkkcY2HwRz4xZxb: No such file or directory
May 18 08:15:08 mx03 MailScanner[15181]: Could not open file +</var/spool/MailScanner/milterout/4Fkkhr0Mmvz5C1d: No such file or directory
May 18 09:03:58 mx03 MailScanner[25134]: Could not open file +</var/spool/MailScanner/milterout/4Fklmp0pFKz5C1t: No such file or directory
for a specific queueid the log is like this
[root@mx03 ~]# grep 4FkRty6Txbz0pDl /var/log/maillog
May 17 21:07:54 mx03 MailScanner[8443]: Requeue: 4FkRts6QNHz4xJn3 to 4FkRty6Txbz0pDl
May 17 21:07:55 mx03 MailScanner[4439]: Could not open file +</var/spool/MailScanner/milterout/4FkRty6Txbz0pDl: No such file or directory
May 17 21:07:55 mx03 MailScanner[4439]: Cannot open /var/spool/MailScanner/milterout/4FkRty6Txbz0pDl for relaying, will try again later
[root@mx03 ~]# grep 4FkRts6QNHz4xJn3 /var/log/maillog
May 17 21:07:49 mx03 postfix/smtpd[5158]: 4FkRts6QNHz4xJn3: client=xxxxxxxx.gr[xxx.xxx.xxx.xxx]
May 17 21:07:49 mx03 postfix/cleanup[5178]: 4FkRts6QNHz4xJn3: message-id=<CAB1Nd4f=WG9RJcBoxNOkcM07nGOnEmVNMovP5qKbUZg4wjPiUQ@xxxx.xxxxx.com>
May 17 21:07:50 mx03 opendkim[9169]: 4FkRts6QNHz4xJn3: XXXXXXXX.gr [xxx.xxx.xxx.xxx] not internal
May 17 21:07:50 mx03 opendkim[9169]: 4FkRts6QNHz4xJn3: not authenticated
May 17 21:07:50 mx03 opendkim[9169]: 4FkRts6QNHz4xJn3: DKIM verification successful
May 17 21:07:50 mx03 opendmarc[9160]: 4FkRts6QNHz4xJn3: SPF(mailfrom): xxxxxx@xxxxx.gr pass
May 17 21:07:50 mx03 opendmarc[9160]: 4FkRts6QNHz4xJn3: xxxxx.gr pass
May 17 21:07:52 mx03 postfix/cleanup[5178]: 4FkRts6QNHz4xJn3: milter-discard: END-OF-MESSAGE from xxxxxxxxx.gr[XXX.XX.XX.XXX]: milter triggers DISCARD action; from=<SRS0=wVVY=KM=xxxxxxx.gr=xxxxxxx@xxxxxx.gr> to=<xxxxxxx@xxxxxxx.gr> proto=ESMTP helo=<xxxxxxxx.gr>
May 17 21:07:54 mx03 MailScanner[8443]: <A> tag found in message 4FkRts6QNHz4xJn3 from xxxxxx@xxxxx.gr
May 17 21:07:54 mx03 MailScanner[8443]: Message 4FkRts6QNHz4xJn3 from XXX.XXX.XXX.XXX ( xxxxxx@xxxxx.gr) to med.uoc.gr is too big for spam checks (2306499 > 2048000 bytes)
May 17 21:07:54 mx03 MailScanner[8443]: Requeue: 4FkRts6QNHz4xJn3 to 4FkRty6Txbz0pDl
May 17 21:07:55 mx03 MailScanner[2770]: Could not open file +</var/spool/MailScanner/milterout/temp-8443-4FkRts6QNHz4xJn3: No such file or directory
May 17 21:07:55 mx03 MailScanner[2770]: Cannot open /var/spool/MailScanner/milterout/temp-8443-4FkRts6QNHz4xJn3 for relaying, will try again later
May 17 21:07:55 mx03 MailScanner[8443]: MailWatch: Logging message 4FkRts6QNHz4xJn3 to SQL
May 17 21:07:55 mx03 MailScanner[14561]: MailWatch: 4FkRts6QNHz4xJn3: Logged to MailWatch SQL
This is something that does not happen in E.F.A. 3
Let me note here that I have a high volume mail infrastructure this this usualy happens under stress, one the other hand this is not an issue on EFA 3
and with "smaller" machines.
Any thoughts?
I have a lot of messages like this in E.F.A. 4
May 18 00:34:14 mx03 MailScanner[14583]: Could not open file +</var/spool/MailScanner/milterout/temp-21076-4FkXSw63ryz4xJn0: No such file or directory
May 18 08:09:01 mx03 MailScanner[24307]: Could not open file +</var/spool/MailScanner/milterout/4FkkYn1LZsz5C1T: No such file or directory
May 18 08:15:08 mx03 MailScanner[4271]: Could not open file +</var/spool/MailScanner/milterout/temp-15181-4FkkcY2HwRz4xZxb: No such file or directory
May 18 08:15:08 mx03 MailScanner[15181]: Could not open file +</var/spool/MailScanner/milterout/4Fkkhr0Mmvz5C1d: No such file or directory
May 18 09:03:58 mx03 MailScanner[25134]: Could not open file +</var/spool/MailScanner/milterout/4Fklmp0pFKz5C1t: No such file or directory
for a specific queueid the log is like this
[root@mx03 ~]# grep 4FkRty6Txbz0pDl /var/log/maillog
May 17 21:07:54 mx03 MailScanner[8443]: Requeue: 4FkRts6QNHz4xJn3 to 4FkRty6Txbz0pDl
May 17 21:07:55 mx03 MailScanner[4439]: Could not open file +</var/spool/MailScanner/milterout/4FkRty6Txbz0pDl: No such file or directory
May 17 21:07:55 mx03 MailScanner[4439]: Cannot open /var/spool/MailScanner/milterout/4FkRty6Txbz0pDl for relaying, will try again later
[root@mx03 ~]# grep 4FkRts6QNHz4xJn3 /var/log/maillog
May 17 21:07:49 mx03 postfix/smtpd[5158]: 4FkRts6QNHz4xJn3: client=xxxxxxxx.gr[xxx.xxx.xxx.xxx]
May 17 21:07:49 mx03 postfix/cleanup[5178]: 4FkRts6QNHz4xJn3: message-id=<CAB1Nd4f=WG9RJcBoxNOkcM07nGOnEmVNMovP5qKbUZg4wjPiUQ@xxxx.xxxxx.com>
May 17 21:07:50 mx03 opendkim[9169]: 4FkRts6QNHz4xJn3: XXXXXXXX.gr [xxx.xxx.xxx.xxx] not internal
May 17 21:07:50 mx03 opendkim[9169]: 4FkRts6QNHz4xJn3: not authenticated
May 17 21:07:50 mx03 opendkim[9169]: 4FkRts6QNHz4xJn3: DKIM verification successful
May 17 21:07:50 mx03 opendmarc[9160]: 4FkRts6QNHz4xJn3: SPF(mailfrom): xxxxxx@xxxxx.gr pass
May 17 21:07:50 mx03 opendmarc[9160]: 4FkRts6QNHz4xJn3: xxxxx.gr pass
May 17 21:07:52 mx03 postfix/cleanup[5178]: 4FkRts6QNHz4xJn3: milter-discard: END-OF-MESSAGE from xxxxxxxxx.gr[XXX.XX.XX.XXX]: milter triggers DISCARD action; from=<SRS0=wVVY=KM=xxxxxxx.gr=xxxxxxx@xxxxxx.gr> to=<xxxxxxx@xxxxxxx.gr> proto=ESMTP helo=<xxxxxxxx.gr>
May 17 21:07:54 mx03 MailScanner[8443]: <A> tag found in message 4FkRts6QNHz4xJn3 from xxxxxx@xxxxx.gr
May 17 21:07:54 mx03 MailScanner[8443]: Message 4FkRts6QNHz4xJn3 from XXX.XXX.XXX.XXX ( xxxxxx@xxxxx.gr) to med.uoc.gr is too big for spam checks (2306499 > 2048000 bytes)
May 17 21:07:54 mx03 MailScanner[8443]: Requeue: 4FkRts6QNHz4xJn3 to 4FkRty6Txbz0pDl
May 17 21:07:55 mx03 MailScanner[2770]: Could not open file +</var/spool/MailScanner/milterout/temp-8443-4FkRts6QNHz4xJn3: No such file or directory
May 17 21:07:55 mx03 MailScanner[2770]: Cannot open /var/spool/MailScanner/milterout/temp-8443-4FkRts6QNHz4xJn3 for relaying, will try again later
May 17 21:07:55 mx03 MailScanner[8443]: MailWatch: Logging message 4FkRts6QNHz4xJn3 to SQL
May 17 21:07:55 mx03 MailScanner[14561]: MailWatch: 4FkRts6QNHz4xJn3: Logged to MailWatch SQL
This is something that does not happen in E.F.A. 3
Let me note here that I have a high volume mail infrastructure this this usualy happens under stress, one the other hand this is not an issue on EFA 3
and with "smaller" machines.
Any thoughts?
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
Sounds like the message didn't get written out to the disk. How is your capacity?
Re: Could not open file
capacity is ok
and disk is on ssd-based vmwareFS .
It is not a capacity problem, there is plenty of space there, and to clarify this usualy happens on high traffic situations i.e. mass processing of emails received through mailing lists, one mail may fail while 1000 others may be ok.
I tried to increase mailscanner children and milter children, did not help
devtmpfs 5,8G 0 5,8G 0% /dev
tmpfs 5,8G 0 5,8G 0% /dev/shm
tmpfs 5,8G 609M 5,2G 11% /run
tmpfs 5,8G 0 5,8G 0% /sys/fs/cgroup
/dev/mapper/centos-root 50G 33G 18G 65% /
none 5,8G 12M 5,8G 1% /var/spool/MailScanner/incoming
/dev/sda1 1014M 319M 696M 32% /boot
/dev/mapper/centos-home 42G 33M 42G 1% /home
tmpfs 1,2G 0 1,2G 0% /run/user/0
memory is at 12G
[root@mx03 ~]# free -m
total used free shared buff/cache available
Mem: 11852 7920 151 628 3780 3042
Swap: 8063 28 8035
and there are 8 vcores on the vm
any guides as on how to proceed to fix this issue?
Thank you
and disk is on ssd-based vmwareFS .
It is not a capacity problem, there is plenty of space there, and to clarify this usualy happens on high traffic situations i.e. mass processing of emails received through mailing lists, one mail may fail while 1000 others may be ok.
I tried to increase mailscanner children and milter children, did not help
devtmpfs 5,8G 0 5,8G 0% /dev
tmpfs 5,8G 0 5,8G 0% /dev/shm
tmpfs 5,8G 609M 5,2G 11% /run
tmpfs 5,8G 0 5,8G 0% /sys/fs/cgroup
/dev/mapper/centos-root 50G 33G 18G 65% /
none 5,8G 12M 5,8G 1% /var/spool/MailScanner/incoming
/dev/sda1 1014M 319M 696M 32% /boot
/dev/mapper/centos-home 42G 33M 42G 1% /home
tmpfs 1,2G 0 1,2G 0% /run/user/0
memory is at 12G
[root@mx03 ~]# free -m
total used free shared buff/cache available
Mem: 11852 7920 151 628 3780 3042
Swap: 8063 28 8035
and there are 8 vcores on the vm
any guides as on how to proceed to fix this issue?
Thank you
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
I'm trying to figure out how a number gets prefixed to the temp file, that looks peculiar to me.
Re: Could not open file
Is there anything I can do ; Do you need some extra info;
Please let me know.
Please let me know.
Re: Could not open file
It occured to me that I have enabled generic scanner on mailscanner.conf in order to scan for ole-vba on attachements
This works flawlessly on EFA3
could this be to blame ?
This works flawlessly on EFA3
could this be to blame ?
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
Does this result in any perceivable loss or duplication of email?
Reason I ask is because I think this is a race condition based on the fact that each child process queries the directory and builds a list of emails to deliver. In theory, two of them could spawn close enough to cause one to deliver and another to notice it is gone from disk.
If so, this is benign and a bugfix is in order to make the children play nice together
Reason I ask is because I think this is a race condition based on the fact that each child process queries the directory and builds a list of emails to deliver. In theory, two of them could spawn close enough to cause one to deliver and another to notice it is gone from disk.
If so, this is benign and a bugfix is in order to make the children play nice together
Re: Could not open file
Well I have to check it out, I have some reports of duplicate mails though.
Re: Could not open file
I am afraid that there is loss of emails
mail get requeued and then there is no mention on the logs :
[root@mx03 ~]# grep 4FVcGc2FJZzPpqG maillog-20210502
Apr 28 14:43:52 mx03 MailScanner[5905]: Requeue: 4FVcFh5kDkz56Zhj to 4FVcGc2FJZzPpqG
Apr 28 14:43:52 mx03 MailScanner[5905]: Could not open file +</var/spool/MailScanner/milterout/4FVcGc2FJZzPpqG: No such file or directory
Apr 28 14:43:52 mx03 MailScanner[5905]: Cannot open /var/spool/MailScanner/milterout/4FVcGc2FJZzPpqG for relaying, will try again later
[root@mx03 ~]# grep 4FVcFh5kDkz56Zhj maillog-20210502
Apr 28 14:43:04 mx03 postfix/smtpd[23267]: 4FVcFh5kDkz56Zhj: client=sonic329-9.consmr.mail.ne1.yahoo.com[66.163.185.71]
Apr 28 14:43:05 mx03 postfix/cleanup[21251]: 4FVcFh5kDkz56Zhj: message-id=<1619610177.942273@dmarc.yahoo.com>
Apr 28 14:43:05 mx03 opendkim[9294]: 4FVcFh5kDkz56Zhj: sonic329-9.consmr.mail.ne1.yahoo.com [66.163.185.71] not internal
Apr 28 14:43:05 mx03 opendkim[9294]: 4FVcFh5kDkz56Zhj: not authenticated
Apr 28 14:43:05 mx03 opendkim[9294]: 4FVcFh5kDkz56Zhj: DKIM verification successful
Apr 28 14:43:05 mx03 opendmarc[9285]: 4FVcFh5kDkz56Zhj: SPF(mailfrom): noreply@dmarc.yahoo.com none
Apr 28 14:43:05 mx03 opendmarc[9285]: 4FVcFh5kDkz56Zhj: dmarc.yahoo.com pass
Apr 28 14:43:52 mx03 MailScanner[5905]: Requeue: 4FVcFh5kDkz56Zhj to 4FVcGc2FJZzPpqG
Apr 28 14:43:52 mx03 MailScanner[5905]: MailWatch: Logging message 4FVcFh5kDkz56Zhj to SQL
Apr 28 14:43:52 mx03 MailScanner[12129]: MailWatch: 4FVcFh5kDkz56Zhj: Logged to MailWatch SQL
mail get requeued and then there is no mention on the logs :
[root@mx03 ~]# grep 4FVcGc2FJZzPpqG maillog-20210502
Apr 28 14:43:52 mx03 MailScanner[5905]: Requeue: 4FVcFh5kDkz56Zhj to 4FVcGc2FJZzPpqG
Apr 28 14:43:52 mx03 MailScanner[5905]: Could not open file +</var/spool/MailScanner/milterout/4FVcGc2FJZzPpqG: No such file or directory
Apr 28 14:43:52 mx03 MailScanner[5905]: Cannot open /var/spool/MailScanner/milterout/4FVcGc2FJZzPpqG for relaying, will try again later
[root@mx03 ~]# grep 4FVcFh5kDkz56Zhj maillog-20210502
Apr 28 14:43:04 mx03 postfix/smtpd[23267]: 4FVcFh5kDkz56Zhj: client=sonic329-9.consmr.mail.ne1.yahoo.com[66.163.185.71]
Apr 28 14:43:05 mx03 postfix/cleanup[21251]: 4FVcFh5kDkz56Zhj: message-id=<1619610177.942273@dmarc.yahoo.com>
Apr 28 14:43:05 mx03 opendkim[9294]: 4FVcFh5kDkz56Zhj: sonic329-9.consmr.mail.ne1.yahoo.com [66.163.185.71] not internal
Apr 28 14:43:05 mx03 opendkim[9294]: 4FVcFh5kDkz56Zhj: not authenticated
Apr 28 14:43:05 mx03 opendkim[9294]: 4FVcFh5kDkz56Zhj: DKIM verification successful
Apr 28 14:43:05 mx03 opendmarc[9285]: 4FVcFh5kDkz56Zhj: SPF(mailfrom): noreply@dmarc.yahoo.com none
Apr 28 14:43:05 mx03 opendmarc[9285]: 4FVcFh5kDkz56Zhj: dmarc.yahoo.com pass
Apr 28 14:43:52 mx03 MailScanner[5905]: Requeue: 4FVcFh5kDkz56Zhj to 4FVcGc2FJZzPpqG
Apr 28 14:43:52 mx03 MailScanner[5905]: MailWatch: Logging message 4FVcFh5kDkz56Zhj to SQL
Apr 28 14:43:52 mx03 MailScanner[12129]: MailWatch: 4FVcFh5kDkz56Zhj: Logged to MailWatch SQL
Re: Could not open file
Hello,
I found this topic while looking up for an issue we have.
It is exactly the same. Our maillog is fillled with the same entries as the original poster.
I discovered this today because a user told us she was not receiving some e-mails that were sent to her and while tracing the mail flow:
and then
and that's the latest entries for this particular mail, but the mail never made it to the final destination.
Also checking the recent logs about the "will try again later" I can see they are some actually being retried again and again
A whole lot of bunch per minutes...
Any idea what could be wrong ?
Cheers
I found this topic while looking up for an issue we have.
It is exactly the same. Our maillog is fillled with the same entries as the original poster.
I discovered this today because a user told us she was not receiving some e-mails that were sent to her and while tracing the mail flow:
Code: Select all
Oct 27 12:17:30 mx1 postfix/smtpd[32563]: 4HfPky015wzMqYwP: client=someserver[1.1.1.1]
Oct 27 12:17:30 mx1 postfix/cleanup[33186]: 4HfPky015wzMqYwP: message-id=<579185583.15521.1635329848828@somedomain>
Oct 27 12:17:30 mx1 opendkim[2742]: 4HfPky015wzMqYwP: someserver [1.1.1.1] not internal
Oct 27 12:17:30 mx1 opendkim[2742]: 4HfPky015wzMqYwP: not authenticated
Oct 27 12:17:30 mx1 opendkim[2742]: 4HfPky015wzMqYwP: no signature data
Oct 27 12:17:30 mx1 opendmarc[48944]: 4HfPky015wzMqYwP: SPF(mailfrom): somedomain pass
Oct 27 12:17:30 mx1 opendmarc[48944]: 4HfPky015wzMqYwP: somedomain none
Oct 27 12:17:31 mx1 postfix/cleanup[33186]: 4HfPky015wzMqYwP: milter-discard: END-OF-MESSAGE from someserver[1.1.1.1]: milter triggers DISCARD action; from=<somemail@address> to=<somemail@address> proto=ESMTP helo=<someserver>
Oct 27 12:18:33 mx1 MailScanner[52943]: <A> tag found in message 4HfPky015wzMqYwP from somemail@address
Oct 27 12:18:33 mx1 MailScanner[52943]: HTML Img tag found in message 4HfPky015wzMqYwP from somemail@address
Oct 27 12:18:36 mx1 MailScanner[52943]: Requeue: 4HfPky015wzMqYwP to 4HfPmD528lzkkhg
Oct 27 12:18:37 mx1 MailScanner[52943]: MailWatch: Logging message 4HfPky015wzMqYwP to SQL
Code: Select all
Oct 27 12:18:38 mx1 MailScanner[53290]: Could not open file +</var/spool/MailScanner/milterout/4HfPmD528lzkkhg: No such file or directory
Oct 27 12:18:38 mx1 MailScanner[53290]: Cannot open /var/spool/MailScanner/milterout/4HfPmD528lzkkhg for relaying, will try again later
Also checking the recent logs about the "will try again later" I can see they are some actually being retried again and again
Code: Select all
Nov 10 17:15:56 mx1 MailScanner[215777]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 17:15:57 mx1 MailScanner[215860]: Cannot open /var/spool/MailScanner/milterout/4Hq92407j1zB7Xy for relaying, will try again later
Nov 10 17:15:59 mx1 MailScanner[216118]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 17:16:00 mx1 MailScanner[215296]: Cannot open /var/spool/MailScanner/milterout/4Hq927165lzB7Xy for relaying, will try again later
Nov 10 17:16:02 mx1 MailScanner[215038]: Cannot open /var/spool/MailScanner/milterout/4Hq92854T4zB7Xy for relaying, will try again later
Nov 10 17:16:02 mx1 MailScanner[216699]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 17:16:03 mx1 MailScanner[215777]: Cannot open /var/spool/MailScanner/milterout/4Hq92B6r9PzB7Xy for relaying, will try again later
Nov 10 17:16:03 mx1 MailScanner[215777]: Cannot open /var/spool/MailScanner/milterout/4Hq92B6tVKzB7Y1 for relaying, will try again later
Nov 10 17:16:14 mx1 MailScanner[67604]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 17:16:14 mx1 MailScanner[215860]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 17:16:14 mx1 MailScanner[215777]: Cannot open /var/spool/MailScanner/milterout/4Hq92P6c9gzB7Xy for relaying, will try again later
Nov 10 17:16:14 mx1 MailScanner[215777]: Cannot open /var/spool/MailScanner/milterout/4Hq92P6gwtzB7Y1 for relaying, will try again later
Any idea what could be wrong ?
Cheers
Re: Could not open file
I forgot to mention that in the log of the mail that I traced I can see:
But when looking up for this mail ID in mailwatch interface :
Checking the db manually:
I guess in the log I should see a corresponging entry like:
but it is not present
Could both be related ? I mean the entry not being added to maillog and the "Cannot open" issue ?
Code: Select all
"MailWatch: Logging message 4HfPky015wzMqYwP to SQL"
Code: Select all
"Message ID '4HfPky015wzMqYwP' not found!"
Code: Select all
MariaDB [mailscanner]> select * from maillog where id = '4HfPky015wzMqYwP';
Empty set (0.00 sec)
Code: Select all
MailWatch: 4HfPky015wzMqYwP : Logged to MailWatch SQL
Could both be related ? I mean the entry not being added to maillog and the "Cannot open" issue ?
Last edited by r00tsh3ll on 10 Nov 2021 17:05, edited 1 time in total.
Re: Could not open file
Also something else I discovered.
On of the mail that is unable to open is present in the mailout folder.
This one has Unable to kick messages additionnaly to the Cannot open.
On of the mail that is unable to open is present in the mailout folder.
Code: Select all
[root@mx1 log]# ls -la /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd
-rw-------. 1 postfix postfix 216727 Oct 12 10:34 /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd
Code: Select all
tail -n 1000 maillog | grep 4HT88q4kNYzlsmd
Nov 10 18:00:04 mx1 MailScanner[215038]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:05 mx1 MailScanner[214600]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:07 mx1 MailScanner[216699]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 18:00:07 mx1 MailScanner[215860]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:09 mx1 MailScanner[216382]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:12 mx1 MailScanner[215038]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:13 mx1 MailScanner[216332]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:15 mx1 MailScanner[216699]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:19 mx1 MailScanner[216332]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Nov 10 18:00:24 mx1 MailScanner[215860]: Cannot open /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd for relaying, will try again later
Nov 10 18:00:26 mx1 MailScanner[216382]: Unable to kick message /var/spool/MailScanner/milterout/4HT88q4kNYzlsmd, will retry soon...
Re: Could not open file
Sorry for the flood, but I want also to add that looking at /var/log/messages we have also a lot of:
not sure if related though
Code: Select all
Nov 10 19:41:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 10 19:41:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 10 19:41:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
This may be some clues into this problem.
It is very unusual to see warnings coming from Copy.pm, which really concerns me. There seem to be some variables unininitialized.
Probably removing or moving the temp- artifact from milterin will clear that part up.
It is very unusual to see warnings coming from Copy.pm, which really concerns me. There seem to be some variables unininitialized.
Probably removing or moving the temp- artifact from milterin will clear that part up.
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
On the earlier post, the file is there and it can't open it. Are you seeing any Denied messages in /var/log/audit/audit.log, by chance?
Re: Could not open file
Hello shawn,
Sorry for the late reply. I thought I would receive notifications when there are replies to the topic, but it seems I don't, I have to check the notifications settings
About the audit.log, there are some entries but they are related to our custom postfix transport databases:
As selinux is in permissive mode, I guess it only notifies but doesn't block the access. If it would the postfix routing and zabbix monitoring would be broken.
Still I should add the exceptions for these files/processes or maybe just get rid of selinux....
The msmilter Copy.pm errors are still flooding (I rebooted the box after the latest update in order to check if it would change anything)
Also we still have "Cannot open" occuring for some milterout files. It concerns only a few files as it process a lot of mail daily. But it is still concerning as it can turn into mail being lost.
I think sometimes it could be a race condition and it retries it, and then it succeed. But for some it never succeed and I can't find any trace of the file on the system.
For example
Is currently being retried often, but the file doesn't exists anywhere.
I don't know where to head at this point to try to debug this. I know a bit how the whole system works but not too deep into the details.
Kind regards.
Sorry for the late reply. I thought I would receive notifications when there are replies to the topic, but it seems I don't, I have to check the notifications settings
About the audit.log, there are some entries but they are related to our custom postfix transport databases:
Code: Select all
type=SYSCALL msg=audit(1636916009.144:265695): arch=c000003e syscall=5 success=yes exit=0 a0=11 a1=7ffee36d5020 a2=7ffee36d5020 a3=17318 items=0 ppid=3906 pid=96324 auid=4294967295 uid=89 gid=89 euid=89 suid=89 fsuid=89 egid=89 sgid=89 fsgid=89 tty=(none) ses=4294967295 comm="cleanup" exe="/usr/libexec/postfix/cleanup" subj=system_u:system_r:postfix_cleanup_t:s0 key=(null)
type=PROCTITLE msg=audit(1636916009.144:265695): proctitle=636C65616E7570002D7A002D7400756E6978002D75
type=AVC msg=audit(1636916012.511:265696): avc: denied { getattr } for pid=91718 comm="qmgr" path="/etc/postfix/transport_all.db" dev="sda3" ino=67774170 scontext=system_u:system_r:postfix_qmgr_t:s0 tcontext=unconfined_u:object_r:admin_home_t:s0 tclass=file permissive=1
type=SYSCALL msg=audit(1636916012.511:265696): arch=c000003e syscall=5 success=yes exit=0 a0=a a1=7ffd3bda98b0 a2=7ffd3bda98b0 a3=48058 items=0 ppid=3906 pid=91718 auid=4294967295 uid=89 gid=89 euid=89 suid=89 fsuid=89 egid=89 sgid=89 fsgid=89 tty=(none) ses=4294967295 comm="qmgr" exe="/usr/libexec/postfix/qmgr" subj=system_u:system_r:postfix_qmgr_t:s0 key=(null)
type=PROCTITLE msg=audit(1636916012.511:265696): proctitle=716D6772002D6C002D74006669666F002D75
type=AVC msg=audit(1636916032.697:265697): avc: denied { name_connect } for pid=1891 comm="zabbix_agentd" dest=8891 scontext=system_u:system_r:zabbix_agent_t:s0 tcontext=system_u:object_r:milter_port_t:s0 tclass=tcp_socket permissive=1
type=SYSCALL msg=audit(1636916032.697:265697): arch=c000003e syscall=42 success=yes exit=0 a0=7 a1=5635d5d9b630 a2=10 a3=0 items=0 ppid=1884 pid=1891 auid=4294967295 uid=988 gid=985 euid=988 suid=988 fsuid=988 egid=985 sgid=985 fsgid=985 tty=(none) ses=4294967295 comm="zabbix_agentd" exe="/usr/sbin/zabbix_agentd" subj=system_u:system_r:zabbix_agent_t:s0 key=(null)
type=PROCTITLE msg=audit(1636916032.697:265697): proctitle=2F7573722F7362696E2F7A61626269785F6167656E74643A206C697374656E6572202332205B70726F63657373696E6720726571756573745D
type=AVC msg=audit(1636916035.591:265698): avc: denied { getattr } for pid=92127 comm="smtpd" path="/etc/postfix/transport_all.db" dev="sda3" ino=67774170 scontext=system_u:system_r:postfix_smtpd_t:s0 tcontext=unconfined_u:object_r:admin_home_t:s0 tclass=file permissive=1
type=SYSCALL msg=audit(1636916035.591:265698): arch=c000003e syscall=5 success=yes exit=0 a0=b a1=7ffee5020fd0 a2=7ffee5020fd0 a3=101d0 items=0 ppid=3906 pid=92127 auid=4294967295 uid=89 gid=89 euid=89 suid=89 fsuid=89 egid=89 sgid=89 fsgid=89 tty=(none) ses=4294967295 comm="smtpd" exe="/usr/libexec/postfix/smtpd" subj=system_u:system_r:postfix_smtpd_t:s0 key=(null)
type=PROCTITLE msg=audit(1636916035.591:265698): proctitle=736D747064002D740070617373002D75002D6F007374726573733D002D6F00736D7470645F7361736C5F617574685F656E61626C653D6E6F
Still I should add the exceptions for these files/processes or maybe just get rid of selinux....
The msmilter Copy.pm errors are still flooding (I rebooted the box after the latest update in order to check if it would change anything)
Code: Select all
Nov 14 19:52:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:52:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:52:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:53:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:53:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:53:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:54:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:54:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:54:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:55:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:55:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:55:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:56:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:56:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:56:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:57:52 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:57:52 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:57:52 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:58:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:58:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:58:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:59:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 19:59:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 19:59:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 20:00:51 mx1 msmilter-init: '/var/spool/MailScanner/milterin/temp-' and '/var/spool/MailScanner/milterin/temp-' are identical (not copied) at /usr/sbin/MSMilter line 533.
Nov 14 20:00:51 mx1 msmilter-init: Use of uninitialized value $atime in utime at /usr/share/perl5/File/Copy.pm line 393.
Nov 14 20:00:51 mx1 msmilter-init: Use of uninitialized value $mtime in utime at /usr/share/perl5/File/Copy.pm line 393.
Code: Select all
Nov 14 18:28:42 mx1 MailScanner[58062]: Cannot open /var/spool/MailScanner/milterout/temp-60376-4HsfRr6dC9zP4Dss for relaying, will try again later
Nov 14 18:30:03 mx1 MailScanner[56910]: Cannot open /var/spool/MailScanner/milterout/4HsfTl0BPGzfTmd for relaying, will try again later
Nov 14 18:30:16 mx1 MailScanner[60532]: Cannot open /var/spool/MailScanner/milterout/4HsfV00Tf7zfTmc for relaying, will try again later
Nov 14 18:30:49 mx1 MailScanner[59936]: Cannot open /var/spool/MailScanner/milterout/4HsfVd6bzGzfTmc for relaying, will try again later
Nov 14 18:30:57 mx1 MailScanner[243946]: Cannot open /var/spool/MailScanner/milterout/4HsfVn4p5fzfTmc for relaying, will try again later
Nov 14 18:31:16 mx1 MailScanner[243372]: Cannot open /var/spool/MailScanner/milterout/4HsfW82HbYzfTmc for relaying, will try again later
Nov 14 18:39:44 mx1 MailScanner[60238]: Cannot open /var/spool/MailScanner/milterout/temp-58032-4Hsfhq4K0WzP4Dsn for relaying, will try again later
Nov 14 18:39:44 mx1 MailScanner[58032]: Cannot open /var/spool/MailScanner/milterout/4Hsfhw4txwzfTmc for relaying, will try again later
Nov 14 18:46:35 mx1 MailScanner[60532]: Cannot open /var/spool/MailScanner/milterout/4Hsfrq5rTLzfTmd for relaying, will try again later
Nov 14 18:49:59 mx1 MailScanner[59936]: Cannot open /var/spool/MailScanner/milterout/4Hsfwl0sxGzfTmc for relaying, will try again later
Nov 14 19:00:41 mx1 MailScanner[58062]: Cannot open /var/spool/MailScanner/milterout/temp-59740-4Hsg8p1V5wzP4Dsb for relaying, will try again later
Nov 14 19:01:01 mx1 MailScanner[57779]: Cannot open /var/spool/MailScanner/milterout/4Hsg9T0wyKzfTmc for relaying, will try again later
Nov 14 19:21:18 mx1 MailScanner[58062]: Cannot open /var/spool/MailScanner/milterout/4Hsgct0PP5zkkF6 for relaying, will try again later
Nov 14 19:21:18 mx1 MailScanner[60532]: Cannot open /var/spool/MailScanner/milterout/4Hsgct0Pb8zkkF3 for relaying, will try again later
Nov 14 19:23:46 mx1 MailScanner[64158]: Cannot open /var/spool/MailScanner/milterout/4Hsggk1ZlXzkkF3 for relaying, will try again later
Nov 14 19:30:16 mx1 MailScanner[57779]: Cannot open /var/spool/MailScanner/milterout/4HsgqD3PkzzkkF6 for relaying, will try again later
Nov 14 19:30:16 mx1 MailScanner[56910]: Cannot open /var/spool/MailScanner/milterout/4HsgqD3RBJzkkF7 for relaying, will try again later
Nov 14 19:50:00 mx1 MailScanner[60376]: Cannot open /var/spool/MailScanner/milterout/4HshG06wcrzkkF3 for relaying, will try again later
Nov 14 19:52:43 mx1 MailScanner[60238]: Cannot open /var/spool/MailScanner/milterout/4HshK71VbWzkkF3 for relaying, will try again later
Nov 14 19:59:46 mx1 MailScanner[59936]: Cannot open /var/spool/MailScanner/milterout/4HshTG6SfzzkkF3 for relaying, will try again later
Nov 14 19:59:54 mx1 MailScanner[59936]: Cannot open /var/spool/MailScanner/milterout/4HshTQ2CzGzkkF6 for relaying, will try again later
Nov 14 19:59:54 mx1 MailScanner[58650]: Cannot open /var/spool/MailScanner/milterout/4HshTQ2GtRzkkF7 for relaying, will try again later
Nov 14 19:59:54 mx1 MailScanner[59936]: Cannot open /var/spool/MailScanner/milterout/4HshTQ2KDMzkkF8 for relaying, will try again later
For example
Code: Select all
/var/spool/MailScanner/milterout/4HshTQ2KDMzkkF8
I don't know where to head at this point to try to debug this. I know a bit how the whole system works but not too deep into the details.
Kind regards.
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
With selinux in permissive your denials can be safely ignored.
The good news is that I have some patches for some of the issues you are seeing.
Would you be willing to try out some patches? I can help you switch to the testing repo temporarily to see if it helps.
The good news is that I have some patches for some of the issues you are seeing.
Would you be willing to try out some patches? I can help you switch to the testing repo temporarily to see if it helps.
Re: Could not open file
Yes no problem.
I just need to be sure we don't lose any incoming mails while testing. Now it's a good time to do the tests (late sunday evening).
I'll do a snapshot of the VM before applying the patches.
Let me know what I should try.
I just need to be sure we don't lose any incoming mails while testing. Now it's a good time to do the tests (late sunday evening).
I'll do a snapshot of the VM before applying the patches.
Let me know what I should try.
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
Okay, let me get the test repo refreshed in the next hour or so with the patches and then I'll post instructions.
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
Testing repo is ready.
Edit /etc/yum.repos.d/eFa4.repo as follows:
Then run the following:
Edit /etc/yum.repos.d/eFa4.repo as follows:
Code: Select all
[eFa4-CentOS]
name=eFa-Project-testing
baseurl=https://dl.efa-project.org/rpm/eFa4/CentOS8/testing
mirrorlist=https://dl.efa-project.org/rpm/eFa4/CentOS8/mirrors-eFa-centos8-testing
enabled=1
Code: Select all
sudo dnf clean all
sudo dnf update
Re: Could not open file
Hello,
Thank you for the instruction.
I have a question though. It seems our install is based on Centos 7 and the url to the testing repo mention Centos8.
Is that possible that when we first installed eFa 4 it was on Centos 7 and now it is based on Centos 8 ? Will this be a problem for the testing ?
Thank you for the instruction.
I have a question though. It seems our install is based on Centos 7 and the url to the testing repo mention Centos8.
Code: Select all
[root@mx1 yum.repos.d]# cat /etc/redhat-release
CentOS Linux release 7.9.2009 (Core)
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
Oh, I'll need to update CentOS 7 with the same patches. Let me do that....
- shawniverson
- Posts: 3649
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Could not open file
For CentOS 7...
/etc/yum.repos.d/eFa.repo
/etc/yum.repos.d/eFa.repo
Code: Select all
[eFa4]
name=eFa-Project-testing
baseurl=https://dl.efa-project.org/rpm/eFa4/testing
mirrorlist=https://dl.efa-project.org/rpm/eFa4/mirrors-eFa-testing
failovermethod=priority
enabled=1
Code: Select all
sudo yum clean all
sudo yum update
Re: Could not open file
What worries me a bit:
Code: Select all
ERROR 1292 (22007) at line 46: Incorrect datetime value: '1970-01-01 00:00:01' for column ``.``.`lastsent` at row 1