Commands are not handled individually when a client sends
Open, HighPublic

Description

[root@ke14rl7 log]# rpm -qv guam
guam-0.8.3-1.4.el7.kolab_16.x86_64

Updated to Kolab 16 from KE14 and configured kolab-imap and guam:

[root@ke14rl7 yum.repos.d]# setup-kolab imap
[root@ke14rl7 yum.repos.d]# setup-kolab guam
Created symlink from /etc/systemd/system/multi-user.target.wants/guam.service to /usr/lib/systemd/system/guam.service.

After that, netstat shows that guam (beam.smp) is listening on port 143 and 993, and that cyrus-imapd is listening on 9993:

[root@ke14rl7 log]# netstat -tlnp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
tcp        0      0 0.0.0.0:3306            0.0.0.0:*               LISTEN      1400/mysqld         
tcp        0      0 127.0.0.1:10026         0.0.0.0:*               LISTEN      1189/python         
tcp        0      0 127.0.0.1:10027         0.0.0.0:*               LISTEN      1482/master         
tcp        0      0 0.0.0.0:587             0.0.0.0:*               LISTEN      1482/master         
tcp        0      0 0.0.0.0:4369            0.0.0.0:*               LISTEN      718/epmd            
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      977/sshd            
tcp        0      0 0.0.0.0:25              0.0.0.0:*               LISTEN      1482/master         
tcp        0      0 0.0.0.0:4190            0.0.0.0:*               LISTEN      1585/cyrus-master   
tcp        0      0 0.0.0.0:37246           0.0.0.0:*               LISTEN      664/beam.smp        
tcp        0      0 127.0.0.1:10024         0.0.0.0:*               LISTEN      1607/amavisd (maste 
tcp        0      0 127.0.0.1:9993          0.0.0.0:*               LISTEN      1585/cyrus-master   
tcp        0      0 127.0.0.1:10025         0.0.0.0:*               LISTEN      1482/master         
tcp6       0      0 :::587                  :::*                    LISTEN      1482/master         
tcp6       0      0 :::143                  :::*                    LISTEN      664/beam.smp        
tcp6       0      0 :::80                   :::*                    LISTEN      983/httpd           
tcp6       0      0 :::4369                 :::*                    LISTEN      718/epmd            
tcp6       0      0 :::22                   :::*                    LISTEN      977/sshd            
tcp6       0      0 :::25                   :::*                    LISTEN      1482/master         
tcp6       0      0 :::4190                 :::*                    LISTEN      1585/cyrus-master   
tcp6       0      0 :::993                  :::*                    LISTEN      664/beam.smp        
tcp6       0      0 :::389                  :::*                    LISTEN      749/ns-slapd        
tcp6       0      0 ::1:10024               :::*                    LISTEN      1607/amavisd (maste 
[root@ke14rl7 log]#

guam is running with the standard config file:

%% Example configuration for Guam.
[
    {
        kolab_guam, [
            {
                imap_servers, [
                    {
                        imaps, [
                            { host, "127.0.0.1" },
                            { port, 9993 },
                            { tls, true }
                        ]
                    }
                ]
            },
            {
                listeners, [
                    {
                        imap, [
                            { port, 143 },
                            { imap_server, imaps },
                            {
                                rules, [
                                    { filter_groupware, [] }
                                ]
                            },
                            {
                                tls_config, [
                                    { certfile, "/etc/pki/cyrus-imapd/cyrus-imapd.pem" }
                                ]
                            }
                        ]
                    },
                    {
                        imaps, [
                            { port, 993 },
                            { implicit_tls, true },
                            { imap_server, imaps },
                            {
                                rules, [
                                    { filter_groupware, [] }
                                ]
                            },
                            {
                                tls_config, [
                                    { certfile, "/etc/pki/cyrus-imapd/cyrus-imapd.pem" }
                                ]
                            }
                        ]
                    }
                ]
            }
        ]
    },

    {
        lager, [
            {
                handlers, [
                    { lager_console_backend, warning },
                    { lager_file_backend, [ { file, "log/error.log"}, { level, error } ] },
                    { lager_file_backend, [ { file, "log/console.log"}, { level, info } ] }
                ]
            }
        ]
    },

    %% SASL config
    {
        sasl, [
            { sasl_error_logger, { file, "log/sasl-error.log" } },
            { errlog_type, error },
            { error_logger_mf_dir, "log/sasl" },      % Log directory
            { error_logger_mf_maxbytes, 10485760 },   % 10 MB max file size
            { error_logger_mf_maxfiles, 5 }           % 5 files max
        ]
    }
].

However, the groupware folders are not filtered out:

[root@ke14rl7 log]# echo ". LIST \"\" \"*\"" | imtest -t "" -u alice.cooper@kolab.io -a alice.cooper@kolab.io -w policeman localhost
S: * OK [CAPABILITIES IMAP4rev1 STARTTLS LITERAL+ ID ENABLE SASL-IR LOGINDISABLED] ke14rl7.kolab.io Cyrus IMAP 2.5.10-49-g2e214b4-Kolab-2.5.10-8.1.el7.kolab_14 server ready
C: S01 STARTTLS
S: S01 OK Begin TLS negotiation now
verify error:num=18:self signed certificate
TLS connection established: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
C: C01 CAPABILITY
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE URLAUTH URLAUTH=BINARY X-NETSCAPE AUTH=PLAIN AUTH=LOGIN SASL-IR X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
S: C01 OK Completed
C: A01 AUTHENTICATE PLAIN YWxpY2UuY29vcGVyQGtvbGFiLmlvAGFsaWNlLmNvb3BlckBrb2xhYi5pbwBwb2xpY2VtYW4=
S: A01 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE URLAUTH URLAUTH=BINARY X-NETSCAPE LOGINDISABLED X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] Success (tls protection) SESSIONID=<ke14rl7.kolab.io-1666-1481299800-1-15845828290821351756>
Authenticated.
Security strength factor: 256
C: Q01 LOGOUT
* LIST (\Noinferiors \HasNoChildren) "/" INBOX
* LIST (\HasNoChildren) "/" Archive
* LIST (\HasChildren) "/" Calendar
* LIST (\HasNoChildren) "/" "Calendar/Personal Calendar"
* LIST (\HasNoChildren) "/" Configuration
* LIST (\HasChildren) "/" Contacts
* LIST (\HasNoChildren) "/" "Contacts/Personal Contacts"
* LIST (\HasNoChildren) "/" Drafts
* LIST (\HasChildren) "/" Files
* LIST (\HasNoChildren) "/" "Files/New folder"
* LIST (\HasNoChildren) "/" Freebusy
* LIST (\HasNoChildren) "/" Journal
* LIST (\HasNoChildren) "/" Notes
* LIST (\HasNoChildren) "/" Sent
* LIST (\HasNoChildren) "/" Spam
* LIST (\HasNoChildren) "/" Tasks
* LIST (\HasNoChildren) "/" Trash
. OK Completed (0.010 secs 18 calls)
* BYE LOGOUT received
Q01 OK Completed
Connection closed.
[root@ke14rl7 log]#

Error log:

[root@ke14rl7 guam]# cat error.log 
2016-12-09 16:46:04.292 [error] <0.123.0> gen_fsm <0.123.0> in state disconnected terminated with reason: no match of right hand value {{error,econnrefused},true,<0.123.0>,{[],[]}} in eimap:disconnected/2 line 137
2016-12-09 16:46:04.307 [error] <0.123.0> CRASH REPORT Process <0.123.0> with 0 neighbours exited with reason: no match of right hand value {{error,econnrefused},true,<0.123.0>,{[],[]}} in eimap:disconnected/2 line 137 in gen_fsm:terminate/7 line 626
[root@ke14rl7 guam]#

Crashlog:

[root@ke14rl7 guam]# cat crash.log 
2016-12-09 16:46:04 =ERROR REPORT====
** State machine <0.123.0> terminating 
** Last event in was {connect,<0.108.0>,server_hello}
** When State == disconnected
**      Data  == {state,"127.0.0.1",9993,true,false,undefined,<<>>,1,{[],[]},undefined,undefined,false,undefined,<<>>,undefined,undefined,false}
** Reason for termination = 
** {{badmatch,{{error,econnrefused},true,<0.123.0>,{[],[]}}},[{eimap,disconnected,2,[{file,"src/eimap.erl"},{line,137}]},{gen_fsm,handle_msg,7,[{file,"gen_fsm.erl"},{line,518}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
2016-12-09 16:46:04 =CRASH REPORT====
  crasher:
    initial call: eimap:init/1
    pid: <0.123.0>
    registered_name: []
    exception exit: {{{badmatch,{{error,econnrefused},true,<0.123.0>,{[],[]}}},[{eimap,disconnected,2,[{file,"src/eimap.erl"},{line,137}]},{gen_fsm,handle_msg,7,[{file,"gen_fsm.erl"},{line,518}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]},[{gen_fsm,terminate,7,[{file,"gen_fsm.erl"},{line,626}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
    ancestors: [<0.108.0>,<0.93.0>,kolab_guam_sup,<0.88.0>]
    messages: []
    links: [<0.108.0>]
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 1598
    stack_size: 27
    reductions: 3223
  neighbours:
[root@ke14rl7 guam]#

Details

Ticket Type
Task
petersen created this task.Dec 9 2016, 5:10 PM
petersen raised the priority of this task from 60 to High.
petersen assigned this task to seigo.
petersen added projects: Kolab 16, Guam.
petersen updated the task description. (Show Details)Dec 9 2016, 5:23 PM
petersen updated the task description. (Show Details)

I could narrow it a bit down towards multiline input (IMO). The single commands are processed and filtered correctly. In the moment you or the client issues multiple IMAP commands at once guam isn't able to intercept and split it correctly.

Only LIST:

# echo 'a0003 LIST "" ""' | imtest -m login -a daniel.hoffend@dotlan.info -w xxx -s localhost -p 993
verify error:num=20:unable to get local issuer certificate
verify error:num=27:certificate not trusted
TLS connection established: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)
S: * OK [CAPABILITIES IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] kolab Cyrus IMAP 2.5.10-49-g2e214b4-Debian-2.5.10.49-0~kolab1 server ready
C: L01 LOGIN daniel.hoffend@dotlan.info {4}
S: + go ahead
C: <omitted>
S: L01 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE URLAUTH URLAUTH=BINARY LOGINDISABLED AUTH=PLAIN AUTH=LOGIN X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<kolab-26434-1481325252-1-5370517285931946706>
Authenticated.
Security strength factor: 256
C: Q01 LOGOUT
* LIST (\Noselect) "/" ""
a0003 OK Completed (0.000 secs)
* BYE LOGOUT received
Q01 OK Completed
Connection closed.

Only LSUB:

# echo 'a0004 LSUB "" "*"' | imtest -m login -a daniel.hoffend@dotlan.info -w xxx -s localhost -p 993
verify error:num=20:unable to get local issuer certificate
verify error:num=27:certificate not trusted
TLS connection established: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)
S: * OK [CAPABILITIES IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] kolab Cyrus IMAP 2.5.10-49-g2e214b4-Debian-2.5.10.49-0~kolab1 server ready
C: L01 LOGIN daniel.hoffend@dotlan.info {4}
S: + go ahead
C: <omitted>
S: L01 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE URLAUTH URLAUTH=BINARY LOGINDISABLED AUTH=PLAIN AUTH=LOGIN X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<kolab-26045-1481325265-1-9377312667545538384>
Authenticated.
Security strength factor: 256
C: Q01 LOGOUT
* LSUB (\Noinferiors) "/" INBOX
* LSUB () "/" Drafts
* LSUB () "/" Sent
* LSUB () "/" Spam
* LSUB () "/" Trash
a0004 OK Completed (0.000 secs 15 calls)
* BYE LOGOUT received
Q01 OK Completed
Connection closed.

BOTH

echo 'a0003 LIST "" ""
a0004 LSUB "" "*"' | imtest -m login -a daniel.hoffend@dotlan.info -w xxx -s localhost -p 993
verify error:num=20:unable to get local issuer certificate
verify error:num=27:certificate not trusted
TLS connection established: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)
S: * OK [CAPABILITIES IMAP4rev1 LITERAL+ ID ENABLE AUTH=PLAIN AUTH=LOGIN SASL-IR] kolab Cyrus IMAP 2.5.10-49-g2e214b4-Debian-2.5.10.49-0~kolab1 server ready
C: L01 LOGIN daniel.hoffend@dotlan.info {4}
S: + go ahead
C: <omitted>
S: L01 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE URLAUTH URLAUTH=BINARY LOGINDISABLED AUTH=PLAIN AUTH=LOGIN X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] User logged in SESSIONID=<kolab-26042-1481325285-1-8680691146708254635>
Authenticated.
Security strength factor: 256
C: Q01 LOGOUT
* LSUB (\Noinferiors) "/" INBOX
* LSUB () "/" Arbeit
* LSUB (\HasChildren) "/" Calendar
* LSUB () "/" Calendar/TesCal
* LSUB () "/" Configuration
* LSUB () "/" Contacts
* LSUB () "/" Drafts
* LSUB () "/" Files
* LSUB () "/" Freebusy
* LSUB () "/" Journal
* LSUB () "/" Notes
* LSUB () "/" Sent
* LSUB () "/" Spam
* LSUB () "/" Tasks
* LSUB () "/" Trash
a0004 OK Completed (0.000 secs 15 calls)
* BYE LOGOUT received
Q01 OK Completed
Connection closed.

Connecting with cli imap client "mutt" you can see this behavior because it always presents the full folder list (in the left folder view (patched) version as well when you want to switch the folders.

seigo renamed this task from Guam not filtering groupware folders to Commands are not handled individually when a client sends.Dec 12 2016, 11:29 AM

Still considering what to be done with this.

It requires a full command PRE-parser in guam (or, well, in eimap) to separate out multiple commands from the client and support sending them to the server in a serial fashion so that the rules have a chance to interact with each command.

If the use case is "User is using mutt to access imap", then the priority is not high. Will have to look further into what exactly is allowed as per the RFCs for client command leniency.

seigo moved this task from Backlog to Pending on the Guam board.Dec 12 2016, 2:29 PM
seigo moved this task from Pending to Backlog on the Guam board.Dec 13 2016, 2:01 PM

I've encountered another bug with guam. This time It's "eM Client" for Windows. I've activated the client debug log (in eM Client) and after sending a XLIST and SELECT command in TLS/SSL mode (it looks like the client sends 2 commands at once) the connections gets into some kind of stale mode. It's no longer working. Hard to tell without decrypting network traffic.

Using a non-tls 143 plaintext connection it seems to works through guam. The folder listing only stales on tls/ssl connections. Might be a client issue, but how knows.

22:12:04.263|027|   A5 NAMESPACE
22:12:04.328|029|   * NAMESPACE (("" "/")) (("Other Users/" "/")) (("Shared Folders/" "/"))
22:12:04.328|029|   A5 OK Completed
22:12:04.328|027|   A6 XLIST "" "%"
22:12:04.328|028|   A7 SELECT "INBOX" (CONDSTORE)
<stale>

So same issue, with slightly different results: multiple commands sent together, which is allowed by the IMAP spec indeed, and then the client ends up waiting for responses that do not come as expected. Thanks for the report.

In summary -> the clients affected thus far are: mutt, eM Client.

(There is a moral here somewhere about protocol specifications ... )

Hello,
i reported the problem by the beginning of 2017 using the mailing list.
Since it hasn't been resolved, i disabled guam by changing the cyrus config.
This was with version 0.9.2-1.
Now, today i gave it a try and installed version 0.9.2-3. (Running on debian jessie).
Thunderbird can get the mails in the inbox, but when it starts to index the folders, thunderbird hangs.
On the server i strace the guam process and see, that there are unjoined threads and they never join.
Perhaps a hint, since erlang is based on threads.
As for now, i disabled guam again.

Kind regards
Franz

pasik added a subscriber: pasik.Sep 7 2017, 9:50 PM
akop added a subscriber: akop.Sep 26 2017, 1:45 PM