Bug 3901 - Failure (race condition) with Dovecot
Summary: Failure (race condition) with Dovecot
Status: RESOLVED INVALID
Alias: None
Product: Claws Mail (GTK 2)
Classification: Unclassified
Component: POP3 (show other bugs)
Version: 3.15.1
Hardware: PC Linux
: P3 critical
Assignee: users
URL:
Depends on:
Blocks:
 
Reported: 2017-10-01 13:05 UTC by acharnleygg
Modified: 2017-10-25 13:08 UTC (History)
0 users

See Also:


Attachments

Description acharnleygg 2017-10-01 13:05:41 UTC
I have four POP3 accounts, all accessed over SSL with valid certs. Using either Evolution or a manual login using SSL client I can login and perform a STAT command. Dovecot is working.

Claws can perform the STAT command on one account (the settings other than username are identical) but for the other three the command fails.

12:01:18] POP< +OK
[12:01:18] POP> PASS ********
[12:01:18] POP< +OK Logged in.
[12:01:18] POP> STAT
[12:01:18] POP< -ERR Unknown command: 

The only difference I can see between what Evolution/manual login is doing is a delay between receiving the OK and issuing STAT.

I've not been able to understand why it works on one of the accounts. All settings are identical.
Comment 1 acharnleygg 2017-10-01 13:16:37 UTC
On further investigation Evolution uses LIST not STAT, however I can as stated previously login over SSL and issue STAT to all accounts.

POP3_STREAM_LINE (3): '+OK'
 36 Got + response
 37 cmd_capa
 38 POP3_STREAM_LINE (4): 'CAPA'
 39 POP3_STREAM_LINE (3): 'TOP'
 40 POP3_STREAM_LINE (4): 'UIDL'
 41 POP3_STREAM_LINE (10): 'RESP-CODES'
 42 POP3_STREAM_LINE (10): 'PIPELINING'
 43 POP3_STREAM_LINE (14): 'AUTH-RESP-CODE'
 44 POP3_STREAM_LINE (END)
 45 opening pop3 INBOX folder
 46 POP3_STREAM_WRITE (6):
 47 LIST^M
UIDL^M
 51 
 52 POP3_STREAM_LINE (15): '+OK 1 messages:'
 53 Got + response
 54 POP3_STREAM_LINE (6): '1 2460'
 55 POP3_STREAM_LINE (END)
 56 POP3_STREAM_LINE (3): '+OK'
Comment 2 Paul 2017-10-01 13:21:56 UTC
did you ask the dovecot dev team about this? It looks more like a question for them than us.
Comment 3 acharnleygg 2017-10-01 13:25:58 UTC
Doing it right now, shall report back.
Comment 4 Andrej Kacian 2017-10-01 14:29:50 UTC
I suggest also looking at server logs. Perhaps they will reveal why Dovecot is acting up.
Comment 5 acharnleygg 2017-10-01 14:55:19 UTC
Already did, enabled all debug options but there's nothing there about the STAT failure. After the login it closes the connection (this is logged).
Comment 6 acharnleygg 2017-10-24 10:34:51 UTC
After conversing with the Dovecot support group it does appear to be an issue with CLAWS. 

---

> Regarding STAT which appears to have an issue with Dovecot:-
>
> [23:50:46] POP< +OK Dovecot ready.
> [23:50:46] POP> USER xxxxx
> [23:50:46] POP< +OK
> [23:50:46] POP> PASS ********
> [23:50:46] POP< +OK Logged in.
> [23:50:46] POP> STAT
> [23:50:46] POP< -ERR Unknown command:  

This response usually has the offending command behind the colon - at 
least in Dovecot v2.2

BTW: could you launch a secure connection, e.g. from the mail server

telnet localhost 110

then type in the commands yourself:

user xxxxx
pass ***
stat

----

