POP3 error with big box

Use this forum if you have installed hMailServer and want to ask a question related to a production release of hMailServer. Before posting, please read the troubleshooting guide. A large part of all reported issues are already described in detail here.
Post Reply
sbouli
Normal user
Normal user
Posts: 69
Joined: 2007-11-27 12:37

POP3 error with big box

Post by sbouli » 2015-11-12 11:52

Hi,

I try to pop a big number of email from within the server running hmailserver ... but I get a kind of timeout on the LIST :

2015-11-12 09:45:03.831000 UTC - 0[2511140]: Setting server busy in nsPop3Protocol::LoadUrl
2015-11-12 09:45:04.862000 UTC - 0[2511140]: Entering NET_ProcessPop3 10
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 1
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 2
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 4
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: +OK POP3
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 26
2015-11-12 09:45:04.862000 UTC - 0[2511140]: SEND: AUTH

2015-11-12 09:45:04.862000 UTC - 0[2511140]: Entering NET_ProcessPop3 40
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: -ERR Invalid command in current state.
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 27
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 28
2015-11-12 09:45:04.862000 UTC - 0[2511140]: SendCapa()
2015-11-12 09:45:04.862000 UTC - 0[2511140]: SEND: CAPA

2015-11-12 09:45:04.862000 UTC - 0[2511140]: Entering NET_ProcessPop3 43
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: +OK CAPA list follows
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 29
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: USER
2015-11-12 09:45:04.862000 UTC - 0[2511140]: capa processed
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 29
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: UIDL
2015-11-12 09:45:04.862000 UTC - 0[2511140]: capa processed
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 29
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: TOP
2015-11-12 09:45:04.862000 UTC - 0[2511140]: capa processed
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 29
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: .
2015-11-12 09:45:04.862000 UTC - 0[2511140]: capa processed
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 30
2015-11-12 09:45:04.862000 UTC - 0[2511140]: ProcessAuth()
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP auth: server caps 0x4AA, pref 0x1C00, failed 0x0, avail caps 0x400
2015-11-12 09:45:04.862000 UTC - 0[2511140]: (GSSAPI = 0x100000, CRAM = 0x2000, APOP = 0x4000, NTLM = 0x8000, MSN = 0x10000, PLAIN = 0x1000, LOGIN = 0x800, USER/PASS = 0x400)
2015-11-12 09:45:04.862000 UTC - 0[2511140]: trying auth method 0x400
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP username
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 5
2015-11-12 09:45:04.862000 UTC - 0[2511140]: OnPromptStart()
2015-11-12 09:45:04.862000 UTC - 0[2511140]: Entering NET_ProcessPop3 0
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 48
2015-11-12 09:45:04.862000 UTC - 0[2511140]: SendUsername()
2015-11-12 09:45:04.862000 UTC - 0[2511140]: USER login
2015-11-12 09:45:04.862000 UTC - 0[2511140]: SEND: USER nobody

2015-11-12 09:45:04.862000 UTC - 0[2511140]: Entering NET_ProcessPop3 24
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:04.862000 UTC - 0[2511140]: RECV: +OK Send your password
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 31
2015-11-12 09:45:04.862000 UTC - 0[2511140]: NextAuthStep()
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 6
2015-11-12 09:45:04.862000 UTC - 0[2511140]: POP3: Entering state: 50
2015-11-12 09:45:04.862000 UTC - 0[2511140]: SendPassword()
2015-11-12 09:45:04.862000 UTC - 0[2511140]: PASS password
2015-11-12 09:45:04.862000 UTC - 0[2511140]: Logging suppressed for this command (it probably contained authentication information)
2015-11-12 09:45:09.456000 UTC - 0[2511140]: Entering NET_ProcessPop3 30
2015-11-12 09:45:09.456000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:09.456000 UTC - 0[2511140]: RECV: +OK Mailbox locked and ready
2015-11-12 09:45:09.456000 UTC - 0[2511140]: POP3: Entering state: 31
2015-11-12 09:45:09.456000 UTC - 0[2511140]: NextAuthStep()
2015-11-12 09:45:09.456000 UTC - 0[2511140]: login succeeded
2015-11-12 09:45:09.456000 UTC - 0[2511140]: POP3: Entering state: 7
2015-11-12 09:45:09.456000 UTC - 0[2511140]: SEND: STAT

