efa-project.org


https://forum.efa-project.org/

Could not open file

https://forum.efa-project.org/viewtopic.php?t=4753

Page 1 of 3

Could not open file

Posted: 18 May 2021 14:38
by gvas
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?

Re: Could not open file

Posted: 18 May 2021 20:58
by shawniverson
Sounds like the message didn't get written out to the disk. How is your capacity?

Re: Could not open file

Posted: 19 May 2021 08:08
by gvas
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

Re: Could not open file

Posted: 22 May 2021 16:28
by shawniverson
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

Posted: 23 May 2021 06:10
by gvas
Is there anything I can do ; Do you need some extra info;
Please let me know.

Re: Could not open file

Posted: 23 May 2021 15:58
by gvas
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 ?

Re: Could not open file

Posted: 23 May 2021 23:07
by shawniverson
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 :lol:

Re: Could not open file

Posted: 24 May 2021 03:58
by gvas
Well I have to check it out, I have some reports of duplicate mails though.

Re: Could not open file

Posted: 01 Jun 2021 07:46
by gvas
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

Re: Could not open file

Posted: 10 Nov 2021 16:29
by r00tsh3ll
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:

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
and then

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
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

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
A whole lot of bunch per minutes...

Any idea what could be wrong ?

Cheers

Re: Could not open file

Posted: 10 Nov 2021 16:31
by r00tsh3ll
I forgot to mention that in the log of the mail that I traced I can see:

Code: Select all

"MailWatch: Logging message 4HfPky015wzMqYwP to SQL"
But when looking up for this mail ID in mailwatch interface :

Code: Select all

"Message ID '4HfPky015wzMqYwP' not found!"
Checking the db manually:

Code: Select all

MariaDB [mailscanner]> select * from maillog where id = '4HfPky015wzMqYwP';
Empty set (0.00 sec)
I guess in the log I should see a corresponging entry like:

Code: Select all

MailWatch: 4HfPky015wzMqYwP : Logged to MailWatch SQL
but it is not present

Could both be related ? I mean the entry not being added to maillog and the "Cannot open" issue ?

Re: Could not open file

Posted: 10 Nov 2021 17:02
by r00tsh3ll
Also something else I discovered.

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
This one has Unable to kick messages additionnaly to the Cannot open.

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

Posted: 10 Nov 2021 18:54
by r00tsh3ll
Sorry for the flood, but I want also to add that looking at /var/log/messages we have also a lot of:

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.
not sure if related though

Re: Could not open file

Posted: 12 Nov 2021 21:14
by shawniverson
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.

Re: Could not open file

Posted: 12 Nov 2021 21:18
by shawniverson
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

Posted: 14 Nov 2021 19:08
by r00tsh3ll
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:

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
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)

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.
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.

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
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

Code: Select all

/var/spool/MailScanner/milterout/4HshTQ2KDMzkkF8
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.

Re: Could not open file

Posted: 14 Nov 2021 20:18
by shawniverson
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.

Re: Could not open file

Posted: 14 Nov 2021 20:43
by r00tsh3ll
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.

Re: Could not open file

Posted: 14 Nov 2021 22:20
by shawniverson
Okay, let me get the test repo refreshed in the next hour or so with the patches and then I'll post instructions.

Re: Could not open file

Posted: 15 Nov 2021 03:30
by shawniverson
Testing repo is ready.

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
Then run the following:

Code: Select all

sudo dnf clean all
sudo dnf update

Re: Could not open file

Posted: 15 Nov 2021 05:14
by r00tsh3ll
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.

Code: Select all

[root@mx1 yum.repos.d]# cat /etc/redhat-release 
CentOS Linux release 7.9.2009 (Core)
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 ?

Re: Could not open file

Posted: 15 Nov 2021 05:15
by shawniverson
Oh, I'll need to update CentOS 7 with the same patches. Let me do that....

Re: Could not open file

Posted: 15 Nov 2021 05:28
by r00tsh3ll
Okay, no problem. Thanks

Re: Could not open file

Posted: 15 Nov 2021 05:33
by shawniverson
For CentOS 7...

/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

Posted: 15 Nov 2021 06:10
by r00tsh3ll
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
All times are UTC
Page 1 of 3

Powered by phpBB® Forum Software © phpBB Limited