SMTP::get_lines() timing out and returning empty string

[vboctor]

Problem description

getLines() times out and returns empty string.

Environment

PHP 7.0.33-0ubuntu0.16.04.2
PHPMailer 6.0.6
Using Amazon SES - older versions of PHPMailer 5.x works.
Linux mis2-us 4.4.0-1075-aws #85-Ubuntu SMP Thu Jan 17 17:15:12 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Debug output

[Fri Mar 08 08:40:04.623561 2019] [:error] [pid 15859] [client 172.31.29.205:42314] SMTP -> get_lines(): timed-out (5 sec), referer: https://mantis-domain/bug_report_page.php
[Fri Mar 08 08:40:04.623605 2019] [:error] [pid 15859] [client 172.31.29.205:42314] SERVER -> CLIENT: , referer: https://mantis-domain/bug_report_page.php
[Fri Mar 08 08:40:04.623658 2019] [:error] [pid 15859] [client 172.31.29.205:42314] CLIENT -> SERVER: EHLO some-valid-domain.com\r\n, referer: https://mantis-domain/bug_report_page.php

Code to reproduce

Here is the code that sends out the email via PHPMailer/SMTP:
https://github.com/mantisbt/mantisbt/blob/master/core/email_api.php#L1252

Cause Found

Removing the following block from the SMTP.php get_lines() function fixes the issue:

            //Must pass vars in here as params are by reference
            if (!stream_select($selR, $selW, $selW, $this->Timelimit)) {
                $this->edebug(
                    'SMTP -> get_lines(): timed-out (' . $this->Timeout . ' sec)',
                    self::DEBUG_LOWLEVEL
                );
                break;
            }

[Synchro]

This nothing to do with get_lines. It’s the call to stream_select that’s failing, which suggests a problem with network or PHP config.

[vboctor]

@Synchro thanks for your prompt response. The code is in get_lines(), and removing it doesn't break the code and emails flow successfully. The debug logs indicates a timeout, but unclear what the reasons can be. Are there specific configs or gotchas that I should look for? What is the reason for this code not being there in older versions of PHPMailer.

[Synchro]

If you search on here for stream_select, you’ll find the reasons for the change in the original issue.

[vboctor]

I assume you are referring to #604. I have read this already.

I added more debugging and noticed the following behavior:

1. feof() - returns false
2. stream_select() returns 0 after TimeLimit.
3. feof() - returns false (added for debugging)
4. fget() - returns a valid line from the AWS SES (added for debugging)

Unfortunately, in the original code when stream_select() returns 0, an empty response for get_lines() is returned and everything fails afterwards.

Kind of looks like the PHP bug referenced here, but that should be fixed as per bug.

One of the notes in PHP documentation indicates that stream_select() shouldn't be called on blocking streams.

So as I see why it was added, it seems to have introduced regression at least for some environments with healthy servers. The code was introduced to protect against unhealthy SMTP servers that never respond.

[Synchro]

There's discussion in #604 about the use of stream_select with blocking, and as far as we could see the use we have should be ok. Ultimately we're suffering from multiple parts of PHP not working as expected/documented - do you have any sensible suggestions for fixing it? In your case you could work around it by sending via a local mail server, which is the recommended (and fastest) way of working anyway.

[vboctor]

do you have any sensible suggestions for fixing it?

Unfortunately, there is no perfect solution here. You can either:

• Remove these lines since they attempt to fix an issue with mis-behaving SMTP servers and introduces an issue with behaving ones in some environments. This will also be consistent with behavior in previous versions of PHPMailer (5.x).
• Add a flag in SMTP class that enables/disables such functionality.

work around it by sending via a local mail server

I suspect that with the same PHP environment and OS, it is likely that this won't work either since in my case EC2 -> AWS SES is as responsive as localhost, so not much benefit and likely to hit same bug. Also I think the benefit of using PHPMailer over mail() function is to be able to send to other servers. Also this enables the ability for the app to make the SMTP server configurable and less environment dependencies and settings.

[utilmind]

