Could not open file

General eFa discussion
r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 06:12

However,

/var/log/messages is filling with

Code: Select all

Nov 15 07:11:16 mx1 php: PHP Notice:  Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:16 mx1 php: Notice: Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:17 mx1 php: PHP Notice:  Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:17 mx1 php: Notice: Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:18 mx1 php: PHP Notice:  Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:18 mx1 php: Notice: Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:19 mx1 php: PHP Notice:  Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:19 mx1 php: Notice: Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:20 mx1 php: PHP Notice:  Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:20 mx1 php: Notice: Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:21 mx1 php: PHP Notice:  Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
Nov 15 07:11:21 mx1 php: Notice: Trying to access array offset on value of type null in /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php on line 120
edit:

Code: Select all

                            $result = dbquery("SELECT id from `maillog` where messageid='" . $message_id . "' LIMIT 1;");
                            $smtpd_id = $result->fetch_row()[0];
That would mean $result returns no ... result

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 06:51

For the PHP Notice, it seems it tries to lookup a message into table maillog using messageid column, but for some of the messages in the table, messageid is empty.

I can manually find the message in the table using the from_address, and for this message, messageid is blank.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 15 Nov 2021 11:59

Is this happening for new messages, or just messages that were previously sent through the system?

I'll update the code to watch for this condition to suppress the notices.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 15 Nov 2021 12:00

r00tsh3ll wrote:
15 Nov 2021 06:10
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
This error is benign, the DMARC schema update tries to set the default datetime. For some reason your database isn't allowing that. I'll check into it, probably a CentOS 7 quirk.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 14:56

Hello Shawn,

okay for the DMARC thing.

For the /var/log/messages mailwatch_milter_relay.php PHP notices, I think this is only for specific cases when the messageid of a message stays blank, but I guess I need to understand why.

There are a relatively a lot of entries with blank messageid and it's raising every minute.

Code: Select all

MariaDB [mailscanner]> select count(*) from maillog where messageid = '';
+----------+
| count(*) |
+----------+
|    99240 |
+----------+

MariaDB [mailscanner]> select count(*) from maillog where messageid = '';
+----------+
| count(*) |
+----------+
|    99242 |
+----------+
it's seems it's around 8-9% of the total:

Code: Select all

MariaDB [mailscanner]> select count(*) from maillog where messageid <> '';
+----------+
| count(*) |
+----------+
|  1141873 |
+----------+
Still if PHP notices would be turned off, it would be silent.

Code: Select all

                            $result = dbquery("SELECT id from `maillog` where messageid='" . $message_id . "' LIMIT 1;");
                            $smtpd_id = $result->fetch_row()[0]; <-- THIS trigger the notice because if there is no results the returned object is not an array (i guess)
                            if ($smtpd_id === null) { 
                                // Add a small delay to prevent race condition between mailwatch logger db and maillog
                                sleep(1);
                            } else {
                                break;
                            }
It also concerns new mails received post update as I backed up /var/log/maillog and truncated it, and restarted the milter_relay.service. I guess this way it only processed new mails.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 15 Nov 2021 15:24

These messages may really not have a message identifier in the header, so I think reworking the code to suppress the notices would be appropriate. The message id is used to correlate the smtp identifiers for relay statistics between postfix and the milter. It is informational only.

If you have a sample redacted header, I could confirm with you whether that is the case here.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 15:27

I temporarily 'silenced' the PHP notices by adding @'s in front of the "offending" line

Code: Select all

@$smtpd_id = $result->fetch_row()[0];
and added some debug output (echoing the message_id and loop count).

I send you a private message with the results for a message that is not found. I don't want to obfuscate data but doesn't want it to be public as it contains customers addresses.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 15:35

If you received my PM you'll see that from postfix point of view it has a message ID.

I noticed this often happens with messages from outlook.com though.

The problem is that even if we silence the notice, it will keep retrying the same message for 1 minute (60x1 second loop).
So it could delay a lot the processing other messages.

Could it be that the pattern used to detect the message id in first place doesn't match outlook (and some others) message id formatting ?

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 15 Nov 2021 18:00

This is the pattern to match the message-id:

Code: Select all

