Postal is somehow missing headers on some received mails (and marking them as spam)

[boindil]

Describe the bug

Some mails are missing headers in the header tab, while they are present in the eml, that can be downloaded from postal. This is somehow even affecting the spam-check.

I believe, that this has something to do with the field X-Google-DKIM-Signature where somehow content seems to be missing / an out of place newline. Just dont know whether its something on googles side or on postals side.

To Reproduce

Send a few mails to postal. We used gmail.

Expected behaviour

Headers not missing, mail not marked as SPAM

Screenshots

Environment details

Postal 2.0.0

[willpower232]

Its working for me in Postal V1 but it doesn't have that extra newline, are you still able to reproduce this?

[boindil]

Hi @willpower232, sorry this response took me so long. I've been covered with other stuff this whole time ...

Yes this is still happening, no I have no way to reproduce it. It's simply happening (I think about 1% of the mails and as of now only gmail).

[boindil]

Even worse: we had a case yesterday where this lead to the messageid missing in the mailsystem that we are forwarding to. This time it was not detected as spam ... see for yourself ...

Yes, postal is great, but loosing messages is not so much fun. Yes you can see them in the postal UI, but as long as one doesn't know about missing mails ... really bad! Before using postal, this was no problem (and yes it really wasn't), these examples are from colleagues sending mails to their work mailbox.

[boindil]

just in case: this is our full postal.yml

general:
  # This can be changed to allow messages to be sent from multiple IP addresses
  use_ip_pools: true

web:
  # The host that the management interface will be available on
  host: postal.mail.domain
  # The protocol that requests to the management interface should happen on
  protocol: https

web_server:
  # Specify configuration for the Postal web server
  bind_address: 127.0.0.1
  port: 5000

smtp_server:
  # Specify configuration to the Postal SMTP server
  port: 25
  tls_enabled: true
  tls_certificate_path: /config/mail.domain.crt
  tls_private_key_path: /config/mail.domain.key
  tls_ciphers: ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES$
  max_message_size: 50

logging:
  # Specify options for the logging
  stdout: true

main_db:
  # Specify the connection details for your MySQL database
  host: 127.0.0.1
  username: postal
  password: 
  database: postal

message_db:
  # Specify the connection details for your MySQL server that will be house the
  # message databases for mail servers.
  host: 127.0.0.1
  username: postal
  password:
  prefix: postal

rabbitmq:
  # Specify connection details for your RabbitMQ server
  host: 127.0.0.1
  username: postal
  password: 
  vhost: postal

dns:
  # Specify the DNS records that you have configured. Refer to the documentation at
  # https://github.com/atech/postal/wiki/Domains-&-DNS-Configuration for further
  # information about these.
  mx_records:
    - mail.domain
  smtp_server_hostname: mail.domain
  spf_include: spf.mail.domain
  return_path: rp.mail.domain
  route_domain: plesk.mail.domain
  track_domain: cl.mail.domain

smtp:
  # Specify an SMTP server that can be used to send messages from the Postal management
  # system to users. You can configure this to use a Postal mail server once the
  # your installation has been set up.
  host: 127.0.0.1
  port: 2525
  username: # Complete when Postal is running and you can
  password: # generate the credentials within the interface.
  from_name: noreply
  from_address: noreply@domain

rails:
  # This is generated automatically by the config initialization. It should be a random
  # string unique to your installation.
  secret_key: 

spamd:
  enabled: true
  host: 127.0.0.1
  port: 783

clamav:
  enabled: true
  host: 127.0.0.1
  port: 3310

[Csardelacal]

Hey there,

I seem to be having the same issue, but with a slight twist. We started using Freshdesk for our support inbox and we started seeing a bunch of very weird emails coming in.

We have an address endpoint that we got from Freshdesk to redirect our email to. So far, this works flawlessly, except for emails from GMail (but not all of them). This is what arrives on the Freshdesk end:

When clicking on the sender I get j4q0qp@psrp.ourdomain.com. So I'm certain that the email got routed through Postal. And when I click on the message I get the raw payload for the message, which incidentally begins with:

