MailWatch stopped logging in to MySQL

[branko77]

Today my MailWatch just stopped logging in to MySQL. Last Message that has been logged was few hours ago. My postfix is working fine and I can send and receive messages. I received few of messages with this text: "MailScanner was attacked by a Denial Of Service attack, and has therefore deleted this part of the message. Please contact your e-mail providers for more information if you need it, giving them the whole of this report. Attack in: /var/spool/MailScanner/incoming/36423/4335498CC.AB426/nmsg-36423-81.html " After reboot of my server my NAGIOS is reporting that Clamd is critical with error "connect to address 127.0.0.1 and port 3310: Connection refused" When I check MySQL I can see that last message was logged few hours ago and that is not logging. maillog reports that MailWatch: Logging message 5D18798D8.A7796 to SQL but no logged message i maillog. I didn't made any changes what so ever...

[stefaweb]

What do you have in /etc/hosts ?

[branko77]

127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4 ::1 localhost localhost.localdomain localhost6 localhost6.localdomain6 192.168.2.1 fqdn.my.domain hostname 192.168.3.1 fqdn.my.domain hostname multi on

[stefaweb]

Try with:

127.0.0.1 localhost 192.168.2.1 fqdn.my.domain hostname 192.168.3.1 fqdn.my.domain hostname2 ::1 localhost ip6-localhost ip6-loopback ff02::1 ip6-allnodes ff02::2 ip6-allrouters

[mmgomess]

Sorry friends but i don´t know what is wrong. I did make all changes but MailWatch is still stopping.

Can anyone do something like a step by step tutorial please?

2017-01-31 8:36 GMT-02:00 branko77 notifications@github.com:

127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4 ::1 localhost localhost.localdomain localhost6 localhost6.localdomain6 192.168.2.1 fqdn.my.domain hostname 192.168.3.1 fqdn.my.domain hostname multi on

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/mailwatch/1.2.0/issues/430#issuecomment-276329311, or mute the thread https://github.com/notifications/unsubscribe-auth/AJSnkyLBLsaJR97NapCOYtV-hOv0BfJiks5rXw65gaJpZM4Lq9fW .

[branko77]

nope... same thing after changes :(

[stefaweb]

And the result for this:

netstat -an | grep 127.0.0.1 | grep 11553

I got:

tcp 0 0 127.0.0.1:11553 0.0.0.0:* LISTEN tcp 1 0 127.0.0.1:11553 127.0.0.1:45830 CLOSE_WAIT

[branko77]

I got:

tcp 0 0 127.0.0.1:11553 0.0.0.0:* LISTEN

[branko77]

Ok, now it is working. I changed line 56 and put 192.168.3.1 instead 127.0.0.1

my $loop = inet_aton("192.168.3.1");

Now I will try with that subject that crashed MailWatch

[branko77]

Ok, now it not crashing but MailWatch didn't logged that message with "crashing" subject. I received it but MailWatch ignored it. Is that ok?

[branko77]

It still working but i got on my CLI this:

Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x92\x98\xC2\xA0...' for column 'subject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 182, <CLIENT> line 697. ) at /usr/share/MailScanner/perl/MailScanner/Config.pm line 1053.

[branko77]

Now I am confused... Is this working or not? I mean it is working but should I expect crash and Denial of Service message again or not? Any other way to test it except that "crashing" subject with heart emoticon?

[Skywalker-11]

Is only MailWatch ignoring that mail or is mailscanner too?

To test you could attach an eicar file. If the mail gets through with the attachment that would be a serious problem.

[branko77]

I tried with eicar message and MailScanner and MailWatch deteted it and that works fine. But I tried once again with "crash" subject and same thing, I received it but no log in MW

This is from my maillog:

Jan 31 12:49:44 mailsek postfix/qmgr[7401]: 568841535A: from=xxxxxx@mydomain.tld, size=2815, nrcpt=1 (queue active) Jan 31 12:49:44 mailsek MailScanner[9673]: Deleted 1 messages from processing-database Jan 31 12:49:44 mailsek MailScanner[9673]: MailWatch: Logging message 7909615359.ABE55 to SQL Jan 31 12:49:45 mailsek postfix/pickup[13425]: 317B215359: uid=1002 from=xxxxxx@mydomain.tld Jan 31 12:49:45 mailsek postfix/cleanup[15282]: 317B215359: hold: header Received: by mailsek.ingkomora.rs (Postfix, from userid 1002)??id 317B215359; Tue, 31 Jan 2017 12:49:45 +0100 (CET) from local; from=xxxxxx@mydomain.tld to=yyyyyy@mydomain.tld Jan 31 12:49:45 mailsek postfix/cleanup[15282]: 317B215359: message-id=090b01d27bb8$11a12ca0$34e385e0$@rs Jan 31 12:49:45 mailsek postfix/pipe[15361]: 568841535A: to=yyyyyy@mydomain.tld, relay=spamassassin, delay=15, delays=14/0/0/0.75, dsn=2.0.0, status=sent (delivered via spamassassin service) Jan 31 12:49:45 mailsek postfix/qmgr[7401]: 568841535A: removed

