search

Z-Hub / Z-Push

Home of Z-Push
https://z-push.org
GNU Affero General Public License v3.0
97 stars 47 forks source link

error sending mail: corrupt headers #24

Closed michlann closed 1 year ago

michlann commented 1 year ago

Hello, I have identified what I believe is a compatibility problem with php8, in the usage of PHP's mail() function. I was using the IMAP backend, configured to use mail() to send messages received from clients. This used to work without problems. Some months ago the mails created this way started to be corrupt, more precisely MIME headers were corrupted in a way that the MIME structure would be displayed as text by mail readers. Analyzing the raw mail source, it turns out some header lines had an additional space character added in front, i.e. they would not be recognised anymore by the mail reader. Debugging Z-Push, it turns out the mails are perfectly fine until handed over to the sending function, in my case mail(). Switching to smtp method is my current workaround. According to this discussion, the adding of spaces in front of headers seems related to changes in PHP8's mail(), potentially related to CR/LF translation. I have not taken the time to debug this further within mail(), but as-is, Z-Push is not able to send correct mails using the mail() sending method. Hence this should be addressed one way or another. This issue serves also to document the problem and my workaround. Environment:

Thanks!

matidau commented 1 year ago

Hi @michlann,

Are you able to provide more details? I'm unable to replicate with the IMAP backend and my hunt through the code is pointing to the use of \r\n for mail. Happy to be proven wrong just not sure what I can check here to get to the bottom of it.

Cheers, Mat

michlann commented 1 year ago

Hello @matidau,

Happy to provide whatever I can to help... but not sure what indeed helps.

I can show that within Z-Push, there is no problem visible. This is from WBXML debug:

Incoming mail: --------------------log-------------------------------

06/08/2023 12:21:14 [366328] [DEBUG] -------- Start
06/08/2023 12:21:14 [366328] [DEBUG] cmd='SendMail' devType='iPad' devId='12345678' getUser='bla@bla.bla' from='85.93.123.123' version='2.6.4+0-0' method='POST'
06/08/2023 12:21:14 [366328] [DEBUG] Used timezone 'Europe/Luxembourg'
06/08/2023 12:21:14 [366328] [ INFO] BackendIMAP(): Using UTF-8 as Default Charset for Searches
06/08/2023 12:21:14 [366328] [DEBUG] Request::ProcessHeaders() ASVersion: 14.0
06/08/2023 12:21:14 [366328] [DEBUG] ZPush::CommandNeedsAuthentication(1): true
06/08/2023 12:21:14 [366328] [DEBUG] BackendIMAP->Logon(): User 'bla@bla.bla' is authenticated on '{localhost:143/imap/notls/norsh}'
06/08/2023 12:21:14 [366328] [DEBUG] ASDevice data loaded for user: 'bla@bla.bla'
06/08/2023 12:21:14 [366328] [DEBUG] InterProcessData:__construct type: 'f2m5ukce695fdbjg9tmt08qnqk'
06/08/2023 12:21:14 [366328] [DEBUG] TopCollector(): Initialized mutexid SysvSemaphore and memid SysvSharedMemory.
06/08/2023 12:21:14 [366328] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
06/08/2023 12:21:14 [366328] [DEBUG] InterProcessData:__construct type: 'f2m5ukce695fdbjg9tmt08qnqk'
06/08/2023 12:21:14 [366328] [DEBUG] LoopDetection(): Initialized mutexid SysvSemaphore and memid SysvSharedMemory.
06/08/2023 12:21:14 [366328] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
06/08/2023 12:21:14 [366328] [DEBUG] ZPush::HierarchyCommand(1): false
06/08/2023 12:21:14 [366328] [DEBUG] ZPush::CommandNeedsPlainInput(1): false
06/08/2023 12:21:14 [366328] [WBXML] I  <ComposeMail:SendMail>
06/08/2023 12:21:14 [366328] [WBXML] I   <ComposeMail:ClientId>
06/08/2023 12:21:14 [366328] [WBXML] I    1095E190-39C6-4405-948A-B9658D62FBB6
06/08/2023 12:21:14 [366328] [WBXML] I   </ComposeMail:ClientId>
06/08/2023 12:21:14 [366328] [WBXML] I   <ComposeMail:SaveInSentItems/>
06/08/2023 12:21:14 [366328] [WBXML] I   <ComposeMail:MIME>
06/08/2023 12:21:14 [366328] [WBXML] I    Content-Type: text/plain;
        charset=us-ascii
Content-Transfer-Encoding: 7bit
From: bla@bla.bla
Mime-Version: 1.0 (1.0)
Date: Sun, 6 Aug 2023 12:21:04 +0200
Subject: Test
Message-Id: <1095E190-39C6-4405-948A-B9658D62FBB6@lannersnet.lu>
To: bla@bli.bli

Test

Sent from my iPad

06/08/2023 12:21:14 [366328] [WBXML] I   </ComposeMail:MIME>
06/08/2023 12:21:14 [366328] [WBXML] I  </ComposeMail:SendMail>

----------------end-log-------------------------------

All good so far, nothing to see. The mail is converted to MIME and then handed over to PHP's mail(). Here is the MIME:

--------------------log-------------------------------

