Long delay running pop3 LIST

[ralfjunker]

I did this

curl --ssl-reqd --insecure -u username:password pop3s://pop.gmx.net

I expected the following

I expect a list of message IDs and message size. The list does indeed shows, but only up to message number 96. Then the display stops in the middle of the line, like here:

[previous lines skipped]
90 8157
91 7650
92 7888
93 7779
94 19238
95 19218
9

Surprisingly, after at least 30 seconds of inactivity, curl continues. It completes the truncated line and writes all remaining lines with no further delay (up to message 222, in my case).

I have seen the same delay in other pop3 contexts, but I am not able to reproduce it there. I hope you can see my findings.

curl/libcurl version

curl 8.8.0 (x86_64-w64-mingw32) libcurl/8.8.0 LibreSSL/3.9.2 zlib/1.3.1 brotli/1.1.0 zstd/1.5.6 WinIDN libpsl/0.21.5 libssh2/1.11.0 nghttp2/1.62.1 ngtcp2/1.6.0 nghttp3/1.4.0
Release-Date: 2024-05-22
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp ws wss
Features: alt-svc AsynchDNS brotli HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM PSL SPNEGO SSL SSPI threadsafe UnixSockets zstd

Note: This is the curl 8.8.0 binary from https://curl.se/windows/dl-8.8.0_3/curl-8.8.0_3-win64-mingw.zip.

operating system

Windows 11, 64 bit.

[ralfjunker]

I tested previous versions:

• curl 8.4.0 and curl 8.5.0 have no delay, they write the entire list in one go in less than 1 second.
• The first version to exhibit the delay is curl 8.6.0, which interrupts for a fraction longer than exactly 120 seconds (> 2 minutes!).
• The same delay of slightly over 120 seconds happens with curl 8.7.0.
• Exact timing of curl 8.8.0 revealed the same almost exactly 120 seconds delay, not just 30 seconds as stated in my initial message above.

Summary:

• curl up to 8.5.0 has no problems. From this I conclude that is not a server fault.
• The problem started with curl 8.6.0 and is reproducible across curl versions, up to the current 8.8.0.
• With > 120 seconds, the interruption is not negligible.

Hopefully this helps to determine the cause.

[bagder]

I wrote up a new test case that lists 1000 messages with POP3 (#14297) but it does not reproduce for me!

[bagder]

@ralfjunker any chance you can retry with the latest curl and see if this works for you as well as it does for me?

[ralfjunker]

I just tried with curl v8.9.1 and is shows the same 2 minute pause after 99 messages before it continues to print the remaining messages without delay, up to the total of about 300.

Thanks for the test case. I was afraid that my findings would be difficult to reproduce.

Feel free to close this issue, I can reopen when I have time for more testing and come up with new findings.

[icing]

Could you give us a trace with -v --trace-config all of such a delay? That would be helpful. Please remember to black out any authentication information. Thanks!

[ralfjunker]

Here you go, both stderr and stdout logged to separate files:

• err.txt
• out.txt

The timestamps in err.txt show the delay, during which there is some activity which is probably causing it.

out.txt shows the curl.exe command issued, version is v8.9.1.

[Gilles760]

Hi,

I have almost the same problem with pop3, with the last curl official version 8.9.1.
But in my case on messages retreive (RETR).

The payload starts, then a lock of 10 minutes, and the rest of the payload.

Thx

log.txt

[icing]

Thanks! That gives some insight:

@bagder The server sends the complete response to the command of 2706 bytes. But Curl_pp_readresp() reads with a 900 bytes buffer (pingpong.c:305). It gets 900 bytes and processes it.

Then it returns and polling the socket will give no event, as the data is pending in the SSL buffers. I suspect the connection timeout just triggers another run which consumes the rest of the response.

Should pingpong expire RUN_NOW the transfer when there is data pending? I am not highly familiar with pingpong and its internals....

[bagder]

Great analysis @icing. It seems this is exactly what is happening.

Should pingpong expire RUN_NOW the transfer when there is data pending? I am not highly familiar with pingpong and its internals....

Maybe we can tweak data_pending() for this case. I'll see if I can create a test that reproduces.

[bagder]

@ralfjunker any chance you can do a build with a test patch to see if it makes any difference for you?

diff --git a/lib/transfer.c b/lib/transfer.c
index 46fde236d..70149de69 100644
--- a/lib/transfer.c
+++ b/lib/transfer.c
@@ -120,13 +120,15 @@ static int data_pending(struct Curl_easy *data)
   struct connectdata *conn = data->conn;
 
   if(conn->handler->protocol&PROTO_FAMILY_FTP)
     return Curl_conn_data_pending(data, SECONDARYSOCKET);
 
-  /* in the case of libssh2, we can never be really sure that we have emptied
-     its internal buffers so we MUST always try until we get EAGAIN back */
-  return conn->handler->protocol&(CURLPROTO_SCP|CURLPROTO_SFTP) ||
+  /* in the case of SSH, we can never be really sure that we have emptied its
+     internal buffers so we MUST always try until we get EAGAIN back */
+  return conn->handler->protocol&(CURLPROTO_SCP|
+                                  CURLPROTO_SFTP|
+                                  CURLPROTO_POP3) ||
     Curl_conn_data_pending(data, FIRSTSOCKET);
 }
 
 /*
  * Check to see if CURLOPT_TIMECONDITION was met by comparing the time of the

[ralfjunker]

I was able to build from GIT with schannel. The patch does not fix the delay.

Some observations:

• The function data_pending(), which the patch modifies, is not called before the delay but only much later, and only once, almost at the very end of the operation.

• During the delay,

curl/lib/select.c

Line 233 in 88727f7

r = Curl_poll(pfd, (unsigned int)num, timeout_ms);

is called literally thousands of times and always returns 0. Outside the delay, it almost never returns 0.

• Being able to build, I bisected: c2d9736 is the first bad commit.

Maybe this helps.

[bagder]

@ralfjunker it would be great if you could take the PR #14597 on a spin.

I have tried to reproduce this case in a local test case (by adding TLS to test case 993) but failed so I can't know for sure I am actually addressing the correct case you experience.

[ralfjunker]

👍 The PR works well with the pop3 LIST request, there is no delay.

👎 The PR causes still has a delay of almost exactly 2 minutes for the pop3 STAT request.

Command: curl.exe --request STAT --ssl-reqd -v --trace-config all --insecure -u use:pwd pop3s://pop.gmx.net

In the case of STAT, the output is short and the delay happens after all output is written. See the
error log for details.

To reproduce, maybe it helps to open a free mail account: https://en.wikipedia.org/wiki/GMX_Mail

[bagder]

Sorry, are you saying this PR adds that STAT delay or that it was there already before and this fix does not fix it?

You did not mention any STAT delay before.

[ralfjunker]

I did not run STAT before. Apologies for the confusion.

The STAT delay was there already before the fix. It is in both 8.9.1 (error log) as well as 8.5.0 (error log).

As STAT is delayed in 8.5.0 (which did not delay LIST), it was there also before c2d9736 delayed LIST.

[bagder]

Then I think we should make a new separate issue for the STAT problem because it is evidently a different one, and we keep this for the LIST delay.