X-Gm-Message-State: AOAM5337hJxJkHq5IcUajB3WbteNp12EcmEMiguppQLi6FG8jgz8TzgG
    mV7qPdAU7G1pHmteJhZ51EJG0gwtdX6Ef2H4PoVhoGMs1to=
X-Google-Smtp-Source: ABdhPJzdGihJNXK1xY62ruEfNmroF9bG64AHQSzGIXo4RusL4Ci0+VgLLmvl+6XXvB2aPvRD4m/jqAZsN1HvXFCB7xU=
X-Received: by 2002:a17:907:60c9:: with SMTP id hv9mr34603581ejc.334.1635940921262;
 Wed, 03 Nov 2021 05:02:01 -0700 (PDT)
MIME-Version: 1.0
From: <<removed>>
Date: Wed, 3 Nov 2021 07:01:46 -0500
Message-ID: <<<removed>>@mail.gmail.com>

The first (X-Gm-Message-State) is the header that @boindil has right after his broken header. On my Server the email does not appear among the incoming emails for the server. Is there anything I can do to help diagnose the issue?

Also notable: The psrp for ALL of these broken messages is the same address (j4q0qp).

Edit: Just stopping spamassasin lead to new messages appearing in the incoming tab (although broken). Disabling spamd in the config resolves the issue in my case, but obviously disables any spam checking. Also, this only happened on gmail.com and not on our gsuite email.

Edit 2: Even with spamassassin disabled, some of the mails are getting messed up when we receive them the headers and both bodies will be in the plain text version. They are still showing up in the UI though, so that's good.

[Wouter0100]

I found what is happening here: Postal is splitting the message in 2 raw parts: header and body. This is happening incorrectly, as it seems part of the header is in the body. I have had this happen to me as well just today.

The new line in the initial issue (X-Google-DKIM-Signature) is from the fact that Postal adds a new line between the header and body, when stitching them back together. This breaks everything.

In my case it's the ARC-Message-Signature header being split, and it is coming a Yahoo recipient. Although, we proxy all our e-mails through Google (as Google is running on our MX, we use Recipient Address Maps in Gmail to forward incoming e-mails to a Routing route's e-mail address in Postal).