[endelwar]

This time its not a emoji but a umlaut (äüö) in the subject problem, not with all mails just with this one which looks like coming in ANSI encoded.

@spec1re and @branko77 could you test the "crash subject" by removing the fix_latin from line 288 of MailWatch.pm, so that the line reads $msg{subject} = $message->{utf8subject};?

[spec1re]

@endelwar - Haha, that's funny it looks like we are on the same track, did exactly what you suggested 2h before and sadly still crashing.

I suspect DBD::mysql or MailScanner v4 is bugged somehow. Next thing which I will try is to install MS v5 and see it it will make a difference.

The problem is, email files which are in "Code Page 1252 Windows Latin 1 (ANSI)" encoded.

[branko77]

Same thing, MailWatch ignored it but I recieved "crasch subject" message and also got warning on my CLI: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x92\x98\xC2\xA0...' for column 'subject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 182, <CLIENT> line 310. ) at /usr/share/MailScanner/perl/MailScanner/Config.pm line 1053.

Note: In new MailWatch.pm the "....fix_latin....." line is 332 no 288.

[stefaweb]

Don't change fix_latin. I already tried. You broke char set storage in the database.

[branko77]

I already tried that and changed back again...

[branko77]

For now no crash.

[geeknocity]

I feel like this bug is a two different bugs now? It started as MailWatch stopped logging emails to the DB, and is ending based on a subject that you are sending through? Is that correct or are they actually connected? Either way, I still have to kill mailscanner manually at least once a day. Thanks for the help/direction.

[branko77]

Subject sent through makes MailWatch stop logging in to the db so they are connected.

[spec1re]

@jch2os14 - MailWatch stopped logging emails to the DB because of malformed subjects, so yes its connected. Just go thru your mailogs and you will find lines like this:

Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x92\x98\xC2\xA0...' for column 'subject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 182, <CLIENT> line 310. ) at /usr/share/MailScanner/perl/MailScanner/Config.pm line 1053.

[geeknocity]

What logs? I searched /var/log/mail.log(and all previous versions) and that did not come up.

[spec1re]

So MailWatch stops logging in to MySQL or not?

[spec1re]

It looks like, in my case, not the subject itself is crashing MailWatchLogging rather the encoding of the whole mail file.

[branko77]

So MailWatch stops logging in to MySQL or not?

So far so good... But I had issues once or twice in a scope of 24 hours, so I want to wait, lets say at least one more day, to confirm it.

[geeknocity]

I found the error in my syslog! What can I do to help?

mail.log.1:Jan 29 16:18:44 mailscanner MailScanner[738]: Could not use Custom Fu nction code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "ev al"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st exec ute failed: Incorrect string value: '\xF0\x9F\x98\x8A\xF0\x9F...' for column 'su bject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 169, line 573.

[branko77]

So far so good... But I had issues once or twice in a scope of 24 hours, so I want to wait, lets say at least one more day, to confirm it.

No, it's crashed again few minute ago. again with a :"Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x9A\x98 \xF0...' for column 'subject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 182, line 614. ) at /usr/share/MailScanner/perl/MailScanner/Config.pm line 1053."

[spec1re]

@jch2os14 & @branko77 - Check the mail which caused this crash, if it has emojis in the subject and what the encoding of the mail file is.

[branko77]

I found message in my maillog. It is advertisement message (I suppose with a bunch of images, links and so on), but it never been delivered to user mailbox. This is from maillog:

EA3D01534C: client=smtp.outgoing.loopia.se[194.9.94.113] Jan 31 15:09:50 hostname postfix/cleanup[36466]: EA3D01534C: hold: header Received: from smtp.outgoing.loopia.se (smtp.outgoing.loopia.se [194.9.94.113])??by mailsek.ingkomora.rs (Postfix) with ESMTP id EA3D01534C??for xxxxxx@mydomain.tld; Tue, 31 Jan 2017 15 from smtp.outgoing.loopia.se[194.9.94.113]; from=prodaja@advertising.networkmedia.rs to=xxxxxx@mydomain.tld proto=ESMTP helo= Jan 31 15:09:50 hostname postfix/cleanup[36466]: EA3D01534C: message-id=f296c796a0da4d321c17dc555c5f23c8@advertising.networkmedia.rs Jan 31 15:09:50 hostname postfix/smtpd[36463]: disconnect from smtp.outgoing.loopia.se[194.9.94.113] Jan 31 15:09:50 hostname MailScanner[19183]: New Batch: Scanning 1 messages, 2356599 bytes Jan 31 15:09:51 hostname MailScanner[19183]: Virus and Content Scanning: Starting Jan 31 15:10:04 hostname MailScanner[19183]: Spam Checks: Found 1 spam messages Jan 31 15:10:04 hostname MailScanner[19183]: Deleted 1 messages from processing-database Jan 31 15:10:04 hostname MailScanner[19183]: MailWatch: Logging message EA3D01534C.AF250 to SQL Jan 31 15:10:04 hostname MailScanner[36543]: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x9A\x98 \xF0...' for column 'subject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 182, line 82.

[spec1re]

@branko77 - You can enable subject loggin in postfix, by adding

# Log Subject Lines in Postfix
/^Subject:/ WARN 

header_checks config and reload postfix.

[endelwar]

Jan 31 15:10:04 hostname MailScanner[36543]: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x9A\x98 \xF0...' for column 'subject' at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 182, line 82.

@branko77 \xF0\x9F\x9A\x98 is an emoji (a car emoji 🚘). Can you check that the subject field in maillog table is utf8mb4_unicode_ci? It's a 4 byte char and will never be inserted correctly if the field is not in this encoding.

[spec1re]