2015-11-12 09:45:09.581000 UTC - 0[2511140]: Entering NET_ProcessPop3 23
2015-11-12 09:45:09.581000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:09.581000 UTC - 0[2511140]: RECV: +OK 717958 1094851138
2015-11-12 09:45:09.581000 UTC - 0[2511140]: POP3: Entering state: 8
2015-11-12 09:45:09.581000 UTC - 0[2511140]: BeginMailDelivery acquiring semaphore
2015-11-12 09:45:09.596000 UTC - 0[2511140]: POP3: Entering state: 9
2015-11-12 09:45:09.596000 UTC - 0[2511140]: SEND: LIST

2015-11-12 09:45:09.659000 UTC - 0[2511140]: Entering NET_ProcessPop3 41
2015-11-12 09:45:09.659000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:09.659000 UTC - 0[2511140]: RECV: +OK 717958 messages (1094851138 octets)
2015-11-12 09:45:09.659000 UTC - 0[2511140]: POP3: Entering state: 10
2015-11-12 09:46:49.831000 UTC - 0[2511140]: Entering NET_ProcessPop3 0

2015-11-12 09:46:49.831000 UTC - 0[2511140]: POP3: Entering state: 24
2015-11-12 09:46:49.831000 UTC - 0[2511140]: Calling ReleaseFolderLock from AbortMailDelivery
2015-11-12 09:46:49.831000 UTC - 0[2511140]: ReleaseFolderLock haveSemaphore = TRUE
2015-11-12 09:46:49.831000 UTC - 0[2511140]: POP3: Entering state: 25
2015-11-12 09:46:49.831000 UTC - 0[2511140]: Clearing server busy in POP3_FREE
2015-11-12 09:46:49.831000 UTC - 0[2511140]: Clearing running protocol in POP3_FREE
2015-11-12 09:46:49.846000 UTC - 0[2511140]: ~nsPop3Protocol()
2015-11-12 09:46:49.846000 UTC - 0[2511140]: Calling ReleaseFolderLock from ~nsPop3Sink
2015-11-12 09:46:49.846000 UTC - 0[2511140]: ReleaseFolderLock haveSemaphore = FALSE


what can I change to be able to download A BIG amount of email ? in either hmailserver (this instance exists only for that) or in thunderbird ....

Thanks for your help !!

Stéphane

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-12 12:14

That log isnt from Hmailserver is it.

From what I see the 1minute 49 second delay may be due to wait on HMS to reply or more likely for your client to 'move on' to the next stage (thereby suggesting the performance issue is with the client).

So, to prove or disprove, can you enable POP logging in HMS, perform the test again and post the corresponding section of your HMS log file.
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

sbouli
Normal user
Normal user
Posts: 69
Joined: 2007-11-27 12:37

Re: POP3 error with big box

Post by sbouli » 2015-11-12 12:40

Hi,

here is the HMS log for a new pop "session" :

Code: Select all