I had an absolutely same issue. It's randomly freeze on the following line:
if (!stream_select($selR, $selW, $selW, $this->Timelimit)) {

Sometimes it works, sometimes does not. Unfortunately this issue forced me to stop using SMTP-based PHPMailer and swith to default mail()-based functionality.

Except only one website where mail() is intentionally disabled in "php.ini". I fixed this issue simply switching to get_lines() from ancient past, when it did not used stream functions like stream_select().

Here is the code for get_lines() method which works for me and does not freezing anything:

    protected function get_lines() {
      $data = '';
      while($str = @fgets($this->smtp_conn,515)) {
        if($this->do_debug >= 4) {
          echo "SMTP -> get_lines(): \$data was \"$data\"\n\n";
          echo "SMTP -> get_lines(): \$str is \"$str\"\n\n";
        }
        $data.= $str;
        if($this->do_debug >= 4)
          echo "SMTP -> get_lines(): \$data is \"$data\"\n\n";
        # if the 4th character is a space then we are done reading
        # so just break the loop
        if(substr($str,3,1) == ' ') break;
      }
      return $data;
    }

I guess that it's not the perfect solution, but it still works. I'm not sure why it ever requires that streams at all, because works with out streams with simple fgets(). Additionally I have made research I noticed that even if stream_select() freezing I still can successfully get data with fgets()!

        while (is_resource($this->smtp_conn) and !feof($this->smtp_conn)) {
            //Must pass vars in here as params are by reference
            if (!stream_select($selR, $selW, $selW, $this->Timelimit)) {
                $this->edebug(
                    'SMTP -> get_lines(): timed-out (' . $this->Timeout . ' sec)',
                    self::DEBUG_LOWLEVEL
                );

                // trying to receive and display the response in any case
                print 'TEST fgets: ';
                print @fgets($this->smtp_conn, 515);
                break;
            }

Here is an output:

2019-05-26 18:45:53 SERVER -> CLIENT: 250-favor.com.ua Hello test.favor.com.ua [127.0.0.1]
250-SIZE 52428800
250-8BITMIME
250-PIPELINING
250-AUTH CRAM-MD5 PLAIN LOGIN
250-CHUNKING
250 HELP
2019-05-26 18:45:53 CLIENT -> SERVER: MAIL FROM:[email protected]
2019-05-26 18:46:05 SMTP -> get_lines(): timed-out (10 sec)
TEST fgets:: 250 OK
2019-05-26 18:46:05 SERVER -> CLIENT:
2019-05-26 18:46:05 SMTP ERROR: MAIL FROM command failed:
2019-05-26 18:46:05 The following From address failed: [email protected] : MAIL FROM command failed,,,SMTP server error: MAIL FROM command failed

[Synchro]

Changing back to the old code will simply return to the old and broken behaviour, which doesn't help anyone. fgets has a bug which means that it doesn't always obey its timeout settings; if you have a fast mail server that responds quickly, it will work fine (as you're finding), but if you talk to a slow server, it can break in a way that we can't handle because of the buggy behaviour of fgets. The stream functions generally do handle timeouts correctly, but suffer from some other issues. Ideally one or the other would be fixed properly upstream, but meanwhile there is no option that will work for everyone, unless you have a clever suggestion that can detect either issue ahead of time.

[ErikLtz]

The code of method get_lines in 6.1.2 have the stream_select call and seem to work well (CentOS 7 towards old Windows email server). However, maybe related to above issue, after receiving a short reply from server of 334 and line end (5 chars read), the info returned from stream_get_meta_data after the fgets indicate blocked=1 and unread_bytes=0. Instead of returning this short reply line, the while loop enter another stream_select call that eventually fail with timeout, THEN returning the previously read data.

I added another case after the stream_get_meta_data checking for a complete line and no more to read, that seem to fix the long wait. Can't really say if this only applies to me or would improve things for others too...?

The if-case just BEFORE the meta_data call checks for a space as fourth character (index 3) in a read chunk of data - I guess this case would apply to the "334\r\n" response if it also included \r as break character, which would be a shorter fix than mine:

        // No more data to read and received end of line? (\r\n or just \n)
        if($info['unread_bytes']==0) {
            $len=strlen($str);
            if(($len>=2 && $str[$len-2]=="\r" && $str[$len-1]=="\n") ||
               ($len>=1 &&                       $str[$len-1]=="\n")) {
                $this->edebug(
                    'SMTP -> get_lines(): got complete line (' . strlen($data) . ' bytes), done here',
                    self::DEBUG_LOWLEVEL
                );
                break;
            }
        }

[Synchro]

That seems reasonable. The docs for fgets say that the line ending is included in the returned string, and that may mean that the tests for line length may not be correct. I wonder if it would be a good idea to switch to using stream_get_line instead, since that has more control over line breaks, and is apparently a little faster. Alternatively I wonder if it's worth applying an rtrim to strip any line break chars from responses before doing tests on the received line; that would simplify the test @ErikLtz suggested. One problem I can see with that is if the line has been truncated because of the length limit given to fgets, rather than because it found a line break.

What I don't quite get is why it would fail to complete (i.e. break out of the loop) given an input string of 250 OK (as in @utilmind's example above), since that should match the 4th char being a space. Maybe the data is read in 2 chunks over 2 iterations, like this:

250
 OK\r\n

i.e. perhaps we should be checking $data[3] rather than $str[3]?

The source refers to RFC5321 S 4.2, specifically:

An SMTP client MUST determine its actions only by the reply code, not
by the text (except for the "change of address" 251 and 551 and, if
necessary, 220, 221, and 421 replies); in the general case, any text,
including no text at all (although senders SHOULD NOT send bare
codes), MUST be acceptable.

One oddity there is that it says that senders should not send bare codes - but senders don't send codes at all, only receivers. RFC quirk I guess, unless they mean that receivers are the senders of codes, which is a little obtuse!

[ErikLtz]

I believe "the oddity" is my mail server replying with ONLY 334\r\n in 5 chars, i.e. NO space after the three status digits and nothing more to read on the socket - which cause a time out. Is 334\r\n a "bare code" that should be accepted? Perhaps not according to standard, but I fixed it with "both" the exit after line end AND a simpler check in the somewhat strange if(...$str[3]==" "...) - extended to break also on \r or \n in that position.

[Synchro]

Yes, that is indeed a bare code. Overall I'd say that the code in get_lines reads like it's not expecting line breaks in the data it reads and that's what's leading to this issue. I can see how your change would fix the bare code problem, but it's not clear to me how a 250 OK response can fail.

I don't think checking for a space as the 4th char is strange, since that's what the RFC says to look for, and nearly everything in there is looking at the beginnings of lines, not the ends. It would be very useful to have a reproducible test for this.

[Synchro]

Can you see if changing it to this works:

    $str = rtrim($str, "\r\n");
    if (!isset($str[3]) || (isset($str[3]) && $str[3] === ' ')) {

This should catch anything that's just a bare code because $str[3] will no longer be set in that case. This is done after $str is appended to $data, so it won't affect the returned string at all.

[ErikLtz]

Fascinating that such a central core function as get_lines in the SMTP module where all data from the server pass through still cause problems/confusion (also involving bugs in PHP as I understand it).
When looking at the code (in 6.1.2) it does contain several cases I didn't expect. From the line based nature of SMTP and given the name of the function, reading one or more lines from the server is the perceived purpose, but still it looks inside lines for "protocol specific details".
From the logs I do realize there are caveats like multiline replies with several 250-xxx lines ended with a 250 OK (where the dash is a continuation mark and space the last line indicator). So looking at that fourth character seems important - very important. Following the path of minimal change would be to only extend the original:

&& $str[3]===' '

into:

&& ($str[3]===' ' || $str[3]==="\r" || $str[3]==="\n")

which I have in my running code now...

[ErikLtz]

Also: as fgets returns full lines, it's not possible to receive "250 OK" split into two halves. If the server was like when using telnet as SMTP client (i.e. telnet localhost 25 and typing along) the fgets would still return full lines and not individual characters, right? :-)

[Synchro]

Indeed, it's a rats nest in there! This particular issue is only triggered by non-compliant servers, but reality dictates that we need to deal with it!

I slightly favour the rtrim approach as it keeps that if simpler, and implicitly avoids any line break shenanigans, though simple comparisons might be faster than a function call. This is one of the functions that is important for performance - I seem to recall that switching away from strlen made a ~20% improvement.

I think the split scenario is indeed unlikely - though it's possible if we hit the length limit on fgets rather than an EOL (and I'm not sure where that 515 char limit is from), but still I don't see how it could happen on 250 OK.

[ErikLtz]

Yeah 515 just like that surprised me too - define('SMTP_MAX_LINE_LENGTH', 515); and fgets(...SMTP_MAX_LINE_LENGTH); would be understandable (if that is what it is).
On performance, it's hard to see how rtrim could do it's thang without internally doing what strlen does, and then some - and just checking index 3 a couple of times should still be faster than any function call. But compared to other factors like select calls, communication across network and more for each line read from the server, both strlen, rtrim or three single character comparisons should be close to negligible...
(in my use case I'm unable to really performance benchmark it as I only use it for a quick SMTP authenticate test - though not surprising there where a big difference in execution time using the old PHP 5 in CentOS compared to the newer 7.2.24 though, but 30 ms or 15 ms is hard to separate "manually")

[Synchro]

I think we can simplify that if to:

if (!isset($str[3]) || $str[3] === ' ' || $str[3] === "\r" || $str[3] === "\n") {

We don't need to check isset($str[3]) because that possibility would be implicit from the first term anyway. Do you see any holes in that logic?

I can't find any reference to 515 in RFC5321, but there is a 512-char limit on both commands and replies (which is what we're looking at here). This limit includes the trailing CRLF, so I can't see any sensible reason it's been bumped up to 515 here; I could understand 514 or 510 if there was confusion about the break, but 515 seems arbitrary. It should definitely be a constant – I will add that.

[Synchro]

@ErikLtz any thoughts on this?

[ErikLtz]

Yes, nice and simple with minimal change. I currently run with:

if (!isset($str[3]) || $str[3] === ' ' || $str[3] === "\r" || $str[3] === "\n") {

and removed the previously added longer check for CRLF at end of string. Seems to work well :-)

[mrbrown2207]

Hi. I found this thread and have read through it a couple of times. I am hoping that someone can give me an idea what to look at. I experience this even with the latest version of PHPMailer. However, I only experience it when I try am trying to connect to mail.domain.com (I can ping it) or if I put in the IP address. If I use domain.com it is fine. I am sure this is my lack of understanding of something....I just don't know what. I was hoping that someone here who knows more than I might be able to give me a hint. Cheers in advance.

[Synchro]

That sounds more like a TLS problem. Please open a new ticket with all your debug output as it doesn't sounds like you're having the issue described here.

[mrbrown2207]

Thank you. I believe I have solved this.