if ( $_ =~ /^message-id: (\S+)$/i ) {
   $messageid = $1;
Like you, I'm wondering if this pattern isn't matching in all cases.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 18:35

Interresting, in the headers of the message where the message id is not extracted:

Code: Select all

Message-ID: 
 <GVAP278MB0310DE2FC290B07EFC17D9BF9F989@GVAP278MB0310.CHEP278.PROD.OUTLOOK.COM>
References: 
 <0107017d233b1df7-ece4d4e1-fb2a-4ca4-9e69-c40aa4de4510-000000@eu-central-1.amazonses.com>
 <ZRAP278MB0173D46E2C469520B41312DC96989@ZRAP278MB0173.CHEP278.PROD.OUTLOOK.COM>
There is a linefeed after "Message-ID: "
The message ID is on a second line prefixed with a space.

Obviously the regex will not match this case: https://regex101.com/r/6Cf8ae/2

It seems to me it's legit and this is called long header field:
https://datatracker.ietf.org/doc/html/r ... tion-2.2.3

If I get it correctly if the next char after a line feed is a white space, it will be interpreted as a continuation of previous header line.

Isn't there libs to extract headers that already handle this ? Maybe this should be used instead of plain regex, or then we need a regex that handle both cases.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 18:54

https://metacpan.org/pod/MIME::Head#Man ... d-contents

maybe using unfold function on the headers...

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 15 Nov 2021 18:54

Yes indeed, this will be simple to resolve. Let me get this code updated to support line continuations so we can test it.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 18:58

Okay :)

By the way we are a bit out of topic of this thread that was about "Cannot open" issue, which seems to be fixed by the way. No new traces of it since the update to the test repo.

Maybe we should move all other stuff to another topic ?

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 15 Nov 2021 19:20

Okay, so for the messageid lookup "problem" by mailwatch_milter_relay.php:

The first case seems when the message id is not identified from the headers (because of the line feeds) like discussed previously.

The other case I have is because we enabled address verification in postfix:
http://www.postfix.org/ADDRESS_VERIFICATION_README.html

Code: Select all

By default, Postfix probe messages have a sender address "double-bounce@$myorigin" (with Postfix versions before 2.5, the default is "postmaster@$myorigin"). This is SAFE because the Postfix SMTP server does not reject mail for this address.
This use probes to verify is the recipient address exists in the target server and it is not logged into maillog and it never will I guess.
But this create "noise" in the logs that are catched by mailwatch_milter_relay.php.

Code: Select all

Nov 15 18:38:30 mx1 postfix/cleanup[93273]: 4HtGd26nP3zRtpQb: message-id=<4HtGd26nP3zRtpQb@mx1.xxxcom>
Nov 15 18:38:30 mx1 postfix/qmgr[92202]: 4HtGd26nP3zRtpQb: from=<double-bounce@mx1.xxx.com>, size=277, nrcpt=1 (queue active)
Nov 15 18:38:30 mx1 postfix/smtp[99679]: 4HtGd26nP3zRtpQb: to=<hello@xyz.com>, relay=mail01.xxx.com[94.xxx.xxx.xxx]:20025, delay=0.04, delays=0/0/0.03/0.01, dsn=2.0.0, status=deliverable (250 OK <hello@xyz.com> Recipient ok)
Nov 15 18:38:30 mx1 postfix/qmgr[92202]: 4HtGd26nP3zRtpQb: removed
I have to find a way for mailwatch_milter_relay.php to just ignore them.

But this is a bit specific for our setup, unless other E.F.A. users are also using address verification.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 16 Nov 2021 00:50

Got some time to work on this. Actually both are real issues, so let me study this. The first one I'll get patched first so you can see how it goes.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 16 Nov 2021 01:39

Clear your repos and update to get this the fix for the first one:

Code: Select all

sudo yum clean all
sudo yum update

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 16 Nov 2021 03:50

Hey. Thanks. Update done. I'll let you know how it's going now with the multiline headers.

For the 2nd case on my side, i've patched a bit the php file to skip processing the log entry if the message-id contains our e.f.a server name (myorigin).

I noticed that the probes/bounces were using locally generated message-id and figured out it could be a way to ignore them.
Not sure it's the best option here but at least it seems to work.

The best would be to get MYORIGIN from the postfix config but for my testing i set it hard in the file.
If you want to see the changes I currently have here is a patch against the dist php file.

Code: Select all