"TCPIP"    2076    "2015-11-12 11:29:27.066"    "TCP - 127.0.0.1 connected to 127.0.0.1:110."
"POP3D"    2076    1054    "2015-11-12 11:29:27.066"  "127.0.0.1"    "SENT: +OK POP3"
"POP3D"    2752    1054    "2015-11-12 11:29:27.066"  "127.0.0.1"    "RECEIVED: CAPA"
"POP3D"    2752    1054    "2015-11-12 11:29:27.066"  "127.0.0.1"    "SENT: +OK CAPA list follows[nl]USER[nl]UIDL[nl]TOP[nl]."
"POP3D"    2076    1054    "2015-11-12 11:29:27.082"  "127.0.0.1"    "RECEIVED: USER nobody"
"POP3D"    2076    1054    "2015-11-12 11:29:27.082"  "127.0.0.1"    "SENT: +OK Send your password"
"POP3D"    3568    1054    "2015-11-12 11:29:27.082"  "127.0.0.1"    "RECEIVED: PASS ***"
"POP3D"    3568    1054    "2015-11-12 11:29:31.957"  "127.0.0.1"    "SENT: +OK Mailbox locked and ready"
"POP3D"    2752    1054    "2015-11-12 11:29:31.957"  "127.0.0.1"    "RECEIVED: STAT"
"POP3D"    2752    1054    "2015-11-12 11:29:32.003"  "127.0.0.1"    "SENT: +OK 718664 1096522385"
"POP3D"    2456    1054    "2015-11-12 11:29:32.019"  "127.0.0.1"    "RECEIVED: LIST"
"POP3D"    2456    1054    "2015-11-12 11:29:32.066"  "127.0.0.1"    "SENT: +OK 718664 messages (1096522385 octets)"
EDIT : nothing more after this, neither with 127.0.0.1 or 1054 or POP3 ...


Stéphane

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-12 12:45

And what does the other log say at the same time? Because that HMS log suggests that it is now waiting on the client to respond (so the problem is with your client):
"POP3D" 2456 1054 "2015-11-12 11:29:32.019" "127.0.0.1" "RECEIVED: LIST"
"POP3D" 2456 1054 "2015-11-12 11:29:32.066" "127.0.0.1" "SENT: +OK 718664 messages (1096522385 octets)"
Last command was from hmailserver.

I think you need to start looking at performance improvement in the client.
2015-11-12 09:45:09.659000 UTC - 0[2511140]: Entering NET_ProcessPop3 41
2015-11-12 09:45:09.659000 UTC - 0[2511140]: POP3: Entering state: 3
2015-11-12 09:45:09.659000 UTC - 0[2511140]: RECV: +OK 717958 messages (1094851138 octets) <<<-- received from HMS
2015-11-12 09:45:09.659000 UTC - 0[2511140]: POP3: Entering state: 10
2015-11-12 09:46:49.831000 UTC - 0[2511140]: Entering NET_ProcessPop3 0


(Have you considered IMAP instead? Out of interest, what client are you using? Outlook by chance?)
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

sbouli
Normal user
Normal user
Posts: 69
Joined: 2007-11-27 12:37

Re: POP3 error with big box

Post by sbouli » 2015-11-12 13:12

Hello,

with both log :

First HMS :

Code: Select all

"TCPIP"    2076    "2015-11-12 12:00:56.926"    "TCP - 127.0.0.1 connected to 127.0.0.1:110."
"POP3D"    2076    1653    "2015-11-12 12:00:56.926"  "127.0.0.1"    "SENT: +OK POP3"
"POP3D"    2088    1653    "2015-11-12 12:00:56.942"  "127.0.0.1"    "RECEIVED: AUTH"
"POP3D"    2088    1653    "2015-11-12 12:00:56.942"  "127.0.0.1"    "SENT: -ERR Invalid command in current state."
"POP3D"    2076    1653    "2015-11-12 12:00:56.958"  "127.0.0.1"    "RECEIVED: CAPA"
"POP3D"    2076    1653    "2015-11-12 12:00:56.958"  "127.0.0.1"    "SENT: +OK CAPA list follows[nl]USER[nl]UIDL[nl]TOP[nl]."
"POP3D"    2088    1653    "2015-11-12 12:00:56.958"  "127.0.0.1"    "RECEIVED: USER nobody"
"POP3D"    2088    1653    "2015-11-12 12:00:56.973"  "127.0.0.1"    "SENT: +OK Send your password"
"POP3D"    2088    1653    "2015-11-12 12:00:56.973"  "127.0.0.1"    "RECEIVED: PASS ***"
"POP3D"    2088    1653    "2015-11-12 12:01:01.051"  "127.0.0.1"    "SENT: +OK Mailbox locked and ready"
"POP3D"    2076    1653    "2015-11-12 12:01:01.051"  "127.0.0.1"    "RECEIVED: STAT"
"POP3D"    2076    1653    "2015-11-12 12:01:01.098"  "127.0.0.1"    "SENT: +OK 719139 1097486385"
"POP3D"    2088    1653    "2015-11-12 12:01:01.098"  "127.0.0.1"    "RECEIVED: LIST"
"POP3D"    2088    1653    "2015-11-12 12:01:01.145"  "127.0.0.1"    "SENT: +OK 719139 messages (1097486385 octets)"
And then thunderbird (UTC = [now-1h] here)

