Long delays using Gmail with Rebex Mail Client

Question

Dear Sirs,

I have a problem using Gmail with Rebex Mail Client.
It works but it stops for a while in 2 different points.
As described below the login needs 30 seconds. But the main problem is that each time I try to read a message it takes 10 seconds!
Often the number of messages to read is quite high, so 10 seconds a message is a lot. In both cases there is no high use of CPU, memory, disk access, etc.

This is my code:

var emailClient = new ImapClient();
emailClient.Connect("imap.gmail.com");

// The login needs for 30 seconds
emailClient.Login(username, password);

...

// Each message needs 10 seconds
var mail = emailClient.GetMailMessage(i);

Can you help with this please?

Thank you.

Answer 1

Hello,

Please make sure that you are indeed using a Rebex Imap client (it is not called ImapClient).

If you do, create a communication log using Imap object's LogWriter property (as described in the Logging HOWTO) and either post it here or mail it to us for analysis.

Comments

Dear Lukas,
 
Thank you for your answer.
 
The class ImapClient (used in the code above) derives from the class Rebex.Net.Imap, so, I confirm it's using Rebex Imap client.
 
You can find in attachment the log file. I interrupted the execution after the 4th "ImapClient.GetMailMessage()" call.

I sent you an email with this answer and the log file in attachment 2 days ago but I didn't receive any answer. Unfortunately I can't send the log file here because there is a maximum of 8000 characters and the log has near 68000. I'm sending you below just the first part of the log file.

Thank you again.
Armando


2019-01-16 10:15:02.988 Opening log file.
2019-01-16 10:15:02.988 INFO FileLogWriter(1)[9] Info: Assembly: Rebex.Common 2018 R2 for .NET 4.0-4.7
2019-01-16 10:15:02.988 INFO FileLogWriter(1)[9] Info: Platform: Windows 6.1.7601 64-bit; CLR: 4.0.30319.42000
2019-01-16 10:15:02.988 DEBUG FileLogWriter(1)[9] Info: Culture: en; Windows-1252
2019-01-16 10:15:02.998 DEBUG Imap(1)[9] Info: State changed from 'Disconnected' to 'Connecting'.
2019-01-16 10:15:02.998 INFO Imap(1)[9] Info: Connecting to imap.gmail.com:993 using Imap.
2019-01-16 10:15:02.998 INFO Imap(1)[9] Info: Assembly: Rebex.Imap 2018 R2 for .NET 4.0-4.7
2019-01-16 10:15:02.998 INFO Imap(1)[9] Info: Platform: Windows 6.1.7601 64-bit; CLR: 4.0.30319.42000
2019-01-16 10:15:02.998 DEBUG Imap(1)[9] Info: Culture: en; Windows-1252
2019-01-16 10:15:02.998 INFO Imap(1)[9] Info: Connecting to imap.gmail.com.
2019-01-16 10:15:03.008 DEBUG ProxySocket(1)[9] Proxy: Resolving 'imap.gmail.com'.
2019-01-16 10:15:03.048 DEBUG ProxySocket(1)[9] Proxy: Connecting to 64.233.167.109:993 (no proxy).
2019-01-16 10:15:03.048 DEBUG Imap(1)[9] Info: Connection succeeded.
2019-01-16 10:15:03.058 DEBUG Imap(1)[9] Info: Upgrading connection to TLS/SSL.
2019-01-16 10:15:03.188 INFO Imap(1)[9] TLS: State StateChange:Negotiating
2019-01-16 10:15:03.188 DEBUG Imap(1)[9] TLS: HandshakeMessage:ClientHello was sent.
2019-01-16 10:15:03.268 DEBUG Imap(1)[9] TLS: HandshakeMessage:ServerHello was received.
2019-01-16 10:15:03.268 INFO Imap(1)[9] TLS: Using TLS 1.2.
2019-01-16 10:15:03.268 DEBUG Imap(1)[9] TLS: The server supports secure renegotiation.
2019-01-16 10:15:03.298 DEBUG Imap(1)[9] TLS: HandshakeMessage:Certificate was received.
2019-01-16 10:15:03.298 DEBUG Imap(1)[9] TLS: HandshakeMessage:ServerKeyExchange was received.
2019-01-16 10:15:03.298 DEBUG Imap(1)[9] TLS: HandshakeMessage:ServerHelloDone was received.
2019-01-16 10:15:03.308 DEBUG Imap(1)[9] TLS: Verifying server certificate ('CN=imap.gmail.com, O=Google LLC, L=Mountain View, S=California, C=US').
2019-01-16 10:15:03.308 DEBUG Imap(1)[9] TLS: Certificate verification result: Accept
2019-01-16 10:15:03.338 DEBUG Imap(1)[9] TLS: Using ephemeral ECDH public key exchange with NIST P-256 curve.
2019-01-16 10:15:03.348 DEBUG Imap(1)[9] TLS: HandshakeMessage:ClientKeyExchange was sent.
2019-01-16 10:15:03.368 DEBUG Imap(1)[9] TLS: CipherSpec:ChangeCipherSpec was sent.
2019-01-16 10:15:03.368 DEBUG Imap(1)[9] TLS: HandshakeMessage:Finished was sent.
2019-01-16 10:15:03.378 DEBUG Imap(1)[9] TLS: CipherSpec:ChangeCipherSpec was received.
2019-01-16 10:15:03.378 DEBUG Imap(1)[9] TLS: HandshakeMessage:Finished was received.
2019-01-16 10:15:03.388 INFO Imap(1)[9] TLS: State StateChange:Secured
2019-01-16 10:15:03.388 INFO Imap(1)[9] TLS: Connection secured using cipher: TLS 1.2, RSA with ephemeral Elliptic Curve Diffie-Hellman, AES with 128-bit key in GCM mode, AEAD
2019-01-16 10:15:03.388 DEBUG Imap(1)[9] TLS: Session ID:
 0000 |F1-84-95-45-8D-65-EA-87 A8-DA-35-9F-0E-C9-2F-82| ...E.e....5.../.
 0010 |BF-CA-FA-82-F6-8C-42-AF 12-B7-B2-8F-05-56-C6-DE| ......B......V..
