GNOME Bugzilla – Bug 714018
IMAP via STARTTLS on cyrus imapd broken
Last modified: 2013-11-02 01:53:00 UTC
---- Reported by geary-maint@gnome.bugs 2013-09-09 03:25:00 -0700 ---- Original Redmine bug id: 7454 Original URL: http://redmine.yorba.org/issues/7454 Searchable id: yorba-bug-7454 Original author: Jens Georg Original description: This used to work previously. The log below is from trying to add a new account on the server. Using a dedicated SSL connection works fine. [msg] 12:19:15 0,052937 geary-application.vala:133: Geary 0.4.0pr1+trunk prefix=/usr exec_dir=/usr/bin is_installed=true [deb] 12:19:15 0,073470 libmessagingmenu.vala:30: Registered messaging-menu indicator [deb] 12:19:15 0,001306 unity-launcher.vala:44: set unity launcher entry count to 0 [deb] 12:19:15 0,053231 geary-controller.vala:906: No accounts found. [deb] 12:19:15 0,055056 conversation-web-view.vala:179: Loading new message viewer style from /home/jens/.config/geary/user-message.css... [deb] 12:19:48 32,824781 imap-client-session.vala:1429: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] Connected to mail.webstreams.de/default:143 [deb] 12:19:48 0,000008 imap-client-session.vala:591: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] Connected [deb] 12:19:48 0,000038 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] connected to mail.webstreams.de/default:143 [deb] 12:19:48 0,036576 imap-client-session.vala:1465: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] ok #1: ID "AUTH=LOGIN" "AUTH=PLAIN" SASL-IR LITERAL+ STARTTLS IMAP4rev1 ENABLE [deb] 12:19:48 0,000103 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE STARTTLS AUTH=PLAIN AUTH=LOGIN SASL-IR] mail Cyrus IMAP v2.4.16-Debian-2.4.16-4+deb7u1 server ready [deb] 12:19:48 0,000220 imap-client-session.vala:680: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] use_starttls=true is_ssl=false starttls=true [deb] 12:19:48 0,000008 imap-client-session.vala:684: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] Attempting STARTTLS... [deb] 12:19:48 0,000334 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED S] a001 starttls [deb] 12:19:48 0,133676 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] a001 OK Begin TLS negotiation now [deb] 12:19:48 0,000182 imap-deserializer.vala:247: [des:0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_TAG] Waiting for deserializer to close... [deb] 12:19:48 0,000074 imap-deserializer.vala:799: [des:0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_TAG] input error: Operation was cancelled [deb] 12:19:48 0,000076 imap-deserializer.vala:249: [des:0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_CLOSED] Deserializer closed [deb] 12:19:48 0,185523 geary-engine.vala:243: Error validating IMAP account info: Stream is already closed [deb] 12:19:48 0,030407 imap-client-connection.vala:406: [0000/mail.webstreams.de/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] Disconnecting... [deb] 12:19:48 0,000042 imap-client-connection.vala:408: [0000/mail.webstreams.de/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] Disconnected [deb] 12:19:48 0,000026 imap-client-session.vala:1435: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_DISCONNECTING] Disconnected from mail.webstreams.de/default:143 [deb] 12:19:48 0,000053 [0000/mail.webstreams.de/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_DISCONNECTED] disconnected from mail.webstreams.de/default:143 [deb] 12:19:48 0,000306 imap-client-session.vala:395: DTOR: ClientSession [deb] 12:19:48 0,075459 [mail.webstreams.de/default:587] SMTP Greeting: 220 mail.webstreams.de ESMTP Postfix (Debian/GNU) [deb] 12:19:48 0,000151 [mail.webstreams.de/default:587] SMTP Request: ehlo [192.168.34.146] [deb] 12:19:48 0,058838 [mail.webstreams.de/default:587] SMTP Response: 250-mail.webstreams.de 250-PIPELINING 250-SIZE 10240000 250-ETRN 250-STARTTLS 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN [deb] 12:19:48 0,000184 [mail.webstreams.de/default:587] SMTP Request: starttls [deb] 12:19:48 0,105839 [mail.webstreams.de/default:587] SMTP Response: 220 2.0.0 Ready to start TLS [msg] 12:19:49 0,242883 geary-endpoint.vala:126: STARTTLS TLS warnings connectin ---- Additional Comments From geary-maint@gnome.bugs 2013-11-01 18:53:00 -0700 ---- ### History #### #1 Updated by Jens Georg 2 months ago forgot: Geary is version 201309060417~0.3.1+985~ubuntu1 from the yorba PPA #### #2 Updated by Jim Nelson 2 months ago * **Category** set to _server-support_ * **Priority** changed from _Normal_ to _High_ * **Target version** set to _0.4.0_ The final warning message was cut off ("geary-endpoint.vala:126: STARTTLS TLS warnings connectin"). Can you post here what the entire line read? #### #3 Updated by Jens Georg 2 months ago Whoops, Sorry [msg] 09:27:02 0,462787 geary-application.vala:133: Geary 0.4.0pr1+trunk prefix=/usr exec_dir=/usr/bin is_installed=true Fontconfig warning: "/etc/fonts/conf.d/50-user.conf", line 14: reading configurations from ~/.fonts.conf is deprecated. [deb] 09:27:04 1,119700 libmessagingmenu.vala:30: Registered messaging-menu indicator [deb] 09:27:04 0,001233 unity-launcher.vala:44: set unity launcher entry count to 0 [deb] 09:27:04 0,364935 geary-controller.vala:906: No accounts found. [deb] 09:27:04 0,221225 conversation-web-view.vala:179: Loading new message viewer style from /home/jens/.config/geary/user-message.css... [deb] 09:27:31 27,308318 imap-client-session.vala:1429: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] Connected to mail.webstreams.de/default:143 [deb] 09:27:31 0,000014 imap-client-session.vala:591: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] Connected [deb] 09:27:31 0,000063 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] connected to mail.webstreams.de/default:143 [deb] 09:27:32 0,036246 imap-client-session.vala:1465: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] ok #1: ID "AUTH=LOGIN" "AUTH=PLAIN" SASL-IR LITERAL+ STARTTLS IMAP4rev1 ENABLE [deb] 09:27:32 0,000080 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE STARTTLS AUTH=PLAIN AUTH=LOGIN SASL-IR] mail Cyrus IMAP v2.4.16-Debian-2.4.16-4+deb7u1 server ready [deb] 09:27:32 0,000185 imap-client-session.vala:680: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] use_starttls=true is_ssl=false starttls=true [deb] 09:27:32 0,000005 imap-client-session.vala:684: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] Attempting STARTTLS... [deb] 09:27:32 0,000229 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED S] a001 starttls [deb] 09:27:32 0,133677 [0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] a001 OK Begin TLS negotiation now [deb] 09:27:32 0,000133 imap-deserializer.vala:247: [des:0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_TAG] Waiting for deserializer to close... [deb] 09:27:32 0,000054 imap-deserializer.vala:799: [des:0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_TAG] input error: Operation was cancelled [deb] 09:27:32 0,000057 imap-deserializer.vala:249: [des:0000/46.4.108.21:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_CLOSED] Deserializer closed [deb] 09:27:32 0,176597 geary-engine.vala:243: Error validating IMAP account info: Stream is already closed [deb] 09:27:32 0,029511 imap-client-connection.vala:406: [0000/mail.webstreams.de/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] Disconnecting... [deb] 09:27:32 0,000033 imap-client-connection.vala:408: [0000/mail.webstreams.de/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] Disconnected [deb] 09:27:32 0,000020 imap-client-session.vala:1435: [0000/mail.webstreams.de/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_DISCONNECTING] Disconnected from mail.webstreams.de/default:143 [deb] 09:27:32 0,000041 [0000/mail.webstreams.de/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_DISCONNECTED] disconnected from mail.webstreams.de/default:143 [deb] 09:27:32 0,000750 imap-client-session.vala:395: DTOR: ClientSession [deb] 09:27:32 0,108110 [mail.webstreams.de/default:587] SMTP Greeting: 220 mail.webstreams.de ESMTP Postfix (Debian/GNU) [deb] 09:27:32 0,000100 [mail.webstreams.de/default:587] SMTP Request: ehlo [192.168.34.146] [deb] 09:27:32 0,064060 [mail.webstreams.de/default:587] SMTP Response: 250-mail.webstreams.de 250-PIPELINING 250-SIZE 10240000 250-ETRN 250-STARTTLS 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN [deb] 09:27:32 0,000135 [mail.webstreams.de/default:587] SMTP Request: starttls [deb] 09:27:32 0,118919 [mail.webstreams.de/default:587] SMTP Response: 220 2.0.0 Ready to start TLS [msg] 09:27:32 0,254921 geary-endpoint.vala:126: STARTTLS TLS warnings connecting to mail.webstreams.de/default:587: 2h (BAD_IDENTITY) [deb] 09:27:32 0,000228 [mail.webstreams.de/default:587] SMTP Request: ehlo [192.168.34.146] [deb] 09:27:33 0,102563 [mail.webstreams.de/default:587] SMTP Response: 250-mail.webstreams.de 250-PIPELINING 250-SIZE 10240000 250-ETRN 250-AUTH PLAIN LOGIN 250-AUTH=PLAIN LOGIN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN [deb] 09:27:33 0,000474 smtp-client-session.vala:102: [mail.webstreams.de/default:587] Attempting PLAIN authenticator [deb] 09:27:33 0,000025 [mail.webstreams.de/default:587] SMTP Request: auth plain [deb] 09:27:33 0,115211 [mail.webstreams.de/default:587] SMTP Response: 334 [deb] 09:27:33 0,000012 [mail.webstreams.de/default:587] Initiated SMTP PLAIN authentication [deb] 09:27:33 0,000310 [mail.webstreams.de/default:587] SMTP AUTH Challenge recvd [deb] 09:27:33 0,119104 [mail.webstreams.de/default:587] SMTP Response: 235 2.7.0 Authentication successful [deb] 09:27:33 0,000128 [mail.webstreams.de/default:587] SMTP Request: quit [deb] 09:27:33 0,104027 [mail.webstreams.de/default:587] SMTP Response: 221 2.0.0 Bye [deb] 09:27:33 0,033396 geary-controller.vala:437: Validation failed. Prompting user for revised account information #### #4 Updated by Jim Nelson 2 months ago * **Status** changed from _Open_ to _Need Information_ Interestingly enough, STARTTLS works on your SMTP server, just not Cyrus. Is it possible it's misconfigured? Can you connect with another client (i.e. Thunderbird) using STARTTLS? #### #5 Updated by Jens Georg 2 months ago Works fine with Evolution and my phone. I tried with my company's dovecot server which shows the same issue and similar log output [deb] 12:15:32 83,565619 geary-controller.vala:454: User entered revised account information, retrying validation [deb] 12:15:32 0,079428 imap-client-session.vala:1429: [0003/mail.openismus.com/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] Connected to mail.openismus.com/default:143 [deb] 12:15:32 0,000013 imap-client-session.vala:591: [0003/mail.openismus.com/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_CONNECTING] Connected [deb] 12:15:32 0,000023 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] connected to mail.openismus.com/default:143 [deb] 12:15:32 0,047296 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] * OK Dovecot ready. [deb] 12:15:32 0,000655 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED S] a001 capability [deb] 12:15:32 0,165110 imap-client-session.vala:1502: [0003/mail.openismus.com/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] capability #1: UNSELECT NAMESPACE SORT SASL-IR "THREAD=REFERENCES" LITERAL+ STARTTLS LOGIN-REFERRALS LOGINDISABLED IMAP4rev1 MULTIAPPEND IDLE CHILDREN [deb] 12:15:32 0,000048 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS LOGINDISABLED [deb] 12:15:32 0,001563 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] a001 OK Capability completed. [deb] 12:15:32 0,000160 imap-client-session.vala:680: [0003/mail.openismus.com/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] use_starttls=true is_ssl=false starttls=true [deb] 12:15:32 0,000014 imap-client-session.vala:684: [0003/mail.openismus.com/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_NOAUTH] Attempting STARTTLS... [deb] 12:15:32 0,000272 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED S] a002 starttls [deb] 12:15:32 0,148173 [0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED R] a002 OK Begin TLS negotiation now. [deb] 12:15:32 0,000193 imap-deserializer.vala:247: [des:0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_TAG] Waiting for deserializer to close... [deb] 12:15:32 0,000111 imap-deserializer.vala:799: [des:0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_TAG] input error: Operation was cancelled [deb] 12:15:32 0,000115 imap-deserializer.vala:249: [des:0003/62.245.151.5:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED/GEARY_IMAP_DESERIALIZER_STATE_CLOSED] Deserializer closed [deb] 12:15:32 0,000656 geary-engine.vala:243: Error validating IMAP account info: Stream is already closed [deb] 12:15:32 0,050110 imap-client-connection.vala:406: [0003/mail.openismus.com/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] Disconnecting... [deb] 12:15:32 0,000051 imap-client-connection.vala:408: [0003/mail.openismus.com/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_CONNECTED] Disconnected [deb] 12:15:32 0,000032 imap-client-session.vala:1435: [0003/mail.openismus.com/default:143 GEARY_IMAP_CLIENT_SESSION_STATE_DISCONNECTING] Disconnected from mail.openismus.com/default:143 [deb] 12:15:32 0,000070 [0003/mail.openismus.com/default:143/GEARY_IMAP_CLIENT_CONNECTION_STATE_DISCONNECTED] disconnected from mail.openismus.com/default:143 [deb] 12:15:32 0,000251 imap-client-session.vala:395: DTOR: ClientSession [deb] 12:15:32 0,103662 [mail.openismus.com/default:587] SMTP Greeting: 220 mail.openismus.com ESMTP Postfix (Ubuntu) [deb] 12:15:32 0,000124 [mail.openismus.com/default:587] SMTP Request: ehlo [192.168.34.237] [deb] 12:15:32 0,097712 [mail.openismus.com/default:587] SMTP Response: 250-mail.openismus.com 250-PIPELINING 250-SIZE 20480000 250-VRFY 250-ETRN 250-STARTTLS 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN [deb] 12:15:32 0,000246 [mail.openismus.com/default:587] SMTP Request: starttls [deb] 12:15:32 0,135546 [mail.openismus.com/default:587] SMTP Response: 220 2.0.0 Ready to start TLS [msg] 12:15:33 0,079844 geary-endpoint.vala:126: STARTTLS TLS warnings connecting to mail.openismus.com/default:587: 2h (BAD_IDENTITY) [deb] 12:15:33 0,000251 [mail.openismus.com/default:587] SMTP Request: ehlo [192.168.34.237] [deb] 12:15:33 0,128283 [mail.openismus.com/default:587] SMTP Response: 250-mail.openismus.com 250-PIPELINING 250-SIZE 20480000 250-VRFY 250-ETRN 250-AUTH PLAIN LOGIN 250-AUTH=PLAIN LOGIN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN [deb] 12:15:33 0,000429 smtp-client-session.vala:102: [mail.openismus.com/default:587] Attempting PLAIN authenticator [deb] 12:15:33 0,000020 [mail.openismus.com/default:587] SMTP Request: auth plain [deb] 12:15:33 0,134710 [mail.openismus.com/default:587] SMTP Response: 334 [deb] 12:15:33 0,000016 [mail.openismus.com/default:587] Initiated SMTP PLAIN authentication [deb] 12:15:33 0,000039 [mail.openismus.com/default:587] SMTP AUTH Challenge recvd [deb] 12:15:33 0,142651 [mail.openismus.com/default:587] SMTP Response: 235 2.7.0 Authentication successful [deb] 12:15:33 0,000132 [mail.openismus.com/default:587] SMTP Request: quit [deb] 12:15:33 0,136846 [mail.openismus.com/default:587] SMTP Response: 221 2.0.0 Bye [deb] 12:15:33 0,000431 geary-controller.vala:442: Validation failed. Prompting user for revised account information #### #6 Updated by Jim Nelson 2 months ago * **Status** changed from _Need Information_ to _Open_ I tried creating dummy accounts to mailstreams.de (just to see if a connection could be made) and see the same problem. I'm not sure what the issue is, but will try and get a handle on this before we ship 0.4. #### #7 Updated by Jim Nelson about 1 month ago * **Status** changed from _Open_ to _Need Information_ Jens, I just tried this again and it looks like Geary made an IMAP SSL connection (but failed to login because I don't have an account with mailstreams.de). Can you try again and let me know if it's working for you? #### #8 Updated by Charles Lindsay about 1 month ago * **Target version** changed from _0.4.0_ to _0.5.0_ #### #9 Updated by Michael Gratton 28 days ago I can confirm this is still happening with current geary 0.4.0+trunk. Server is Cyrus Imapd 2.4.12 with SASL enabled, but only with plain auth supported. #### #10 Updated by Jim Nelson 27 days ago Michael, can you send a log to geary@yorba.org? $ geary --debug > geary.log #### #11 Updated by Michael Gratton 26 days ago * **File** signature.asc added On 26/10/13 09:53, redmine@redmine.yorba.org wrote: > Michael, can you send a log to geary@yorba.org? I just sent the requested log then. -- ⊨ Michael Gratton, Percept Wrangler. ⚙ <http://mjog.vee.net/> #### #12 Updated by Jim Nelson 20 days ago * **Status** changed from _Need Information_ to _Open_ * **Assignee** set to _Jim Nelson_ * **Priority** changed from _High_ to _Urgent_ * **Target version** changed from _0.5.0_ to _0.4.1_ I think I've finally got a handle on this. The problem is in the connection layer when STARTTLS is initiated. I believe this will be a small patch and should be a candidate for 0.4.1. #### #13 Updated by Jim Nelson 20 days ago Michael, Jens, can you pull from the `bug/7454-starttls` branch and see if that fixes your problem? #### #14 Updated by Michael Gratton 20 days ago On Sat, Nov 2, 2013 at 9:31 AM, redmine@redmine.yorba.org wrote: > Michael, Jens, can you pull from the `bug/7454-starttls` branch and see if that fixes your problem? I just tested it out - that branch seems to fix the problem for me. //Mike (Sent from Geary) #### #15 Updated by Jim Nelson 20 days ago Great to hear! I'm going to commit to master and the 0.4 branch. #### #16 Updated by Jim Nelson 20 days ago * **Status** changed from _Open_ to _Fixed_ Applied in changeset 174d6545c6983accd2ddd26cca64553a267cf0d1. --- Bug imported by chaz@yorba.org 2013-11-21 20:24 UTC --- This bug was previously known as _bug_ 7454 at http://redmine.yorba.org/show_bug.cgi?id=7454 Imported an attachment (id=260832) Unknown milestone "unknown in product geary. Setting to default milestone for this product, "---". Setting qa contact to the default for this product. This bug either had no qa contact or an invalid one.