Code: Select all

2015-11-12 11:00:55.911000 UTC - 0[1f11140]: Setting server busy in nsPop3Protocol::LoadUrl
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: Entering NET_ProcessPop3 10
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: POP3: Entering state: 1
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: POP3: Entering state: 2
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: POP3: Entering state: 4
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: RECV: +OK POP3
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: POP3: Entering state: 26
2015-11-12 11:00:56.942000 UTC - 0[1f11140]: SEND: AUTH

2015-11-12 11:00:56.958000 UTC - 0[1f11140]: Entering NET_ProcessPop3 40
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 3
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: RECV: -ERR Invalid command in current state.
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 27
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 28
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: SendCapa()
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: SEND: CAPA

2015-11-12 11:00:56.958000 UTC - 0[1f11140]: Entering NET_ProcessPop3 43
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 3
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: RECV: +OK CAPA list follows
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 29
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: RECV: USER
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: capa processed
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 29
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: RECV: UIDL
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: capa processed
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 29
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: RECV: TOP
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: capa processed
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 29
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: RECV: .
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: capa processed
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 30
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: ProcessAuth()
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP auth: server caps 0x4AA, pref 0x1C00, failed 0x0, avail caps 0x400
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: (GSSAPI = 0x100000, CRAM = 0x2000, APOP = 0x4000, NTLM = 0x8000, MSN =  0x10000, PLAIN = 0x1000, LOGIN = 0x800, USER/PASS = 0x400)
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: trying auth method 0x400
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP username
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 5
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: OnPromptStart()
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: Entering NET_ProcessPop3 0
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: POP3: Entering state: 48
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: SendUsername()
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: USER login
2015-11-12 11:00:56.958000 UTC - 0[1f11140]: SEND: USER nobody

2015-11-12 11:00:56.973000 UTC - 0[1f11140]: Entering NET_ProcessPop3 24
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: POP3: Entering state: 3
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: RECV: +OK Send your password
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: POP3: Entering state: 31
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: NextAuthStep()
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: POP3: Entering state: 6
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: POP3: Entering state: 50
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: SendPassword()
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: PASS password
2015-11-12 11:00:56.973000 UTC - 0[1f11140]: Logging suppressed for this command (it probably contained authentication information)
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: Entering NET_ProcessPop3 30
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: POP3: Entering state: 3
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: RECV: +OK Mailbox locked and ready
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: POP3: Entering state: 31
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: NextAuthStep()
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: login succeeded
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: POP3: Entering state: 7
2015-11-12 11:01:01.051000 UTC - 0[1f11140]: SEND: STAT

2015-11-12 11:01:01.098000 UTC - 0[1f11140]: Entering NET_ProcessPop3 23
2015-11-12 11:01:01.098000 UTC - 0[1f11140]: POP3: Entering state: 3
2015-11-12 11:01:01.098000 UTC - 0[1f11140]: RECV: +OK 719139 1097486385
2015-11-12 11:01:01.098000 UTC - 0[1f11140]: POP3: Entering state: 8
2015-11-12 11:01:01.098000 UTC - 0[1f11140]: BeginMailDelivery acquiring semaphore
2015-11-12 11:01:01.098000 UTC - 0[1f11140]: POP3: Entering state: 9
2015-11-12 11:01:01.098000 UTC - 0[1f11140]: SEND: LIST

