"failed to read - connection closed?" error when trying to query successful connection

[JustinLardinois]

Describe the bug
I'm able to successfully create a connection, but then I'm getting a "failed to read - connection closed?" error when I try to query for messages.

Used config
Using default config

Code to Reproduce

        $clientManager = new ClientManager();

        $client = $clientManager->make([
            'host'          => 'imap.googlemail.com',
            'port'          => 993,
            'encryption'    => 'ssl',
            'validate_cert' => true,
            'username'      => 'username@example.com',
            'password'      => 'password',
            'protocol'      => 'imap'
        ]);

        try {
            $client->connect();
        } catch (ConnectionFailedException $e) {
            echo 'Unable to connect to username@example.com';
            return;
        }

        $inbox = $client->getFolderByName('INBOX');

        $messages = $inbox->query()
            ->leaveUnread()
            ->unseen()
            ->from('example.com')
            ->since(\Carbon\Carbon::now()->subDays(1))
            ->get();

Expected behavior
The query will be successful and my application will continue execution

Screenshots
N/A

Desktop / Server (please complete the following information):

• OS: CentOS 7
• PHP: 7.4.30
• Version: v3.2.0
• Provider: Gmail (G Suite)

Additional context
Same error as #215, but I don't know if it's a related issue or not. I saw the comment on that issue asking for debug output, but I couldn't figure out how to enable that.

[Webklex]

Hi @JustinLardinois ,
you can enable the debug mode by either setting it directly inside your config (https://github.com/Webklex/php-imap/blob/master/src/config/imap.php#L152) or via method call:

/** @var \Webklex\PHPIMAP\Client $client */
$client->getConnection()->enableDebug();

There is also a new version available (released 10min ago). I recommend you update before you continue debugging :)

Best regards & happy coding,

[JustinLardinois]

Thank you. I've updated to 4.0.0.

I'm still having this issue, but the error message is now "empty response."

Here's the debug output:

>> TAG2 LOGOUT
<< * BYE LOGOUT Requested
<< TAG2 OK 73 good day (Success)

[Webklex]

This looks like you've enabled debug to late in your code. The error empty response. indicates that a command was send, but the server didn't respond.

If debug is enabled while you are sending the command, you'll be able to see what was send to server. For example:

>> TAG2 LOGOUT

Is the command send to the server.

<< * BYE LOGOUT Requested
<< TAG2 OK 73 good day (Success)

Is the received response.

TAG2 also tells me, that that there has been only one command send to the server before.

Here is an example what to expect, if you call:

/** @var \Webklex\PHPIMAP\Client $client */
$client->connect();

$inbox = $client->getFolder("INBOX");

$messages = $inbox->query()
    ->leaveUnread()
    ->unseen()
    ->from('example.com')
    ->since(\Carbon\Carbon::now()->subDays(1))
    ->get();

>> TAG1 LOGIN "someone@example.com" "some password"
<< TAG1 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE QUOTA] Logged in
>> TAG2 LIST "" "*"
<< * LIST (\HasChildren) "." INBOX
<< * LIST (\HasNoChildren) "." INBOX.new
<< * LIST (\HasNoChildren) "." INBOX.9AL56dEMTTgUKOAz
<< * LIST (\HasNoChildren) "." INBOX.U9PsHCvXxAffYvie
<< * LIST (\HasNoChildren \UnMarked \Trash) "." INBOX.Trash
<< * LIST (\HasNoChildren) "." INBOX.processing
<< * LIST (\HasNoChildren \Sent) "." INBOX.Sent
<< * LIST (\HasNoChildren) "." INBOX.OzDWCXKV3t241koc
<< * LIST (\HasNoChildren) "." INBOX.5F3bIVTtBcJEqIVe
<< * LIST (\HasNoChildren) "." INBOX.8J3rll6eOBWnTxIU
<< * LIST (\HasNoChildren \Junk) "." INBOX.Junk
<< * LIST (\HasNoChildren \Drafts) "." INBOX.Drafts
<< * LIST (\HasNoChildren) "." INBOX.test
<< TAG2 OK List completed (0.002 + 0.000 + 0.001 secs).
>> TAG3 SELECT "INBOX"
<< * FLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk unknown-1)
<< * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk unknown-1 \*)] Flags permitted.
<< * 136 EXISTS
<< * 0 RECENT
<< * OK [UNSEEN 94] First unseen.
<< * OK [UIDVALIDITY 1488899637] UIDs valid
<< * OK [UIDNEXT 275] Predicted next UID
<< TAG3 OK [READ-WRITE] Select completed (0.002 + 0.000 + 0.001 secs).
>> TAG4 UID SEARCH UNSEEN FROM "example.com" SINCE "18-Aug-2022"

Best regards,

[JustinLardinois]

I played around a bit, I think I was actually enabling debug too early. I was previously enabling it directly after the $clientManager->make call, but I moved it to where it was in your example and got this more detailed output (still with the "empty response" error).