One interesting thing I'm seeing is that it's always the last line of a multi-line header (at least, it's the case with me and with the person reporting the issue):

Here the output of a MySQL query that shows the split in the 2 different rows within the raw-table (1162 is the raw body ID):

I had this on Postal 2.1.2. Logs of smtp:

[9] [2022-09-13T07:32:24.126] DEBUG -- : [CUEUUF]    Client identified as 209.85.210.198
[9] [2022-09-13T07:32:24.126] DEBUG -- : [CUEUUF] => 220 x ESMTP Postal/CUEUUF
[9] [2022-09-13T07:32:24.261] DEBUG -- : [CUEUUF] <= EHLO mail-pf1-f198.google.com
[9] [2022-09-13T07:32:24.271] DEBUG -- : [CUEUUF] => 250-My capabilities are
[9] [2022-09-13T07:32:24.271] DEBUG -- : [CUEUUF] => 250-STARTTLS
[9] [2022-09-13T07:32:24.271] DEBUG -- : [CUEUUF] => 250 AUTH CRAM-MD5 PLAIN LOGIN
[9] [2022-09-13T07:32:24.434] DEBUG -- : [CUEUUF] <= STARTTLS
[9] [2022-09-13T07:32:24.434] DEBUG -- : [CUEUUF] => 220 Ready to start TLS
[9] [2022-09-13T07:32:24.725] DEBUG -- : [CUEUUF] <= EHLO mail-pf1-f198.google.com
[9] [2022-09-13T07:32:24.727] DEBUG -- : [CUEUUF] => 250-My capabilities are
[9] [2022-09-13T07:32:24.727] DEBUG -- : [CUEUUF] => 250 AUTH CRAM-MD5 PLAIN LOGIN
[9] [2022-09-13T07:32:24.880] DEBUG -- : [CUEUUF] <= MAIL FROM:<x@yahoo.com>
[9] [2022-09-13T07:32:24.881] DEBUG -- : [CUEUUF] => 250 OK
[9] [2022-09-13T07:32:25.016] DEBUG -- : [CUEUUF] <= RCPT TO:<x@x>
[9] [2022-09-13T07:32:25.062] DEBUG -- : [CUEUUF] Added route 20 to recipients (tag: nil)
[9] [2022-09-13T07:32:25.065] DEBUG -- : [CUEUUF] => 250 OK
[9] [2022-09-13T07:32:25.201] DEBUG -- : [CUEUUF] <= DATA
[9] [2022-09-13T07:32:25.202] DEBUG -- : [CUEUUF] => 354 Go ahead
[9] [2022-09-13T07:32:25.339] DEBUG -- : [CUEUUF] <= Received: by mail-pf1-f198.google.com with SMTP id n18-20020a056a000d5200b0053e16046751so6868238pfv.7
[9] [2022-09-13T07:32:25.339] DEBUG -- : [CUEUUF] Not logging further message data.
[9] [2022-09-13T07:32:25.576] DEBUG -- : [CUEUUF] => 250 OK
[9] [2022-09-13T07:32:56.743] DEBUG -- : [CUEUUF] <= QUIT
[9] [2022-09-13T07:32:56.744] DEBUG -- : [CUEUUF] => 221 Closing Connection
[9] [2022-09-13T07:32:56.744] DEBUG -- : [CUEUUF]    Connection closed

@willpower232 do you have any idea? I don't see how this line could cause this, only if, due to an error, somehow elsewhere a new line is added within the header.

[Wouter0100]

Just to continue on the topic above, I'm unable to further investigate the issue rn. I have:

• Enabled SMTP data logging on this specific email server within Postal.
• Send a copy of each email to a seperate inbox before it is send to Postal.

With these 2 measures I'm hopefully able to see what emails will get stuck and determine their exact raw message before it reaches Postal.

edit: Nevermind, the SMTP data logging is not working for routing routes. So only the second measure in place currently to hopefully debug this issue better.

[Wouter0100]

Interestingly enough it seem to start happening more and more often. Could be that we recently onboarded a customer with a lot more variation in their e-mailing, not sure.

Regardless, we already had a sample from which we received a copy e-mail. Right now it wasn't before the end of a multi-line header and it was in the X-SONIC-DKIM-SIGN header. So it seems.. right. Random. There seems to be no correlation in when the new line occurs between lines, nr. of chars or whatever.

Left the one copy we received on another server, right how Postal spits out the body+header. As you're able to see, just a normal enter. No line that's missing or whatever.

Also checked, all line-endings are 0x0a 0x20 in the copy - meaning there is also no difference between the line endings (new line + space). Although, our mailserver may normalize this as well - of course. In the download from Postal the copied line ending is 0x0d 0x0a 0x0d 0x0a 0x20, which corresponds with the code making line endings \r\n here.

It seems like we're, for whatever reason, iterating twice over this without new data being present.

I made a patch to forcefully enable SMTP data logging on an incoming route, let's see what kind of logs we get.

[Wouter0100]

I was able to reproduce it with my own emailing. Let's get debugging!

Right.. I found that the new line happens in between 2 buffers and the new line happens on the beginning of a new buffer. Could it be that the buffer is ending in between a \r\n, which causes a new line twice because of this normalize step? One \r in the ending buffer, and one \n in the new buffer.

This peace of ruby:

test = "--\r--".encode("BINARY", universal_newline: true).encode("BINARY", crlf_newline: true)
test1 = "--\n--".encode("BINARY", universal_newline: true).encode("BINARY", crlf_newline: true)
puts "Hello, ==#{test}==#{test1}==!";

Results in:

Hello, ==--

--==--

--==!

So this could very well be the case, as in this case the new lines are thus handled twice.

@willpower232 do you have an idea on how to solve this? It's a little more difficult then just removing one new line and I don't have so much experience with mail servers nor Ruby, unfortunately.

For now I replaced .encode("BINARY", universal_newline: true) with .gsub(/\r/,"") as an "solution" and will also purpose this, meaning: we will ignore all \r and convert \n into \r\n because only \r seems never valid for an enter.