2015-11-12 11:01:01.145000 UTC - 0[1f11140]: Entering NET_ProcessPop3 41
2015-11-12 11:01:01.145000 UTC - 0[1f11140]: POP3: Entering state: 3
2015-11-12 11:01:01.145000 UTC - 0[1f11140]: RECV: +OK 719139 messages (1097486385 octets)
[b]2015-11-12 11:01:01.145000 UTC - 0[1f11140]: POP3: Entering state: 10
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: Entering NET_ProcessPop3 0[/b]
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: POP3: Entering state: 24
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: Calling ReleaseFolderLock from AbortMailDelivery
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: ReleaseFolderLock haveSemaphore = TRUE
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: POP3: Entering state: 25
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: Clearing server busy in POP3_FREE
2015-11-12 11:02:42.004000 UTC - 0[1f11140]: Clearing running protocol in POP3_FREE
2015-11-12 11:02:42.020000 UTC - 0[1f11140]: ~nsPop3Protocol()
2015-11-12 11:02:42.020000 UTC - 0[1f11140]: Calling ReleaseFolderLock from ~nsPop3Sink
2015-11-12 11:02:42.020000 UTC - 0[1f11140]: ReleaseFolderLock haveSemaphore = FALSE

I am using THUNDERBIRD (on the same host), as for IMAP i will try ...

Stéphane

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-12 13:24

You might want to look elsewhere for the solution, namely with Mozilla: https://www.google.co.uk/search?q=thund ... cessPop3+0

(Interesting one here: https://community.plus.net/forum/index. ... c=133969.0)
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-12 15:31

700K+ messages at 130MB is quite a lot - you not thought of simply doing a clear down?
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

sbouli
Normal user
Normal user
Posts: 69
Joined: 2007-11-27 12:37

Re: POP3 error with big box

Post by sbouli » 2015-11-12 16:46

I did already trash all the mail twice, but now I need to find a way to deal with that kind of problem without trashing everything ...
It seems to work in IMAP ... I am working on it ;)

here is an answer on the Thunderbird forum : http://forums.mozillazine.org/viewtopic ... &t=2973335

Code: Select all

Do you really have 717,958 messages (taking about 1GB of space) in your inbox?

For comparison, this is what I get after detecting a new message with a Gmail POP account:

2015-11-12 12:57:53.521000 UTC - 0[4211140]: RECV: +OK 1 messages (4486 bytes)
2015-11-12 12:57:53.521000 UTC - 0[4211140]: POP3: Entering state: 10
2015-11-12 12:57:53.521000 UTC - 0[4211140]: RECV: 1 4486
2015-11-12 12:57:53.521000 UTC - 0[4211140]: POP3: Entering state: 10
2015-11-12 12:57:53.521000 UTC - 0[4211140]: RECV: .
2015-11-12 12:57:53.521000 UTC - 0[4211140]: POP3: Entering state: 11
2015-11-12 12:57:53.521000 UTC - 0[4211140]: SEND: UIDL

In your log file state 10 is LIST_SEARCH_HEADERS . TB sent a LIST command and got back a OK status and the number of messages and their total size in the mailbox, but didn't get a subsequent scan listing. That is probably why it went to state 24 (ERROR_DONE) and then "AbortMailDelivery". The POP3 server should have explicitly returned an error (-ERR followed by a error message) when it ran into a problem returning the scan listing. It looks like Thunderbird wasn't coded defensively enough and since they got an +OK and no scan listing, it was interpreted as there is no new mail.

In my case TB got a OK status and the number of messages and their total size in the mailbox, a scan listing of the new messages (there was only one) and then sent a UIDL command to get a unique-id listing for that message.

I've used hMailServer (installed on my PC) before with a IMAP account. It worked fine with Thunderbird. I suggest you see if you have the same problem with a IMAP account. I'm suggesting it just for troubleshooting purposes, I'm not suggesting you switch. You don't need to delete the POP account to add the IMAP account.