>> TAG2 LIST "" "*"
<< * LIST (\HasNoChildren) "/" "INBOX"
<< * LIST (\HasNoChildren) "/" "Some Label"
<< * LIST (\HasNoChildren) "/" "Another Label"
<< * LIST (\HasNoChildren) "/" "Yet Another Label"
<< * LIST (\HasChildren \Noselect) "/" "[Gmail]"
<< * LIST (\All \HasNoChildren) "/" "[Gmail]/All Mail"
<< * LIST (\Drafts \HasNoChildren) "/" "[Gmail]/Drafts"
<< * LIST (\HasNoChildren \Important) "/" "[Gmail]/Important"
<< * LIST (\HasNoChildren \Sent) "/" "[Gmail]/Sent Mail"
<< * LIST (\HasNoChildren \Junk) "/" "[Gmail]/Spam"
<< * LIST (\Flagged \HasNoChildren) "/" "[Gmail]/Starred"
<< * LIST (\HasNoChildren \Trash) "/" "[Gmail]/Trash"
<< TAG2 OK Success
>> TAG3 SELECT "INBOX"
>> TAG4 LOGOUT
<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $NotPhishing $Phishing)
<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $NotPhishing $Phishing \*)] Flags permitted.
<< * OK [UIDVALIDITY 1] UIDs valid.
<< * 7975768 EXISTS
<< * 0 RECENT
<< * OK [UIDNEXT 7983426] Predicted next UID.
<< * OK [HIGHESTMODSEQ 425620554]
<< TAG3 OK [READ-WRITE] INBOX selected. (Success)
<< * BYE LOGOUT Requested
<< TAG4 OK 73 good day (Success)

[Webklex]

Interestingly LOGOUT gets called before the TAG3 SELECT "INBOX" response gets received. I can't think of a scenario which would cause this - besides a really bad internet connection in combination with a request which takes > 30sec. But I doubt that's the case.

[JustinLardinois]

I don't know if this helps, but I've been playing around with the library on two different accounts, and I'm only seeing these issues for one of them. In both cases I'm using app passwords as recommended.

[Webklex]

If you test both accounts in an isolated environment - do you still get the same error? Perhaps some surrounding conditions (unrelated to this library) fail, which causes ImapProtocol::__destruct() to be invoked and therefor LOGOUT to be sent.

[JustinLardinois]

Alright, I created a standalone script that's just as follows:

$clientManager = new ClientManager();

$client = $clientManager->make([
    'host'          => 'imap.googlemail.com',
    'port'          => 993, 
    'encryption'    => 'ssl',
    'validate_cert' => true,
    'username'      => 'username@example.com',
    'password'      => 'password',
    'protocol'      => 'imap'
]);     

try {   
    $client->connect();
} catch (ConnectionFailedException $e) {
    die('Unable to connect to username@example.com');
}       
$client->getConnection()->enableDebug();

$inbox = $client->getFolderByName('INBOX');

$messages = $inbox->query()
    ->leaveUnread()
    ->unseen()
    ->since(\Carbon\Carbon::now()->subDays(1))
    ->limit(10)
    ->get();

And tweaked the credentials for both of the accounts I was testing with.

The first account that I haven't had any problems with worked fine. I've attached some debug output trimmed for length and edited for sensitive information: first-account.txt

For the second account, I still have the same issue:

>> TAG2 LIST "" "*"
<< * LIST (\HasNoChildren) "/" "INBOX"
<< * LIST (\HasNoChildren) "/" "Label name"
<< * LIST (\HasNoChildren) "/" "a different label name"
<< * LIST (\HasNoChildren) "/" "Yet another label"
<< * LIST (\HasChildren \Noselect) "/" "[Gmail]"
<< * LIST (\All \HasNoChildren) "/" "[Gmail]/All Mail"
<< * LIST (\Drafts \HasNoChildren) "/" "[Gmail]/Drafts"
<< * LIST (\HasNoChildren \Important) "/" "[Gmail]/Important"
<< * LIST (\HasNoChildren \Sent) "/" "[Gmail]/Sent Mail"
<< * LIST (\HasNoChildren \Junk) "/" "[Gmail]/Spam"
<< * LIST (\Flagged \HasNoChildren) "/" "[Gmail]/Starred"
<< * LIST (\HasNoChildren \Trash) "/" "[Gmail]/Trash"
<< TAG2 OK Success
>> TAG3 SELECT "INBOX"

[Webklex]

Hi @JustinLardinois ,
thanks for the followup. This is really strange - I'm having a hard time to make sense of it. Both are gmail accounts, but one works and another doesn't. So whats the difference between them two?
One unlikely idea: could it be that one of them is being used actively by several clients - perhaps even on the same host and therefor google terminates the session, because another client took over? How is google handling parallel sessions? I don't believe that's the cause, I'm just out of ideas...

[JustinLardinois]

I suppose that's a potential cause—the account I'm having issues with is an inbox that's regularly accessed by several people at my company. Though I'm pretty sure everyone is accessing it through the Gmail.com webapp, not a separate IMAP client.

I'm certainly not an IMAP expert so I don't know whether that would be related.

The only thing that comes to my mind is they're using different MFA methods. The account that works is using an authenticator app; the one that doesn't is using SMS MFA. I don't see why that would matter for IMAP, but something to think about. I did try temporarily disabling SMS MFA on the account that was having issues, but turns out Google only supports app passwords if you have MFA enabled, so that didn't help.