I upgraded to version 0.22.0 today and installed the scripts required to use SSL using Brian Smith's SSL Setup utility. I am able to connect to my server without problem. However, it takes so long to retrieve the first message that the connection often times out. When it does not time out, messages are retreived very slowly -- 10 seconds or more per message.
I used the msgcapture.exe utility to see whether I could detect anything strange, but it gave me nothing other than the using POPfile is starting/shutting down messages.
Before the upgrade I was using OpenSSL with Stunnel to check my mail. I went back to this arrangement -- still using POPfile 0.22.0 -- and my download speeds were back to normal.
I am using Windows XP SP 1. I have Norton Antivirus 2002 screening my incoming mail for viruses, but it has no effect on the download speed when I use Stunnel.
alan
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I've just found the same problem when I tried to download a single test message using an SSL connection (with forking enabled on Win98SE system).
The Eudora progress bar got to 100% and just sat there for ages. Eventually Eudora got fed up waiting, displayed the message and the following error:
******.com, 1 message(s) left to download.,DELE 1 [11:43:19 AM]
Error reading from network. Cause: Eudora got tired of waiting for the server. (10100)
When I checked the POPFile log file I found that most of the message had been downloaded in 1 second but there seemed to be a problem right at the end of the message (1 minute delay) and another when Eudora issued the DELE command (5 minutes delay).
(some log entries removed from the following block to reduce clutter)
(following block unedited, apart from removing the date from the beginning of each line)
11:37:18 -881553: bayes: 646: Read slurp data _________________________________[0d][0a]IPCop-user XXXXXX
11:38:19 -881553: mq: 378: post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
11:38:19 -881553: mq: 393: sending post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to parent GLOB(0x146eba8)
11:38:19 699837: mq: 378: post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
11:38:19 699837: mq: 385: queuing post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
11:38:19 699837: mq: 387: COMIT queue length now 0
11:38:19 699837: mq: 129: Message COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) ready for delivery
11:38:19 699837: mq: 132: Delivering message COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to history
11:38:19 699837: mq: 132: Delivering message COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to bayes
11:38:19 -881553: pop3: 210: Command: --DELE 1--
11:38:19 -881553: pop3: 302: DELE 1[0d][0a]
11:38:19 -881553: pop3: 646: Read slurp data [0a]
11:38:19 -881553: pop3: 302: [0a]
11:43:20 -881553: mq: 378: post CMPLT (-881553)
11:43:20 -881553: mq: 393: sending post CMPLT (-881553) to parent GLOB(0x146eba8)
11:43:20 -881553: pop3: 668: POP3 proxy done
11:43:20 699837: mq: 378: post CMPLT (-881553)
11:43:20 699837: mq: 389: dropping post CMPLT (-881553)
11:43:20 699837: mq: 259: Done with -881553 (0 to go)
The last of the "Read slurp data" entries at 11:37:18 did not contain the very end of the message. I think there should have been another "Read slurp data" entry with the last line of text from the message (when I examined the received message I found it seemed to be complete though it also had two extra blank lines at the very end).
There was a mysterious delay before the next log entry appeared:
11:37:18 -881553: bayes: 646: Read slurp data ...
11:38:19 -881553: mq: 393: sending post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to parent GLOB(0x146eba8)
Perhaps your log files show similar problems? The current log file can be accessed via a link on the Configuration page in the UI and the log files themselves are normally found in the 'User Data' folder. Using
will display the location if you don't know it already.
To get a more detailed log report, use the logger_level parameter on the Advanced page in the UI. The default value is 0, using 1 gives more detail and 2 gives the maximum amount of detail (I used level 2).
Brian
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Small correction to my previous post. The "There was a mysterious delay before the next log entry appeared" log extract:
11:37:18 -881553: bayes: 646: Read slurp data ...
11:38:19 -881553: mq: 393: sending post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to parent GLOB(0x146eba8)
should have been:
11:37:18 -881553: bayes: 646: Read slurp data _________________________________[0d][0a]IPCop-user XXXXXX
11:38:19 -881553: mq: 378: post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
I've not been able to do any more SSL tests as only one of my accounts supports it and that account is not used much because the server is quite often "off the air".
Brian
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I don't have enough data to answer this question. I usually get one message a day via that account and hardly ever use it to send mail (I gave up trying to send mail after a prolonged period when the server was "off" more than it was "on").
My original report showed a test message (2,713 bytes) taking over 6 minutes to arrive (as far as Eudora was concerned). Since then I have managed to do some more tests and it seems that there is something special about my first test message.
My other test messages "only" have a 60 second delay during transmission (i.e. the final 5 minute delay does not occur) and in one case the message had no delay at all and arrived in a couple of seconds. But I'm sure that 5 minute delay has happened more than once (using the same message body - perhaps the size or content is significant?)
There may another problem with SSL support. I sent 4 messages using Eudora from my main POP3 account to my SSL-enabled account and then used Outlook Express to download these messages without using POPFile. The elapsed time to download all 4 messages was 7 seconds.
I re-sent the same 4 messages from Eudora (using "Send again") and used Outlook Express to download all 4 via POPFile with SSL. This time the elapsed time was 130 seconds (there was a 60 second delay during two of the three successful message download sequences).
Outlook Express was only able to retrieve 3 messages via POPFile with SSL, reporting error 0x800420CD 0x800CCC90 at the end. (Eudora was able to retrieve that message via POPFile with SSL)
Brian
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
>> I guess all this points towards POPFile or the SSL libraries we are using. <<
I agree. My SSL Setup wizard downloads the SSL components (including the OpenSSL DLLs) from the University of Winnipeg "repository" as that was the one Scott mentioned. Since all of the SSL components come from the same source, I assumed they would be compatible. (I've not tried looking for another source yet)
The SSL Setup wizard installs the OpenSSL libraries in the same directory as Net::SSLeay's SSLeay.dll (because that keeps everything under the main POPFile program directory and this is the location mentioned in the error message when the OpenSSL DLLs cannot be found by Perl).
I've also started to get GPFs in Perl58.dll since I started trying to test SSL. I've found several different versions of the OpenSSL DLLs on my hard disk so I'll try using these with POPFile to see if it makes any difference.
Brian
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Plus the earlier mentioned issue that may or may not be related to the slowness some are experiencing.
Problem is, AS doesn't seem to carry Net_SSLeay and the Perl module must match the openssl library. I have no idea where one can find a pre-compiled Win version other than the one repository at uwinnepeg.
Scott
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
>> I have no idea where one can find a pre-compiled Win version other than the one repository at uwinnepeg. <<
Same here. I've found some mirrors for IO::Socket::SSL and Net::SSLeay but they all omit the OpenSSL DLLs and simply refer back to uwinnipeg for them. (I've seen some references to newer versions of IO::Socket::SSL and Net::SSLeay but they are still unofficial versions so I've not tried to find them.)
>> Perl module must match the openssl library <<
The Net::SSLeay documentation (which is for 1.24, not the 1.25 module found at uwinnipeg) says "This module uses OpenSSL-0.9.6c. It does not work with any earlier version and there is no guarantee that it will work with later versions either, though as long as C API does not change, it should." so I tried using a matching pair of "0.9.7d 17 Mar 2004" OpenSSL DLLs.
There were no error messages but I still got the 60 second delay between a pair of "Read slurp data" entries for a small test message (1,322 bytes).
I changed the Connection Timeout (on the Configuration page) from 60 to 30 seconds, restarted POPFile, re-sent that small test message and this time the delay was 30 seconds... and it occurred at exactly the same place in the message.
The IO::Socket::SSL documentation mentions some debugging modes but I don't know enough Perl to get them to work.
At least I've stopped getting GPFs in Perl58.dll when I try to use SSL (I turned forking off and have not had any GPFs yet).
Brian
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
"If you need to select(2) on the socket, go right ahead, but be warned that OpenSSL does some internal buffering so SSL_read does not always return data even if socket selected for reading (just keep on selecting and trying to read). Net::SSLeay.pm is no different from the C language OpenSSL in this respect."
Don't know if it means anything in this context though.
Scott
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
In our Japanese forum, two users reported the similar problem.
They reported 1 or 3 minites of delay while downloading a mail via SSL.
They use Windows XP, POPFile 0.22.0 and Brian's SSL setup.
Here is a snapshot of their log:
2004/9/22 00:35:22 160: bayes: 646: Read slurp data ......[0d]　
2004/9/22 00:36:22 160: bayes: 646: Read slurp data [0a]....
One of them reported the delay may relate with the GLOBAL_timeout.
Naoki
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
>> One of them reported the delay may relate with the GLOBAL_timeout. <<
I don't know enough about how POPFile works to say for sure, but I had noticed that the "60 second" delays I see during message transfer match the time shown in the "pop3: 639: Connected to ******.com:995 timeout 60" log entry.
The "5 minute" delay I see is just Eudora's 300 second network timeout - after waiting 300 seconds for the "+OK" response to its "DELE" command, Eudora gives up and displays the message.
Brian
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I upgraded to version 0.22.0 today and installed the scripts required to use SSL using Brian Smith's SSL Setup utility. I am able to connect to my server without problem. However, it takes so long to retrieve the first message that the connection often times out. When it does not time out, messages are retreived very slowly -- 10 seconds or more per message.
I used the msgcapture.exe utility to see whether I could detect anything strange, but it gave me nothing other than the using POPfile is starting/shutting down messages.
Before the upgrade I was using OpenSSL with Stunnel to check my mail. I went back to this arrangement -- still using POPfile 0.22.0 -- and my download speeds were back to normal.
I am using Windows XP SP 1. I have Norton Antivirus 2002 screening my incoming mail for viruses, but it has no effect on the download speed when I use Stunnel.
alan
I've just found the same problem when I tried to download a single test message using an SSL connection (with forking enabled on Win98SE system).
The Eudora progress bar got to 100% and just sat there for ages. Eventually Eudora got fed up waiting, displayed the message and the following error:
******.com, 1 message(s) left to download.,DELE 1 [11:43:19 AM]
Error reading from network. Cause: Eudora got tired of waiting for the server. (10100)
When I checked the POPFile log file I found that most of the message had been downloaded in 1 second but there seemed to be a problem right at the end of the message (1 minute delay) and another when Eudora issued the DELE command (5 minutes delay).
(some log entries removed from the following block to reduce clutter)
11:37:14 -881553: pop3: 514: Connected to ******.com:995 timeout 60
11:37:15 -881553: pop3: 210: Command: --STAT--
11:37:16 -881553: pop3: 210: Command: --UIDL--
11:37:16 -881553: pop3: 210: Command: --LIST 1--
11:37:17 -881553: pop3: 210: Command: --RETR 1--
11:37:18 -881553: history: 285: reserve_slot selected random number 563568117
11:37:18 -881553: history: 312: reserve_slot returning slot id 81
11:37:18 -881553: bayes: 646: Read slurp data ...
(several "Read slurp data ..." entries deleted)
(following block unedited, apart from removing the date from the beginning of each line)
11:37:18 -881553: bayes: 646: Read slurp data _________________________________[0d][0a]IPCop-user XXXXXX
11:38:19 -881553: mq: 378: post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
11:38:19 -881553: mq: 393: sending post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to parent GLOB(0x146eba8)
11:38:19 699837: mq: 378: post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
11:38:19 699837: mq: 385: queuing post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
11:38:19 699837: mq: 387: COMIT queue length now 0
11:38:19 699837: mq: 129: Message COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) ready for delivery
11:38:19 699837: mq: 132: Delivering message COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to history
11:38:19 699837: mq: 132: Delivering message COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to bayes
11:38:19 -881553: pop3: 210: Command: --DELE 1--
11:38:19 -881553: pop3: 302: DELE 1[0d][0a]
11:38:19 -881553: pop3: 646: Read slurp data [0a]
11:38:19 -881553: pop3: 302: [0a]
11:43:20 -881553: mq: 378: post CMPLT (-881553)
11:43:20 -881553: mq: 393: sending post CMPLT (-881553) to parent GLOB(0x146eba8)
11:43:20 -881553: pop3: 668: POP3 proxy done
11:43:20 699837: mq: 378: post CMPLT (-881553)
11:43:20 699837: mq: 389: dropping post CMPLT (-881553)
11:43:20 699837: mq: 259: Done with -881553 (0 to go)
The last of the "Read slurp data" entries at 11:37:18 did not contain the very end of the message. I think there should have been another "Read slurp data" entry with the last line of text from the message (when I examined the received message I found it seemed to be complete though it also had two extra blank lines at the very end).
There was a mysterious delay before the next log entry appeared:
11:37:18 -881553: bayes: 646: Read slurp data ...
11:38:19 -881553: mq: 393: sending post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to parent GLOB(0x146eba8)
Then the DEL command sequence went wrong:
11:38:19 -881553: pop3: 210: Command: --DELE 1--
11:38:19 -881553: pop3: 302: DELE 1[0d][0a]
11:38:19 -881553: pop3: 646: Read slurp data [0a]
11:38:19 -881553: pop3: 302: [0a]
11:43:20 -881553: mq: 378: post CMPLT (-881553)
Here is a successful DELE sequence for comparison (from a non-SSL session):
10:57:18 -958465: pop3: 210: Command: --DELE 1--
10:57:18 -958465: pop3: 302: DELE 1[0d][0a]
10:57:18 -958465: pop3: 646: Read slurp data +OK Deleted.[0d][0a]
10:57:18 -958465: pop3: 302: +OK Deleted.[0d][0a]
Perhaps your log files show similar problems? The current log file can be accessed via a link on the Configuration page in the UI and the log files themselves are normally found in the 'User Data' folder. Using
Start -> Programs -> POPFile -> Support -> PFI Diagnostic utility (simple)
will display the location if you don't know it already.
To get a more detailed log report, use the logger_level parameter on the Advanced page in the UI. The default value is 0, using 1 gives more detail and 2 gives the maximum amount of detail (I used level 2).
Brian
Small correction to my previous post. The "There was a mysterious delay before the next log entry appeared" log extract:
11:37:18 -881553: bayes: 646: Read slurp data ...
11:38:19 -881553: mq: 393: sending post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0) to parent GLOB(0x146eba8)
should have been:
11:37:18 -881553: bayes: 646: Read slurp data _________________________________[0d][0a]IPCop-user XXXXXX
11:38:19 -881553: mq: 378: post COMIT (Y82Dwi2xxKY2jfY54C:81:regular:0)
I've not been able to do any more SSL tests as only one of my accounts supports it and that account is not used much because the server is quite often "off the air".
Brian
> the server is quite often "off the air".
But when on-air, it performs well?
Manni
>> But when on-air, it performs well? <<
I don't have enough data to answer this question. I usually get one message a day via that account and hardly ever use it to send mail (I gave up trying to send mail after a prolonged period when the server was "off" more than it was "on").
My original report showed a test message (2,713 bytes) taking over 6 minutes to arrive (as far as Eudora was concerned). Since then I have managed to do some more tests and it seems that there is something special about my first test message.
My other test messages "only" have a 60 second delay during transmission (i.e. the final 5 minute delay does not occur) and in one case the message had no delay at all and arrived in a couple of seconds. But I'm sure that 5 minute delay has happened more than once (using the same message body - perhaps the size or content is significant?)
There may another problem with SSL support. I sent 4 messages using Eudora from my main POP3 account to my SSL-enabled account and then used Outlook Express to download these messages without using POPFile. The elapsed time to download all 4 messages was 7 seconds.
I re-sent the same 4 messages from Eudora (using "Send again") and used Outlook Express to download all 4 via POPFile with SSL. This time the elapsed time was 130 seconds (there was a 60 second delay during two of the three successful message download sequences).
Outlook Express was only able to retrieve 3 messages via POPFile with SSL, reporting error 0x800420CD 0x800CCC90 at the end. (Eudora was able to retrieve that message via POPFile with SSL)
Brian
I should have read my message before posting - I forgot to mention that the "7 seconds" download via Outlook Express used an SSL connection.
Brian
I thought so. I guess all this points towards POPFile or the SSL libraries we are using. Right?
Manni
>> I guess all this points towards POPFile or the SSL libraries we are using. <<
I agree. My SSL Setup wizard downloads the SSL components (including the OpenSSL DLLs) from the University of Winnipeg "repository" as that was the one Scott mentioned. Since all of the SSL components come from the same source, I assumed they would be compatible. (I've not tried looking for another source yet)
The SSL Setup wizard installs the OpenSSL libraries in the same directory as Net::SSLeay's SSLeay.dll (because that keeps everything under the main POPFile program directory and this is the location mentioned in the error message when the OpenSSL DLLs cannot be found by Perl).
I've also started to get GPFs in Perl58.dll since I started trying to test SSL. I've found several different versions of the OpenSSL DLLs on my hard disk so I'll try using these with POPFile to see if it makes any difference.
Brian
Might check the openssl version number, 0.9.7c seems to have problems.
http://groups.google.com/groups?q=Net::SSLeay&start=30&hl=en&lr=&ie=UTF-8&scoring=d&selm=_mhqc.120120%24Dn1.2376%40fe2.texas.rr.com&rnum=38
Scott
The DLLs downloaded by the SSL Setup wizard appear to be from OpenSSL 0.9.7c 30 September 2003.
Brian
Great. There's a security advisory out against 0.9.7c http://www.openssl.org/news/secadv_20040317.txt
Plus the earlier mentioned issue that may or may not be related to the slowness some are experiencing.
Problem is, AS doesn't seem to carry Net_SSLeay and the Perl module must match the openssl library. I have no idea where one can find a pre-compiled Win version other than the one repository at uwinnepeg.
Scott
>> I have no idea where one can find a pre-compiled Win version other than the one repository at uwinnepeg. <<
Same here. I've found some mirrors for IO::Socket::SSL and Net::SSLeay but they all omit the OpenSSL DLLs and simply refer back to uwinnipeg for them. (I've seen some references to newer versions of IO::Socket::SSL and Net::SSLeay but they are still unofficial versions so I've not tried to find them.)
>> Perl module must match the openssl library <<
The Net::SSLeay documentation (which is for 1.24, not the 1.25 module found at uwinnipeg) says "This module uses OpenSSL-0.9.6c. It does not work with any earlier version and there is no guarantee that it will work with later versions either, though as long as C API does not change, it should." so I tried using a matching pair of "0.9.7d 17 Mar 2004" OpenSSL DLLs.
There were no error messages but I still got the 60 second delay between a pair of "Read slurp data" entries for a small test message (1,322 bytes).
I changed the Connection Timeout (on the Configuration page) from 60 to 30 seconds, restarted POPFile, re-sent that small test message and this time the delay was 30 seconds... and it occurred at exactly the same place in the message.
The IO::Socket::SSL documentation mentions some debugging modes but I don't know enough Perl to get them to work.
At least I've stopped getting GPFs in Perl58.dll when I try to use SSL (I turned forking off and have not had any GPFs yet).
Brian
I did notice this in the Net::SSLeay docs.
"If you need to select(2) on the socket, go right ahead, but be warned that OpenSSL does some internal buffering so SSL_read does not always return data even if socket selected for reading (just keep on selecting and trying to read). Net::SSLeay.pm is no different from the C language OpenSSL in this respect."
Don't know if it means anything in this context though.
Scott
>> Don't know if it means anything in this context though. <<
I think it'll depend upon what IO::Socket::SSL does as I think POPFile does not use Net::SSLeay directly.
Brian
I've made a patch for this problem. How about this?
http://sourceforge.net/tracker/index.php?func=detail&aid=1035050&group_id=63137&atid=502958
If using SSL, we may have to check the internal buffer of OpenSSL.
This patch will check the buffer by pending() function.
Naoki
>> I've made a patch for this problem. How about this? <<
Your patch fixes all of the problems I found with my simple set of 4 test messages:
(1) no more 5 minute delay at the end of test message 1 (this happened every time, before your patch)
(2) the "Read slurp data" entry for the last line of test message 1 now appears in the log (before your patch it never appeared in the log)
(3) no more 60 second delays during message downloads
(4) Outlook Express is now able to download all 4 test messages (it only managed to download 3 out of 4 before your patch)
As far as I am concerned, you've solved the problem, Naoki!
Brian
Brian,
Thanks for your report and I'm glad to hear my patch fixes your problems.
In Japanese forum, one user reported that my patch fixes his problem, too.
I'm going to ask John to merge this patch to 0.22.1.
Naoki
In our Japanese forum, two users reported the similar problem.
They reported 1 or 3 minites of delay while downloading a mail via SSL.
They use Windows XP, POPFile 0.22.0 and Brian's SSL setup.
Here is a snapshot of their log:
2004/9/22 00:35:22 160: bayes: 646: Read slurp data ......[0d]　
2004/9/22 00:36:22 160: bayes: 646: Read slurp data [0a]....
One of them reported the delay may relate with the GLOBAL_timeout.
Naoki
>> One of them reported the delay may relate with the GLOBAL_timeout. <<
I don't know enough about how POPFile works to say for sure, but I had noticed that the "60 second" delays I see during message transfer match the time shown in the "pop3: 639: Connected to ******.com:995 timeout 60" log entry.
The "5 minute" delay I see is just Eudora's 300 second network timeout - after waiting 300 seconds for the "+OK" response to its "DELE" command, Eudora gives up and displays the message.
Brian
I may have found a clue to this problem.
POPFile timeouts while
$slurp_data__{"$handle"}{select}->can_read( $self->global_config_( 'timeout' ) )
in line 531 of POPFile/Module.pm.
I don't know why this timeout occurs, but it does.
Any ideas?
Naoki