I may have gotten some details wrong (I'm more familiar with the IMAP protocol) but I think I'm in the right ballpark. Since the server is installed on the same PC as Thunderbird you can safely make a insecure connection using telnet from a windows console and see it it has similar problems. See https://sites.google.com/a/geekmungus.c ... fortesting for how to do that.
Will keep you informed !

Stéphane
Last edited by jimimaseye on 2015-11-12 17:21, edited 1 time in total.
Reason: url modified to work

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-12 18:57

So according to that one answer they are suggesting the hmailserver is at fault.

Hmmmmmm....... Perhaps its the sheer size/quantity of the emails tat makes your HMS choke before issuing the listing.

From page 7 of https://tools.ietf.org/html/rfc1939#page-7 :

Code: Select all

  Examples:
             C: LIST
             S: +OK 2 messages (320 octets)
             S: 1 120
             S: 2 200
             S: .
               ...
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
mattg
Moderator
Moderator
Posts: 20799
Joined: 2007-06-14 05:12
Location: 'The Outback' Australia

Re: POP3 error with big box

Post by mattg » 2015-11-13 03:40

I'd think this is a POP3 timeout issue personally

Check the advanced settings for thunderbird, and look under 'timeout' for something that looks relevant. Most POP3 clients timeout at around 1 to 2 minutes by default.
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-13 09:11

Wel yes, its a tieout of some reason. Thing is it ddnt receive the list of messages that (seemingly) should be following the first response. IT received
"POP3D" 2088 1653 "2015-11-12 12:01:01.145" "127.0.0.1" "SENT: +OK 719139 messages (1097486385 octets)"
but then nothing. It waited 1minute 40 seconds and no list was received. That RFC seems to me that the server should also be sending an individual list immediately after this line but nothing is received (hence the timeout).
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
mattg
Moderator
Moderator
Posts: 20799
Joined: 2007-06-14 05:12
Location: 'The Outback' Australia

Re: POP3 error with big box

Post by mattg » 2015-11-13 10:04

I disagree that 'nothing is received'.

I think that ALL of a single message is not received, hence the timeout.
Perhaps a single large message is holding this up.

Change the timeout to 10 minutes at least if you can and try again
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

User avatar
jimimaseye
Moderator
Moderator
Posts: 8551
Joined: 2011-09-08 17:48

Re: POP3 error with big box

Post by jimimaseye » 2015-11-13 10:28

As I can tell (or interpret from the RFC) it isnt actually sending the message, it should just be sending the message properties (list number, uid) and would be surprised if it takes the server 1m 40 seconds to send the first entry. That said, I dont know how it compiles the list: if it is building the list (all 700k entries in it) before it then starts to report the list back then it still fits in with the original statement that it is due to the message count be too large (and/or the server being WAY too underpowered). That said, if on the contrary it doesnt compile the list first, and should start sending the list one-by-one as it finds them, then this lays the issue at HMS feet.

The problem is reproducing this to test. Anyone got an email account, connecting by POP, that has over 700,000 messages in the INBOX?? (no? I didnt think so. )

(I think I read somewhere yesterday of a similar issue and the user found it to be a problem in one of the emails: they found the email and deleted it then everything returned to normal. Cant remember if this was an EXACT replication of this problem though).
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

sbouli
Normal user
Normal user
Posts: 69
Joined: 2007-11-27 12:37

Re: POP3 error with big box

Post by sbouli » 2015-11-13 10:51

Hi guys,

I really think that this problem is not high priority ... how many of us have this amount of email in one account ?

I was just hopping to use a easy way to handle the returned mail in only one spot and using the filters to deal with it (I am used to HMS ;) ) ...
In IMAP it seems to work but the size of the box in HMS is not dropping down ...
I think that I will change for postfix only to get the mails and drop them as files, I will then use linux to filter the files (I will then be able to move the files around on multiple servers if needed) .. I think of postfix instead of HMS because of the database problem and that file parsing will be way easier on linux.

Like that, no more pop or imap ... but I will have to convert the message rules in bash script ... (this part was in the hands of my colleague who doesn't code in bash).

The only thing that may interest HMS users is for an old account forgetted that we might whant to have a look to before dropping the mails ...

Whatsoever, I will still use HMS for all the boxes we use in the office ! THANKS for this perfect software !!

EDIT : the VM with the HMS and Thunderbird is with 8vcpu (no cpu limit), 8Go and currently use about 20/30% cpu and 2.45Go ...

Stéphane

Post Reply