[root@mx1 sriccio]# diff /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php mailwatch_milter_relay.php 
44c44,46
< define('QUERYTIMEOUT', '60');
---
> define('QUERYTIMEOUT', '10');
> 
> define('MYORIGIN', 'mx1.swisscenter.com');
56a59,62
>             if (preg_match('/@' . MYORIGIN . '/', $message_id)) {
>               echo "DEBUG: (doit) Skipping " . $message_id . "\n";
>               continue;
>             }
58c64
<             $smtpd_id = $result->fetch_row()[0];
---
>             @$smtpd_id = $result->fetch_row()[0];
86a93,97
>                 $message_id = safe_value($explode[2]);
>                 if (preg_match('/@' . MYORIGIN . '/', $message_id)) {
>                     echo "DEBUG: (follow) Skipping " . $message_id . "\n";
>                     continue;
>                 }
118a130
>                             echo "DEBUG: message_id " . $message_id . " Loop count: " . $j . "\n";
120c132
<                             $smtpd_id = $result->fetch_row()[0];
---
>                             @$smtpd_id = $result->fetch_row()[0];
128a141
>                             echo "DEBUG: message_id " . $message_id . " Found match!\n";

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 16 Nov 2021 04:00

Hmm after the update and restart, the issue still persists.

Code: Select all

MariaDB [mailscanner]> select messageid from maillog where id = '4HtXLp6B7jzVj4M6';
+-----------+
| messageid |
+-----------+
|           |
+-----------+
That's a post-update processed message.

In which file is the message-id extraction logic so I can check how we're doing it now ?

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 16 Nov 2021 04:35

While we're at it, let me share another "issue" that I thihnk I've discovered with mailwatch_milter_relay.php.

I'll try to explain it the best I can:

Let's say an external mail is received and that mail has multiple recipients. I.E. user1@domainone.com, user2@domainone.com, user@domaintwo.com.
E.F.A is the MX for domainone.com and domaintwo.com.

The mail is then splitted in 3 different mails, one for each recipient.
Each mail resulting from the split is processed by MailScanner then relayed to the target server.

It will create in maillog an entry for each mail with their own different postfix ID.
Until here no problem.

Except that for these 3 entries in maillog the "messageid" is the same as it is the same mail.

Now, mailwatch_milter_relay.php will catch the infos for each of the 3 delivered mails and look it up in maillog using "messageid" (limit 1).

It will then associate ALL 3 relaying information (via mtalog_ids) to the first maillog entry it founds with the corresponding "messageid"

So one of the maillog entry will have the 3 relaying info attached and the other maillog entries will have no relaying information.

At this point I have no idea how to fix this as we only rely on "messageid" which alone is not enough to differentiate the corresponding maillog entry.

I think the splitting is required for some stuff to work correctly but can't remember exactly, and is set with default_destination_recipient_limit = 1
http://www.postfix.org/postconf.5.html# ... ient_limit

In a wonderful world it would associate each relay info to it's corresponding maillog entry :)

I'm not sure I'm explaining the issue well...

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 16 Nov 2021 14:44

r00tsh3ll wrote:
16 Nov 2021 04:00
In which file is the message-id extraction logic so I can check how we're doing it now ?
I must have pushed the update out without the code change. Let me double check. I just noticed the changes weren't present on my host either.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 16 Nov 2021 14:47

r00tsh3ll wrote:
16 Nov 2021 04:35
In a wonderful world it would associate each relay info to it's corresponding maillog entry :)

I'm not sure I'm explaining the issue well...
This is a good explanation, and yes, this is another issue. It appears that in addition to the message-id I am going to need to find a way to capture the recipients individually as well to differentiate the individual message deliveries.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 17 Nov 2021 13:56

Got the testing repo updated properly. You should be able to test again. Still work to do, but this will have the unfolding logic.

Before you run the update, back up your customizations to /usr/share/MailScanner/perl/custom/MailWatch.pm

Code: Select all

sudo yum clean all
sudo yum update

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 18 Nov 2021 17:02

Hello Shawn,

Thank you for the repo update. I can see the unfolding logic in MailWatch.pm but unfortunately it doesn't seems to catch the folded message-id.

I had not much time past days to take a deeper look but I'll add some debug output to it tomorrow to understand why it's not working.

Kind regards.

User avatar
shawniverson
Posts: 3525
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Could not open file

Post by shawniverson » 18 Nov 2021 20:18

I did see a tiny thing I should tweak in the unfolding that may help. I need to use \s instead of a literal space for any unfolding and string matching in the lines, so I will adjust that and update it as well.

r00tsh3ll
Posts: 30
Joined: 14 Feb 2021 06:34

Re: Could not open file

Post by r00tsh3ll » 20 Nov 2021 19:46

Hello shawn, a bit out of topic question but, how do we disable auto-update ? IIRC there was an option in the admin menu but it seems to be gone.
I don't mind auto updates when using the production repo, but as we are currently on the testing repo while we sort some things out, I prefer to be around when an update is done :)

Thanks

Post Reply