Any idea how this works in postfix.pm?

    # Decode ISO subject lines into UTF8
    # Needed for UTF8 support in MailWatch 2.0
    eval {
     $message->{utf8subject} = Encode::decode('MIME-Header',
                                              $message->{subject});
    };
    if ($@) {
     # Eval failed - store a copy of the subject before MIME::WordDecoder
     # is run, as this appears to destroy the characters of some subjects
     $message->{utf8subject} = $message->{subject};
    }

    # Decode the ISO encoded Subject line
    # Over-ride the default default character set handler so it does it
    # much better than the MIME-tools default handling.
    MIME::WordDecoder->default->handler('*' => \&MailScanner::Message::WordDecoderKeep7Bit);
    my $TmpSubject = MIME::WordDecoder::unmime($message->{subject});
    if ($TmpSubject ne $message->{subject}) {
      # The unmime function dealt with an encoded subject, as it did
      # something. Allow up to 10 trailing spaces so that SweepContent
      # is more kind to us and doesn't go and replace the whole subject,
      # thinking that it is malicious. Total replacement and hence
      # destruction of unicode subjects is rather harsh when we are just
      # talking about a few spaces.
      $TmpSubject =~ s/ {1,10}$//;
      $message->{subject} = $TmpSubject;

Is there anything similar in MailWatch?

[branko77]

@endelwar

Can you check that the subject filed in maillog table is utf8mb4_unicode_ci? It's a 4 byte char and will never be inserted correctly if the field is not in this encoding.

No, it is utf8_general_ci. Should I change it to utf8mb4_general_ci? Should I change only subject field or some other fields as well? Can I do it through phpMyAdmin (I know it is possible but is it ok to do it in that way)?

[stefaweb]

You should have utf8mb4_general_ci everywhere. database tables columns MailWatch.pm

[endelwar]

You should have utf8mb4_general_ci everywhere.

actually should be utf8mb4_unicode_ci

[branko77]

actually should be utf8mb4_unicode_ci

I just changed all collation to actually should be utf8mb4_unicode_ci in mailscanner db and restarted MailWatch. Now I am waiting to see whether is going to work or crash again. I didn't changed anything in MailWatch.pm. I saw "utf8mb4" already present in a few code lines.

[endelwar]

in MailWatch.pm. I saw "utf8mb4" already present in a few code lines

beware that you're using a yet-to-be-reviewed code

[branko77]

beware that you're using a yet-to-be-reviewed code

One of reasons I didn't want to change it... For now it is ok. Should I try to send email containing emoticons in subject in order to test it?

[branko77]

Ok I tested it from yahoo to my email server with a bunch of emoticons and it went well I even have it in my recent messaged view on MailWatch web gui.

[spec1re]

I found a dirty workaround for the ANSI Subject crash, I just strip all CP1252 encoded umlauts out of the subject via postfix header_checks. This works well and for my surprising, postfix will encode the mail file from ANSI to UTF-8.

So at the moment MailWatch doesn't goes down anymore.

[geeknocity]

Branko77, So in the end what fixed it for you was changing settings in MySQL?

On Feb 1, 2017 5:27 AM, "branko77" notifications@github.com wrote:

Ok I tested it from yahoo to my email server with a bunch of emoticons and it went well I even have it in my recent messaged view on MailWatch web gui.

[image: untitled] https://cloud.githubusercontent.com/assets/24565680/22503309/6e4dff34-e871-11e6-9a03-01b91e694fa3.png

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/mailwatch/1.2.0/issues/430#issuecomment-276623108, or mute the thread https://github.com/notifications/unsubscribe-auth/AWZB5YXtviIv2rz3RWxxZ2odomybW7-vks5rYF4mgaJpZM4Lq9fW .

[branko77]

@jch2os14 I suppose it does, but I want to wait for another, lets say 24 hours, just to be sure. In the meanwhile I tried with several other messages with emoticons and Cyrillic subjects and it was all well displayed in Mailwatch web GUI. MySQL logged those messages and I received them properly. Anyway, I will let you all know about how it works and if I have (hopefully not) any other problems.

One more PrtScr

[geeknocity]

Spec1re, Can you show me what you did in postfix?

Thanks

On Feb 1, 2017 6:11 AM, "branko77" notifications@github.com wrote:

@jch2os14 https://github.com/jch2os14 I suppose it does, but I want to wait for another, lets say 24 hours, just to be sure. In the meanwhile I tried with several other messages with emoticons and Cyrillic subjects and it was all well displayed in Mailwatch web GUI. MySQL logged those messages and I received them properly. Anyway, I will let you all know about how it works and if I have (hopefully not) any other problems.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/mailwatch/1.2.0/issues/430#issuecomment-276631846, or mute the thread https://github.com/notifications/unsubscribe-auth/AWZB5R_1BM971DyRULlUPkXzWRCqt6inks5rYGhdgaJpZM4Lq9fW .

[spec1re]

Sure, but first you need to collect a few mails with those crashing subjects, in my case it was the ANSI encoded umlauts like:

xFC = ü

and as you can see in the error message:

Error: DBD::mysql::st execute failed: Incorrect string value: '\xFCberne...' for column 'headers'

so now we write a header_checks rule:

if /^Subject: Some Unique Pharse/
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4} ${5} ${6} ${7} ${8} ${9} ${10}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4} ${5} ${6} ${7} ${8} ${9}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4} ${5} ${6} ${7} ${8}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4} ${5} ${6} ${7}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4} ${5} ${6}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4} ${5}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3} ${4}
/^(.*?)[^\x00-\x80]+(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2} ${3}
/^(.*?)[^\x00-\x80]+(.*)$/ REPLACE ${1} ${2}
endif 

Be careful if you regex pattern is a bit to easy, it will replace all special characters from any mail which could be a problem with legit mails.

[geeknocity]

OH wow. Ok. I was thinking it was something that would encode every email, not just looking for certain characters. Maybe I'll wait until the official fix! :)

[spec1re]

@stefaweb

http://www.perlmonks.org/?node_id=745506

The point is that perl still uses a single byte internally for characters in the original the Latin-1 range (from iso-8859-1), and even when perl has flagged a latin-1 string as being utf8 data, you should "encode" it into an external (true multibyte) form before sending it to the database.

Does MailWatchLogging encode non UTF-8 data, before sending it to the database?

[stefaweb]

I think so. See https://github.com/mailwatch/1.2.0/issues/430#issuecomment-275918702

Line 266 in MailWatch.pm: $msg{subject} = fix_latin($message->{utf8subject});

[spec1re]

DBD::mysql::st execute failed: Incorrect string value: '\xFCberne...' for column 'headers' at row 1 at

Looks like your input data isn't really in UTF-8 encoding... In UTF-8, \xED would start a multibyte sequence, which may not be followed by 'n' (i.e. \x6E, a byte without the 8th/high bit set), as it is here. This is simply invalid UTF-8 encoding, which is presumably why MySql complains.

We have here somehow invalid UTF-8 encoding?

[branko77]

I can say that today, after I set whole db to utf8mb4_unicode_ci, didn't experienced any problem. And my users received few emails contain emos in subject which crashed MySQL logging before encoding changes. MailWatch works for 5 hours now without any problem and it has processed about 900 messages so far.