2019-01-16 10:15:03.388 DEBUG Imap(1)[9] Info: Connection upgraded to TLS/SSL.
2019-01-16 10:15:03.388 DEBUG Imap(1)[9] Info: State changed from 'Connecting' to 'Reading'.
2019-01-16 10:15:03.388 INFO Imap(1)[9] Response: * OK Gimap ready for requests from 80.41.197.124 y68mb1026677266wmc
2019-01-16 10:15:03.398 DEBUG Imap(1)[9] Info: State changed from 'Reading' to 'Ready'.
2019-01-16 10:15:03.408 DEBUG Imap(1)[9] Info: State changed from 'Ready' to 'Sending'.
2019-01-16 10:15:03.408 INFO Imap(1)[9] Command: R00001 CAPABILITY
2019-01-16 10:15:03.408 DEBUG Imap(1)[9] Info: State changed from 'Sending' to 'Reading'.
2019-01-16 10:15:03.428 INFO Imap(1)[9] Response: * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 XYZZY SASL-IR AUTH=XOAUTH2 AUTH=PLAIN AUTH=PLAIN-CLIENTTOKEN AUTH=OAUTHBEARER AUTH=XOAUTH
2019-01-16 10:15:03.428 INFO Imap(1)[9] Response: R00001 OK Thats all she wrote! y68mb1026677266wmc
2019-01-16 10:15:03.428 DEBUG Imap(1)[9] Info: State changed from 'Reading' to 'Ready'.
2019-01-16 10:15:03.448 DEBUG Imap(1)[9] Info: State changed from 'Ready' to 'Sending'.
2019-01-16 10:15:03.448 INFO Imap(1)[9] Command: R00002 AUTHENTICATE PLAIN
2019-01-16 10:15:03.448 DEBUG Imap(1)[9] Info: State changed from 'Sending' to 'Reading'.
2019-01-16 10:15:03.468 INFO Imap(1)[9] Response: +
2019-01-16 10:15:03.468 DEBUG Imap(1)[9] Info: State changed from 'Reading' to 'Sending'.
2019-01-16 10:15:03.468 INFO Imap(1)[9] Command: **********
2019-01-16 10:15:03.468 DEBUG Imap(1)[9] Info: State changed from 'Sending' to 'Reading'.
2019-01-16 10:15:03.778 INFO Imap(1)[9] Response: * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS ENABLE MOVE CONDSTORE ESEARCH UTF8=ACCEPT LIST-EXTENDED LIST-STATUS LITERAL- SPECIAL-USE APPENDLIMIT=35651584
2019-01-16 10:15:03.778 INFO Imap(1)[9] Response: R00002 OK scifatturepassive@gmail.com authenticated (Success)
2019-01-16 10:15:03.778 DEBUG Imap(1)[9] Info: State changed from 'Reading' to 'Ready'.
2019-01-16 10:15:03.788 DEBUG Imap(1)[9] Info: State changed from 'Ready' to 'Sending'.
2019-01-16 10:15:03.788 INFO Imap(1)[9] Command: R00003 STATUS Inbox (UNSEEN)
2019-01-16 10:15:03.788 DEBUG Imap(1)[9] Info: State changed from 'Sending' to 'Reading'.
2019-01-16 10:15:13.954 INFO Imap(1)[9] Response: * STATUS "Inbox" (UNSEEN 1)
2019-01-16 10:15:13.954 INFO Imap(1)[9] Response: R00003 OK Success [THROTTLED]
2019-01-16 10:15:13.954 DEBUG Imap(1)[9] Info: State changed from 'Reading' to 'Ready'.
2019-01-16 10:15:13.964 DEBUG Imap(1)[9] Info: State changed from 'Ready' to 'Sending'.
2019-01-16 10:15:13.964 INFO Imap(1)[9] Command: R00004 SELECT Inbox
2019-01-16 10:15:13.964 DEBUG Imap(1)[9] Info: State changed from 'Sending' to 'Reading'.
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $NotPhishing $Phishing)
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $NotPhishing $Phishing \*)] Flags permitted.
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * OK [UIDVALIDITY 1] UIDs valid.
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * 204 EXISTS
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * 0 RECENT
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * OK [UIDNEXT 205] Predicted next UID.
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: * OK [HIGHESTMODSEQ 32349]
2019-01-16 10:15:24.085 INFO Imap(1)[9] Response: R00004 OK [READ-WRITE] Inbox selected. (Success) [THROTTLED]
2019-01-16 10:15:24.085 DEBUG Imap(1)[9] Info: State changed from 'Reading' to 'Ready'.
2019-01-16 10:15:24.105 DEBUG Imap(1)[9] Info: State changed from 'Ready' to 'Sending'.
2019-01-16 10:15:24.105 INFO Imap(1)[9] Command: R00005 FETCH 1:* (UID RFC822.SIZE FLAGS INTERNALDATE BODY.PEEK[HEADER])
2019-01-16 10:15:24.105 DEBUG Imap(1)[9] Info: State changed from 'Sending' to 'Reading'.
2019-01-16 10:15:34.340 INFO Imap(1)[9] Response: * 1 FETCH (UID 1 RFC822.SIZE 6971 INTERNALDATE "18-Jun-2018 11:39:34 +0000" FLAGS (\Seen) BODY[HEADER] {471}
2019-01-16 10:15:34.340 INFO Imap(1)[9] Response: ...471 bytes...
2019-01-16 10:15:34.340 INFO Imap(1)[9] Response: )