06/08/2023 12:21:14 [366328] [DEBUG] BackendIMAP->SendMail(): Final mail to send:
06/08/2023 12:21:14 [366328] [WBXML] MIME-Version: 1.0
From: bla@bla.bla
Date: Sun, 6 Aug 2023 12:21:04 +0200
Subject: Test
Message-id: <1095E190-39C6-4405-948A-B9658D62FBB6@lannersnet.lu>
To: bla@bli.bli
Return-path: bla@bla.bla
Content-Type: multipart/mixed;
 boundary="=_9016cc7d42b53efa58ac945a3c7230d7"

06/08/2023 12:21:14 [366328] [WBXML] Body: This is a multi-part message in MIME format.
Body: --=_9016cc7d42b53efa58ac945a3c7230d7
Body: Content-Type: multipart/alternative;
Body:  boundary="=_1628643c72e0f22620402bd507ed05db"
Body: 
Body: --=_1628643c72e0f22620402bd507ed05db
Body: Content-Transfer-Encoding: base64
Body: Content-Type: text/plain; charset=utf-8
Body: 
Body: VGVzdA0KDQpTZW50IGZyb20gbXkgaVBhZA0K
Body: --=_1628643c72e0f22620402bd507ed05db--
Body: 
Body: --=_9016cc7d42b53efa58ac945a3c7230d7--
Body: 

06/08/2023 12:21:14 [366328] [DEBUG] BackendIMAP->sendMessage(): SendingMail with mail
06/08/2023 12:21:14 [366328] [DEBUG] BackendIMAP->sendMessage(): send return value 1
06/08/2023 12:21:14 [366328] [DEBUG] BackendIMAP->saveSentMessage(): saving message in Sent Items folder

----------------end-log-------------------------------

That is still good. Also, as the log tells, the mail is saved in the Sent folder. And that copy is always intact.

In other words, I don't see so far where Z-Push would be to blame, other than, maybe, the way the mail() function is called.

And now the problem: here is what the mail looks like on the receiver end:

--------------------log-------------------------------

To: bla@bli.bli
Subject: Test7
MIME-Version: 1.0
 From: bla@bla.bla
 Date: Sun, 6 Aug 2023 18:14:16 +0200
 Message-id: <BA014D49-4C04-4767-BC12-C8D58C8F849F@lannersnet.lu>
 Return-path: bla@bla.bla
 Content-Type: multipart/mixed;
 boundary="=_eb5366f0be07a3ec0907584a88270498"
Message-Id: <E1qSgOg-000TQw-2O@hedwig>
From: www-data <bla@bla.bla>
Date: Sun, 06 Aug 2023 18:14:26 +0200

This is a multi-part message in MIME format.
--=_eb5366f0be07a3ec0907584a88270498
Content-Type: multipart/alternative;
 boundary="=_bd09042eff71e7e3e59f8f86dde78a60"

--=_bd09042eff71e7e3e59f8f86dde78a60
Content-Transfer-Encoding: base64
Content-Type: text/plain; charset=utf-8

TG9nIEFTIGRlYnVnDQoNClNlbnQgZnJvbSBteSBpUGFkDQo=
--=_bd09042eff71e7e3e59f8f86dde78a60--

--=_eb5366f0be07a3ec0907584a88270498--

----------------end-log-------------------------------

Yes, that's not the exact same message, but that's not relevant. The problem is visible in the 5 lines after "MIME-Version: 1.0", where there is an additional space character (verified with hexdump). The last indented line is correct again, since the "boundary=..." is a continuation of the previous line - space is expected.

So the problem resides between logs 2 and 3, and in between those is mail(). I don't have traces anymore, but I am quite sure I verified that on the first hop mailserver the spaces are already inserted. Also, it's probably easy to switch PHP back to 7.4 and verify the problem has gone. I could do that one of these days if of interest.

I'm no PHP expert, so it's difficult for me to debug further. A first verification could be to check the semantics of PHP's mail(), if that changed from 7 to 8, which could potentially explain changed behaviour.

Thanks anyway!

matidau commented 1 year ago

So that was a bit of good fun tracking that down. I've replicated it and yes you were spot on it is causing problems for PHP 8.0+

If your interested this Drupal issue explains what happened between 7.4 and 8.0 pretty well https://www.drupal.org/project/drupal/issues/3270647

If you can test PR #25 and let me know if this resolves this for you.

michlann commented 1 year ago

Hi matidau, do I get it right that your code now leaves $this->sep undefined for PHP8 and later? Could that be a problem?

FWIW, the source code within Z-Push is a copy of PEAR's Mail module. Their latest version 1.5.1 has not touched this specific code at hand.

In any case I just verified that my previous header mangling problem is gone with your patch. Thanks for that!

matidau commented 1 year ago

It gets defined on this line, before the modified code block gets hold of it. https://github.com/Z-Hub/Z-Push/blob/2f0b2c82c966021f5d8ad110cb30d962730f419e/src/backend/imap/Mail.php#L75C9-L75C9

    var $sep = "\r\n";

This is what caused my original confusion 😊

While we could work on incorporating the current PEAR version, I'm trying not to look at new features or bigger changes than bugs until after AS16 support.

Thanks for testing, I'll merge the PR 😊

michlann commented 1 year ago

ACK, thanks a lot!