I can confirm this works for one of the offending accounts within CLAWS.
Comment 7 Paul 2017-10-24 10:50:48 UTC
(In reply to comment #6)

This doesn't tell us anything more. Maybe if you quote your conversation with the dovecot team that will help, maybe it won't.
Comment 8 Andrej Kacian 2017-10-24 10:55:49 UTC
(In reply to comment #0)
> Claws can perform the STAT command on one account (the settings other than
> username are identical) but for the other three the command fails.

Is this happening on the same three accounts? Are these accounts being checked all at once? Do the three "non-working" accounts work when manually checked individually instead of all at once?
Comment 9 acharnleygg 2017-10-24 11:55:55 UTC
There's not much to go on. Dovecot insist it's fine and given I can telnet in and run STAT on one of the accounts that fails I'm inclined to agree.

I have four POP3 accounts, the first one (in Claws) works. The next three don't on either automatic or manual checking. Settings (other than the username) are identical to the working first account.

I still suspect there's a race condition because if I do;

user xxxx
STAT

I get "-ERR Unknown command."

Dovecot says the command is normally included before the hyphen so the outcome matches by hypothesis.

Andrew




> The reason dovecot is not logging anything is that there is nothing to
> log. Invalid command usage is not normally worthy of logging. Rawlogs
> *SHOULD* have logged it.
> 
> Aki
Comment 10 Paul 2017-10-24 12:32:25 UTC
Dose fetching from those 3 accounts succeed if you fetch individually, as Andrej asks in comment 8?

/Message/Receive/[account name]
Comment 11 acharnleygg 2017-10-24 12:44:09 UTC
No.

"The next three don't on either automatic or manual checking" ;)

The first account works fine. I changed the order so it's #2 in the auto list and #1 (which was #2) continues to fail.

Rgs,
A.
Comment 12 acharnleygg 2017-10-24 12:46:35 UTC
Actually the "Get Mail" button or "Receive > From all" doesn't do anything. Probably one of the accounts has errored and it's silently died.
Comment 13 Paul 2017-10-24 13:01:43 UTC
(In reply to comment #12)
> Actually the "Get Mail" button or "Receive > From all" doesn't do anything.
> Probably one of the accounts has errored and it's silently died.

Not doing anything seems odd. Please try that again and attach the debug output.

Start with `claws-mail --debug`, and then attach the debug output from when you attempt to fetch mail onwards.
Comment 14 Andrej Kacian 2017-10-24 13:11:05 UTC
(In reply to comment #9)
> I still suspect there's a race condition because if I do;
> 
> user xxxx
> STAT
> 
> I get "-ERR Unknown command."

No, this is correct behavior from the server, as per RFC 1939 (section 3). The STAT command simply is not available before you authenticate.

The fact that the negative response ends with a '.' instead of a ':' is due to the fact that different session states are handled by different programs in Dovecot:

vala dovecot # pwd
/usr/libexec/dovecot
vala dovecot # strings pop3-login | grep 'Unknown command'
Unknown command.
vala dovecot # strings pop3 | grep 'Unknown command'
-ERR Unknown command: %s
vala dovecot #

The question remains what exactly is being sent that Dovecot sees it as an empty command. Perhaps a space, or some other whitespace character?
Comment 15 acharnleygg 2017-10-24 14:01:47 UTC
OK I didn't have inc installed, and it's symlinked to the wrong dir. I'll have to report that to Fedora. Fixed it and now there's automation...

 Account 'xxx1': Connecting to POP3 server: xxx:995...
[12:59:22] POP< +OK Dovecot ready.
[12:59:22] POP> USER xxx1
[12:59:22] POP< +OK
[12:59:22] POP> PASS ********
[12:59:22] POP< +OK Logged in.
[12:59:22] POP> STAT
[12:59:22] POP< +OK 89 2801955
[12:59:22] POP> UIDL
[12:59:22] POP< +OK
[12:59:22] POP> LIST
[12:59:22] POP< +OK 89 messages:
[12:59:22] POP> QUIT
[12:59:23] POP< +OK Logging out.
* Account 'xxx2': Connecting to POP3 server: xxx:995...
[12:59:23] POP< +OK Dovecot ready.
[12:59:23] POP> USER xxx2
[12:59:23] POP< +OK
[12:59:23] POP> PASS ********
[12:59:24] POP< +OK Logged in.
[12:59:24] POP> STAT
[12:59:24] POP< -ERR Unknown command: 
*** error occurred on POP session
*** Error occurred while processing mail.
Comment 16 Paul 2017-10-24 14:44:46 UTC
(In reply to comment #15)

What has inc got to do with this? Are you using an external program to fetch mail?

Can you try fetching mail with just one of the problematic accounts and one only and share that debug out?
Comment 17 Michael Schwendt 2017-10-24 15:19:12 UTC
> What has inc got to do with this?

And what symlink would be relevant for inc?

The brevity of comments in this ticket is not helpful. Also, the mailing-list would be more suitable for sharing log files.
Comment 18 acharnleygg 2017-10-24 15:57:44 UTC
Paul, I was asked for multiple fetching and that I did. claws-mail uses inc underneath the hood to automate it and it was missing. That's a separate issue that I've since filed with Fedora.

Yes, let's focus on one of the accounts that doesn't work.

I have no debugging information available from Dovecot or from Claws other than what is in the log window and console.

Window:

[14:56:47] POP< +OK Logged in.
[14:56:47] POP> STAT
[14:56:47] POP< -ERR Unknown command: 
*** error occurred on POP session
*** Error occurred while processing mail.

Console:


TIMING msgcache_get_msg_list : 0s000ms
msgcache.c:277:TIMING msgcache_get_msg_list : 0s000ms
filtering.c:198:checking 0 messages

** (claws-mail:1418): WARNING **: [14:56:47] Error occurred while processing mail.

alertpanel.c:254:Creating alert panel dialog...
Comment 19 acharnleygg 2017-10-24 16:03:55 UTC
Related: https://bugzilla.redhat.com/show_bug.cgi?id=1053916
Comment 20 Paul 2017-10-24 16:41:37 UTC
(In reply to comment #17) 
> The brevity of comments in this ticket is not helpful. Also, the
> mailing-list would be more suitable for sharing log files.

Log files were asked for here, so sharing them here is fine.
Comment 21 Paul 2017-10-24 16:43:37 UTC
(In reply to comment #18)
> claws-mail uses inc underneath the hood to automate it and it was missing. 

No, it doesn't.
Comment 22 Michael Schwendt 2017-10-24 17:14:47 UTC
The ticket wrt the wrong default ext_inc_path is this:
https://bugzilla.redhat.com/1505859

See my response in that ticket.
Comment 23 acharnleygg 2017-10-24 17:26:13 UTC
OK, whatever Paul. It complained inc was missing and failed without it.
Comment 24 Paul 2017-10-24 18:46:20 UTC
(In reply to comment #23)
> OK, whatever Paul. It complained inc was missing and failed without it.

OK. It's true, though.

How does the outcome of https://bugzilla.redhat.com/1505859 reflect on this report?
Comment 25 Andrej Kacian 2017-10-25 10:37:31 UTC
Can you try manually reentering the correct password on the affected accounts? My suspicion is that you somehow have a trailing newline included in the password (perhaps via copy&paste, so Claws Mail ends up sending an extra newline after the PASS line, and before the STAT line, leading to the -ERR response.

Manual test:

$ telnet localhost 110
Trying ::1...
Connected to localhost.
Escape character is '^]'.
+OK Dovecot ready.
USER xyz1
+OK
PASS xyz%1*pwd

+OK Logged in.
-ERR Unknown command:
Comment 26 acharnleygg 2017-10-25 12:18:42 UTC
AMAZING Andrej!!

They are copy/pasted from a spreadsheet and while there's no newline in the spreadsheet value LibreOffice is inserting one on copy.

So the resolution, if a small change could be made to strip \n\r characters from the password in Claws this will not happen for other unsuspecting users.

Bravo Andrej!
Comment 27 Andrej Kacian 2017-10-25 13:08:30 UTC
In next release, there will be a "Show password" checkbox next to each password, and a newline character will be easily visible there. We will also look at adding a warning in case user enters a newline character in username or password field.

I do not like the idea of automatically correcting this for the user.

Note You need to log in before you can comment on or make changes to this bug.