---

For some reason, we never received that email, although I see one from June. I just tried sending an email - please let me know whether it arrived both by replying to it and here at the forum.

However, the short log is sufficient for now - it shows that there is indeed a delay of 10 seconds while waiting for each server response once the client has authenticated. So the next step is to try to determine what causes this delay. The best course of action is to install a network protocol analyzer such as Wireshark (https://www.wireshark.org/) at the machine experiencing the issue, and see whether the delay occurs at the network level or not.

---

Dear Lukas,
 
The network is alright. If I connect to other email providers it works properly. I have the problem with Gmail only. Also I tested the program from a different network in a different place and got the same result. I think this means that there is no network problem.

Since the issue is limited to Gmail I wonder if Google dislike that the program reads the emails often and they add this delay in order to limit the traffic. Unfortunately I couldn't find any information about this matter anywhere.

Thank you.
Armando

---

OK, so all we know for sure at this point is that:
1. Your application experiences a 10-second delay while waiting for IMAP server response when using Gmail.
2. The network doesn't seem to make a difference.
3. Other Rebex Secure Mail users apparently don't experience this.

Based on this data, it looks like there are several possible explanations:
a) Gmail/Google is deliberately introducing a delay into the communication for some reason.
b) Something is wrong with your application.
c) Something is wrong with the machine or OS where your application runs.

A Wireshark log would make it very simple do refute (b) because it makes it possible to listen at the network packet level, which is below the application level. So giving it a try still sounds very useful.

To refute (c), simply try running the application on a different machine. (Let us know if you tried this already.)

And if (a) is the cause and it's Gmail that is in fact behaving this way, I assume the problem would stop manifesting if you used a different user account. At least unless Gmail could still identify your application (by an IP address for example) and apply the same kind of throttling.  So perhaps trying the same application on a totally unrelated IP with a different Gmail account is the way to go now.

---

Dear Lukas,

After some tests we realised that the problem was caused by Google.

We were reading the emails from gmail very often during the day. Apparently Google adds those waiting times to prevent users to use their servers too much.
Now we're getting the emails a few times a day and all delays vanished.

Best Regards,
Armando

---

Thanks for letting us know about this!