View Issue Details

IDProjectCategoryView StatusLast Update
0004783SOGoBackend Mailpublic2020-05-14 20:12
Reportermzch Assigned Toludovic  
PriorityhighSeveritymajorReproducibilityalways
Status resolvedResolutionreopened 
PlatformServerOSDebian GNU/Linux 10 (Buster)OS Version10.0
Product Version4.0.7 
Fixed in Version5.0.0 
Summary0004783: IMAPS (SSL) broken with gnutls in Debian Buster
Description

It seems that SOGo can't understand the response of Dovecot server, so always fails to login to a remote IMAP server.

I have 2 IMAP server. One is a simple IMAP server which has PAM backend. SOGo runs on it without any problem, but another, which has MySQL backend, always fails to login.

Steps To Reproduce

Only login and select mail.

TagsBuster, Debian, GnuTLS, imap, imaps

Activities

mzch

mzch

2019-07-13 07:29

reporter  

Log.txt (11,358 bytes)   
-- SOGo Log
Jul 13 06:49:38 sogod [4645]: <0x0x5643dd010430[NGImap4Client]> TLS started successfully.
Jul 13 06:49:38 sogod [4645]: <0x0x5643dd010430[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
Jul 13 06:49:38 sogod [4645]: [ERROR] <0x0x5643dd00e2f0[NGImap4ConnectionManager]> IMAP4 login failed:
Jul 13 06:49:38 sogod [4645]: <0x5643dccac200[SOGoMailAccount]:0> renewing imap4 password
Jul 13 06:49:38 sogod [4645]: <0x0x5643dd034ef0[NGImap4Client]> TLS started successfully.
Jul 13 06:49:38 sogod [4645]: <0x0x5643dd034ef0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
Jul 13 06:49:38 sogod [4645]: [ERROR] <0x0x5643dd00e2f0[NGImap4ConnectionManager]> IMAP4 login failed:
Jul 13 06:49:38 sogod [4645]: [ERROR] <0x5643dccac200[SOGoMailAccount]:0> Could not connect IMAP4
Jul 13 06:49:38 sogod [4645]: 203.141.134.112 "GET /SOGo/so/mzch/Mail/0/view HTTP/1.1" 200 17/0 0.168 - - 4M
Jul 13 06:49:38 sogod [4645]: <0x0x5643dcf5fda0[NGHttpRequest]> got 2 values for cookie 'XSRF-TOKEN', using first only: 046eab9994feeb60b2bb8f1a867c3e5eec55ac9c,1561253855.lejy384sa9ro.KwYdIDKYPsvb60g
Jul 13 06:49:38 sogod [4645]: <0x0x5643dd04f1e0[NGImap4Client]> TLS started successfully.
Jul 13 06:49:38 sogod [4645]: <0x0x5643dd04f1e0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
Jul 13 06:49:38 sogod [4645]: [ERROR] <0x0x5643dd00e2f0[NGImap4ConnectionManager]> IMAP4 login failed:
Jul 13 06:49:38 sogod [4645]: <0x5643dd046c10[SOGoMailAccount]:0> renewing imap4 password
Jul 13 06:49:38 sogod [4645]: <0x0x5643dcff3950[NGImap4Client]> TLS started successfully.
Jul 13 06:49:38 sogod [4645]: <0x0x5643dcff3950[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
Jul 13 06:49:38 sogod [4645]: [ERROR] <0x0x5643dd00e2f0[NGImap4ConnectionManager]> IMAP4 login failed:
Jul 13 06:49:38 sogod [4645]: [ERROR] <0x5643dd046c10[SOGoMailAccount]:0> Could not connect IMAP4
Jul 13 06:49:38 sogod [4645]: 203.141.134.112 "POST /SOGo/so/mzch/Mail/unseenCount HTTP/1.1" 200 21/31 0.145 - - 0

-- Dovecot Log

Jul 12 23:49:38 n03 dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Jul 12 23:49:38 n03 dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
Jul 12 23:49:38 n03 dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Jul 12 23:49:38 n03 dovecot: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Jul 12 23:49:38 n03 dovecot: auth: Debug: auth client connected (pid=31797)
Jul 12 23:49:38 n03 dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=3PE/boqNIJ/AqM+K#011lip=192.168.207.22#011rip=192.168.207.138#011lport=143#011rport=40736#011ssl_cipher=TLS_AES_256_GCM_SHA384#011ssl_cipher_bits=256#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3#011resp=<hidden>
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Jul 12 23:49:38 n03 dovecot: auth: Debug: auth client connected (pid=31801)
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<3PE/boqNIJ/AqM+K>): query: SELECT username as user, password FROM mailbox WHERE username = 'mzch@uixis.com' AND active = '1'
Jul 12 23:49:38 n03 dovecot: auth: Debug: client passdb out: OK#0111#011user=mzch@uixis.com#011
Jul 12 23:49:38 n03 dovecot: auth: Debug: master in: REQUEST#0111400766465#01131797#0111#0118232a486f12d97195f237ee1009552cb#011session_pid=31803#011request_auth_token
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<3PE/boqNIJ/AqM+K>): SELECT concat('/var/mail/', maildir) as home, concat('*:bytes=', quota) as quota_rule, 998 as uid, 8 as gid FROM mailbox WHERE active = '1' AND username = (SELECT goto FROM alias WHERE (address = 'mzch@uixis.com' AND alias.active = '1') OR (address = (SELECT concat('mzch', '@', target_domain) FROM alias_domain where alias_domain = 'uixis.com' AND alias_domain.active = '1' ) ) )
Jul 12 23:49:38 n03 dovecot: auth: Debug: master userdb out: USER#0111400766465#011mzch@uixis.com#011home=/var/mail/uixis.com/mzch/#011quota_rule=*:bytes=15728640000#011uid=998#011gid=8#011auth_token=eaebbf07f001c23ad59b207de89eafef1a96db9f
Jul 12 23:49:38 n03 dovecot: imap-login: Login: user=<mzch@uixis.com>, method=PLAIN, rip=192.168.207.138, lip=192.168.207.22, mpid=31803, TLS, session=<3PE/boqNIJ/AqM+K>
Jul 12 23:49:38 n03 dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=xApBboqNIp/AqM+K#011lip=192.168.207.22#011rip=192.168.207.138#011lport=143#011rport=40738#011ssl_cipher=TLS_AES_256_GCM_SHA384#011ssl_cipher_bits=256#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3#011resp=<hidden>
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<xApBboqNIp/AqM+K>): query: SELECT username as user, password FROM mailbox WHERE username = 'mzch@uixis.com' AND active = '1'
Jul 12 23:49:38 n03 dovecot: auth: Debug: client passdb out: OK#0111#011user=mzch@uixis.com#011
Jul 12 23:49:38 n03 dovecot: imap(mzch@uixis.com)<31803><3PE/boqNIJ/AqM+K>: Connection closed (No commands sent) in=0 out=379 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jul 12 23:49:38 n03 dovecot: auth: Debug: master in: REQUEST#01111927553#01131801#0111#01154e4b116a9f698a21d0c757fa6c22780#011session_pid=31804#011request_auth_token
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<xApBboqNIp/AqM+K>): SELECT concat('/var/mail/', maildir) as home, concat('*:bytes=', quota) as quota_rule, 998 as uid, 8 as gid FROM mailbox WHERE active = '1' AND username = (SELECT goto FROM alias WHERE (address = 'mzch@uixis.com' AND alias.active = '1') OR (address = (SELECT concat('mzch', '@', target_domain) FROM alias_domain where alias_domain = 'uixis.com' AND alias_domain.active = '1' ) ) )
Jul 12 23:49:38 n03 dovecot: auth: Debug: master userdb out: USER#01111927553#011mzch@uixis.com#011home=/var/mail/uixis.com/mzch/#011quota_rule=*:bytes=15728640000#011uid=998#011gid=8#011auth_token=e7a39fdb4cacb4a23770723458a67e356335f222
Jul 12 23:49:38 n03 dovecot: imap-login: Login: user=<mzch@uixis.com>, method=PLAIN, rip=192.168.207.138, lip=192.168.207.22, mpid=31804, TLS: read(size=492) failed: Connection reset by peer, session=<xApBboqNIp/AqM+K>
Jul 12 23:49:38 n03 dovecot: imap(mzch@uixis.com)<31804><xApBboqNIp/AqM+K>: Connection closed (No commands sent) in=0 out=379 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jul 12 23:49:38 n03 dovecot: auth: Debug: auth client connected (pid=31805)
Jul 12 23:49:38 n03 dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=HrREboqNJp/AqM+K#011lip=192.168.207.22#011rip=192.168.207.138#011lport=143#011rport=40742#011ssl_cipher=TLS_AES_256_GCM_SHA384#011ssl_cipher_bits=256#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3#011resp=<hidden>
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<HrREboqNJp/AqM+K>): query: SELECT username as user, password FROM mailbox WHERE username = 'mzch@uixis.com' AND active = '1'
Jul 12 23:49:38 n03 dovecot: auth: Debug: client passdb out: OK#0111#011user=mzch@uixis.com#011
Jul 12 23:49:38 n03 dovecot: auth: Debug: master in: REQUEST#0113533045761#01131805#0111#011976c2beed8c25e6f7981c031a6af73e8#011session_pid=31807#011request_auth_token
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<HrREboqNJp/AqM+K>): SELECT concat('/var/mail/', maildir) as home, concat('*:bytes=', quota) as quota_rule, 998 as uid, 8 as gid FROM mailbox WHERE active = '1' AND username = (SELECT goto FROM alias WHERE (address = 'mzch@uixis.com' AND alias.active = '1') OR (address = (SELECT concat('mzch', '@', target_domain) FROM alias_domain where alias_domain = 'uixis.com' AND alias_domain.active = '1' ) ) )
Jul 12 23:49:38 n03 dovecot: auth: Debug: master userdb out: USER#0113533045761#011mzch@uixis.com#011home=/var/mail/uixis.com/mzch/#011quota_rule=*:bytes=15728640000#011uid=998#011gid=8#011auth_token=d80e776ce564abf3387668cfb3eb267f3fba06d8
Jul 12 23:49:38 n03 dovecot: imap-login: Login: user=<mzch@uixis.com>, method=PLAIN, rip=192.168.207.138, lip=192.168.207.22, mpid=31807, TLS, session=<HrREboqNJp/AqM+K>
Jul 12 23:49:38 n03 dovecot: auth: Debug: auth client connected (pid=31808)
Jul 12 23:49:38 n03 dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=Gr5FboqNKJ/AqM+K#011lip=192.168.207.22#011rip=192.168.207.138#011lport=143#011rport=40744#011ssl_cipher=TLS_AES_256_GCM_SHA384#011ssl_cipher_bits=256#011ssl_pfs=KxANY#011ssl_protocol=TLSv1.3#011resp=<hidden>
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<Gr5FboqNKJ/AqM+K>): query: SELECT username as user, password FROM mailbox WHERE username = 'mzch@uixis.com' AND active = '1'
Jul 12 23:49:38 n03 dovecot: auth: Debug: client passdb out: OK#0111#011user=mzch@uixis.com#011
Jul 12 23:49:38 n03 dovecot: imap(mzch@uixis.com)<31807><HrREboqNJp/AqM+K>: Connection closed (No commands sent) in=0 out=379 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jul 12 23:49:38 n03 dovecot: auth: Debug: master in: REQUEST#0113184525313#01131808#0111#01144e7963d05404dcd882b19fd3ed3d66a#011session_pid=31810#011request_auth_token
Jul 12 23:49:38 n03 dovecot: auth-worker(31800): Debug: sql(mzch@uixis.com,192.168.207.138,<Gr5FboqNKJ/AqM+K>): SELECT concat('/var/mail/', maildir) as home, concat('*:bytes=', quota) as quota_rule, 998 as uid, 8 as gid FROM mailbox WHERE active = '1' AND username = (SELECT goto FROM alias WHERE (address = 'mzch@uixis.com' AND alias.active = '1') OR (address = (SELECT concat('mzch', '@', target_domain) FROM alias_domain where alias_domain = 'uixis.com' AND alias_domain.active = '1' ) ) )
Jul 12 23:49:38 n03 dovecot: auth: Debug: master userdb out: USER#0113184525313#011mzch@uixis.com#011home=/var/mail/uixis.com/mzch/#011quota_rule=*:bytes=15728640000#011uid=998#011gid=8#011auth_token=36ffa7773d8357354c708e6df01793d2d22091fb
Jul 12 23:49:38 n03 dovecot: imap-login: Login: user=<mzch@uixis.com>, method=PLAIN, rip=192.168.207.138, lip=192.168.207.22, mpid=31810, TLS: read(size=492) failed: Connection reset by peer, session=<Gr5FboqNKJ/AqM+K>
Jul 12 23:49:38 n03 dovecot: imap(mzch@uixis.com)<31810><Gr5FboqNKJ/AqM+K>: Connection closed (No commands sent) in=0 out=379 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Log.txt (11,358 bytes)   
mzch

mzch

2019-07-14 12:49

reporter   ~0013671

I installed another instance of SOGo, and tried to connect to IMAP server which another SOGo run on. As a result, connection failed due to the same error. I also tried Gmail, and the result is the same.

gturner

gturner

2019-07-24 15:46

reporter   ~0013676

I encountered the same problem after upgrading servers running Debian 9 to Debian 10.

I upgraded the SOGo server first, and all was fine.

However when I upgraded the server running dovecot, SOGo no longer displays mail (although Address Book and Calendar still work).

Bug was reported to Debian: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=932081

Bug was also discussed on the SOGo mailing list two months earlier with no solution: https://lists.inverse.ca/sogo/arc/users/2019-06/msg00005.html

gturner

gturner

2019-07-24 15:47

reporter  

sogo.log (2,101 bytes)   
Jul 24 08:28:00 sogod [22882]: localhost "GET /SOGo/ HTTP/1.1" 200 2442/0 0.004 - - 0
2019-07-24 08:28:19.923 sogod[22882:22882] ERROR(-[NSException(NGMiscellaneous) initWithFormat:]): missing format!
Jul 24 08:28:19 sogod [22882]: <0x0x559fabd1d5d0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
Jul 24 08:28:19 sogod [22882]: [ERROR] <0x0x559fabd8a1b0[NGImap4ConnectionManager]> IMAP4 login failed:
  host=mail.unzane.com, user=gturner, pwd=yes
  url=imaps://gturner@mail.unzane.com/
  base=(null)
  base-class=(null))
  = <0x0x559fabd1d5d0[NGImap4Client]: login=gturner(pwd) socket=<NGActiveSSLSocket[0x0x559fabb43370]: mode=rw address=<0x0x559fabd7a140[NGInternetSocketAddress]: host=nyarlathotep.unzane.com port=35094> connectedTo=<0x0x559fabd3c7f0[NGInternetSocketAddress]: host=mail.unzane.com port=993>>>
Jul 24 08:28:19 sogod [22882]: <0x559fabedc620[SOGoMailAccount]:0> renewing imap4 password
2019-07-24 08:28:19.969 sogod[22882:22882] ERROR(-[NSException(NGMiscellaneous) initWithFormat:]): missing format!
Jul 24 08:28:19 sogod [22882]: <0x0x559fabec4dd0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
Jul 24 08:28:19 sogod [22882]: [ERROR] <0x0x559fabd8a1b0[NGImap4ConnectionManager]> IMAP4 login failed:
  host=mail.unzane.com, user=gturner, pwd=yes
  url=imaps://gturner@mail.unzane.com/
  base=(null)
  base-class=(null))
  = <0x0x559fabec4dd0[NGImap4Client]: login=gturner(pwd) socket=<NGActiveSSLSocket[0x0x559fabd28b70]: mode=rw address=<0x0x559fabcf2010[NGInternetSocketAddress]: host=nyarlathotep.unzane.com port=35096> connectedTo=<0x0x559fabd1a940[NGInternetSocketAddress]: host=mail.unzane.com port=993>>>
Jul 24 08:28:19 sogod [22882]: [ERROR] <0x559fabedc620[SOGoMailAccount]:0> Could not connect IMAP4
Jul 24 08:28:19 sogod [22882]: 127.0.0.1 "POST /SOGo/so/gturner/Mail/unseenCount HTTP/1.1" 200 21/31 0.135 - - 0
sogo.log (2,101 bytes)   
gturner

gturner

2019-07-24 15:47

reporter  

dovecot.log (813 bytes)   
Jul 24 08:28:19 azathoth dovecot[655]: imap-login: Login: user=<gturner>, method=PLAIN, rip=184.105.220.22, lip=184.105.220.20, mpid=26318, TLS, session=<N0eA9W6OFom4adwW>
Jul 24 08:28:19 azathoth dovecot[655]: imap(gturner)<26318><N0eA9W6OFom4adwW>: Connection closed (No commands sent) in=0 out=373 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jul 24 08:28:19 azathoth dovecot[655]: imap-login: Login: user=<gturner>, method=PLAIN, rip=184.105.220.22, lip=184.105.220.20, mpid=26319, TLS: read(size=530) failed: Connection reset by peer, session=<nveA9W6OGIm4adwW>
Jul 24 08:28:19 azathoth dovecot[655]: imap(gturner)<26319><nveA9W6OGIm4adwW>: Connection closed (No commands sent) in=0 out=373 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
dovecot.log (813 bytes)   
gturner

gturner

2019-08-09 00:53

reporter   ~0013702

FYI bug still exists in 4.0.8.

the_nic

the_nic

2019-09-01 11:18

reporter   ~0013728

This could be related to the crash I was observing, too. My bugfix is already merged to master: https://github.com/inverse-inc/sogo/pull/258

Maybe you can inform downstream, too?

mzch

mzch

2019-09-02 07:25

reporter   ~0013729

Thanks, @the_nic. it's already been reported in Debian, downstrem, bug tracker.

ludovic

ludovic

2019-10-28 19:46

administrator   ~0013866

Suspending, reopen if still present.

Christian Mack

Christian Mack

2019-12-20 13:06

developer   ~0014006

Reopened as requested on mailinglist.
See
https://lists.inverse.ca/sogo/arc/users/2019-12/msg00048.html

adi

adi

2019-12-20 13:11

reporter   ~0014008

Thanks for reopening! :)

As I already detailed in the mailing list posting: this issue occurs to me only when using gnutls with Debian/Buster. When using openssl everything works just fine. Debian Buster (10) has gnutls v3.6.7-4 while Debian Stretch (9) had v3.5.8-5+deb9u4.

jaywalker

jaywalker

2020-01-22 20:24

reporter   ~0014087

I also observe this bug after upgrading the imap server (dovecot) to debian buster.

Is there any known workaround?

jaywalker

jaywalker

2020-01-23 20:10

reporter   ~0014098

Additional Information:
I experience this bug also in sogo 4.3.0 with a dovecot server authenticating against ldap.

mighty.duck

mighty.duck

2020-02-08 09:40

reporter   ~0014147

I can confirm this. My IMAP server is using Debian Buster + Dovecot secured with a SSL-cert. Clients like Thunderbird, Outlook and other proprietary mobile phone clients can connect to Dovecot on port 993 (default). My groupware server is a separate machine using Debian Buster + SOGo. While Sogo can establish a unsecured connection to the IMAP server in PLAIN mode (which is highly insecure), it can't connect to imaps://mail.example.com as stated by the install instructions.

Logs are the same like shown by reporter mzch and gturners reference to Debian bugreports (https://sogo.nu/bugs/view.php?id=4783#c13676).

Bug confirmed by fresh install of Buster + Dovecot on machine A and Buster + Sogo on machine B.

Then I found out, that a compile on myself with a link to OpenSSL (instead of GnuTLS) should work (see https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=932081#37).

My question is, is that a particular bug known to be solved at SOGo or by the package maintainer?

adi

adi

2020-02-11 15:16

reporter   ~0014150

Maybe the title of this issue could be changed to something that reflects the actual issue, like: "IMAPS broken with gnutls in Debian/Buster".
It would be great to know if someone actually plans to work on this or if any more information is needed.

mighty.duck

mighty.duck

2020-02-12 08:53

reporter   ~0014152

I agree with adi. This bug has nothing to do with the database backend. I recommend slightly changed title "IMAPS (SSL) broken with gnutls in Debian Buster".

Buster is stable, I don't use Bullseye testing to confirm it there. But the libraries are the same. Same goes for Ubuntu eoan and disco. So I doubt it's different there.

This is severe. The only circumvention is changing code and recompile. Also you have to go for plain auth without encryption.

mighty.duck

mighty.duck

2020-02-12 08:55

reporter   ~0014153

Also=Or*

adi

adi

2020-05-10 12:05

reporter   ~0014316

This bug is set to feedback; is there any more information needed? If so, what do you miss?

the_nic

the_nic

2020-05-12 08:24

reporter   ~0014327

Can someone try this fix: https://github.com/inverse-inc/sope/pull/51

adi

adi

2020-05-12 10:12

reporter   ~0014328

unfortunately it doesn't; but de behavior changed a little: I think, I haven't seen the "renewing imap4 password" line before.

2020-05-12 12:06:40.042 sogod[15535:15535] ERROR(-[NSException(NGMiscellaneous) initWithFormat:]): missing format!
May 12 12:06:40 sogod [15535]: <0x0x5625118ad370[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
May 12 12:06:40 sogod [15535]: [ERROR] <0x0x5625118b8da0[NGImap4ConnectionManager]> IMAP4 login failed:
[imap server details redacted]
= <0x0x5625118ad370[NGImap4Client]: login=[redacted] socket=<NGActiveSSLSocket[0x0x5625118f9c20]: mode=rw address=<0x0x562511892b30[NGInternetSocketAddress]: host=[redacted] port=47022> connectedTo=<0x0x5625118ad6e0[NGInternetSocketAddress]: host=[redacted] port=993>
May 12 12:06:40 sogod [15535]: <0x5625118fab60[SOGoMailAccount]:0> renewing imap4 password
2020-05-12 12:06:40.154 sogod[15535:15535] ERROR(-[NSException(NGMiscellaneous) initWithFormat:]): missing format!
May 12 12:06:40 sogod [15535]: <0x0x5625118c2340[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception UnexpectedEndOfStream: the parsed stream ended unexpectedly
(...)
May 12 12:06:40 sogod [15535]: [ERROR] <0x5625118fab60[SOGoMailAccount]:0> Could not connect IMAP4

the_nic

the_nic

2020-05-12 11:01

reporter   ~0014329

@adi thanks for the test
The renew line is also in the first log, and thats unrelated actually. When compiling sope by hand, do you see any suspicious warnings?

adi

adi

2020-05-12 11:59

reporter   ~0014330

No, not really... At least nothing directly related:

  • NSProcessInfo+misc.m: In function ‘-[NSProcessInfo(misc) virtualMemorySize]’:
    NSProcessInfo+misc.m:156:19: warning: variable ‘res’ set but not used [-Wunused-but-set-variable]
  • NGMimeBodyPart.m: In function ‘-[NGMimeBodyPart bodyInfo]’:
    NGMimeBodyPart.m:237:3: warning: ‘NSString’ may not respond to ‘-filename’
    if ((o = [[self headerForKey: @"content-disposition"] filename]))
    ^~
    NGMimeBodyPart.m:237:3: warning: (Messages without a matching method signature
    NGMimeBodyPart.m:237:3: warning: will be assumed to return ‘id’ and accept
    NGMimeBodyPart.m:237:3: warning: ‘...’ as arguments.)
  • NGImap4Client.m:946:55: warning: "/" within comment [-Wcomment]
    result = [client annotation: folderName entryName: @"/
    " attributeName: @"value"];

    NGImap4Client.m:947:48: warning: "/" within comment [-Wcomment]
    result = [client annotation: @"" entryName: @"/
    " attributeName: @"value"];

    NGImap4Client.m: In function ‘-[NGImap4Client annotation:entryName:attributeName:]’:
    NGImap4Client.m:979:2: warning: ‘NGImap4Client’ may not respond to ‘-_imapFolder2Folder:’
    [folderList setObject: [obj objectForKey: [[obj allKeys] objectAtIndex:0]] forKey: [[self _imapFolder2Folder: [[obj allKeys] objectAtIndex:0]] substringFromIndex:1]];
    ^
    NGImap4Client.m:979:2: warning: (Messages without a matching method signature
    NGImap4Client.m:979:2: warning: will be assumed to return ‘id’ and accept
    NGImap4Client.m:979:2: warning: ‘...’ as arguments.)

  • WORadioButton.m: In function ‘-[WORadioButton takeValuesFromRequest:inContext:]’:
    WORadioButton.m:80:2: warning: #warning FIXME, radio button form handling [-Wcpp]
  • SoSecurityManager.m: In function ‘-[SoSecurityManager makeExceptionForObject:reason:]’:
    SoSecurityManager.m:77:13: warning: variable ‘r’ set but not used [-Wunused-but-set-variable]
  • EOEntity.m: In function ‘-[EOEntity validatePropertiesCache]’:
    EOEntity.m:833:9: warning: passing argument 1 of ‘sortedArrayUsingFunction:context:’ from incompatible pointer type [-Wincompatible-pointer-types]
    [fetAttr sortedArrayUsingFunction:_compareByName context:nil]];
    ^
    EOEntity.m:833:9: note: expected ‘NSComparisonResult ()(struct objc_object , struct objc_object , void )’ {aka ‘long int ()(struct objc_object , struct objc_object , void )’} but argument is of type ‘int ()(struct objc_object , struct objc_object , void )’
  • NGLdapFileManager.m: In function ‘-[NGLdapFileManager(ExtendedFileManager) pathForGlobalID:]’:
    NGLdapFileManager.m:724:32: warning: logical not is only applied to the left hand side of comparison [-Wlogical-not-parentheses]
    (plus some more #TODO-Warnings)
the_nic

the_nic

2020-05-12 14:33

reporter   ~0014331

I pushed another minor fix. Would you try again? Unfortunately, I cannot reproduce the bug.

Is there any IMAP log when you enable ImapDebugEnabled = YES;?

the_nic

the_nic

2020-05-12 16:09

reporter   ~0014333

Okay, I was able to reproduce and find the issue. gnutls_record_recv() and gnutls_record_send() may return GNUTLS_E_AGAIN or GNUTLS_E_INTERRUPTED. In these cases we just have to retry.

Added a diaper around these function, now it works.

adi

adi

2020-05-12 18:09

reporter   ~0014334

you are my hero! :) The patch fixes the issue! Thank you very much for investigating and fixing the issue!

Issue History

Date Modified Username Field Change
2019-07-13 07:29 mzch New Issue
2019-07-13 07:29 mzch File Added: Log.txt
2019-07-14 12:49 mzch Note Added: 0013671
2019-07-24 15:46 gturner Note Added: 0013676
2019-07-24 15:47 gturner File Added: sogo.log
2019-07-24 15:47 gturner File Added: dovecot.log
2019-08-09 00:53 gturner Note Added: 0013702
2019-09-01 11:18 the_nic Note Added: 0013728
2019-09-02 07:25 mzch Note Added: 0013729
2019-10-28 19:46 ludovic Note Added: 0013866
2019-10-28 19:46 ludovic Status new => resolved
2019-10-28 19:46 ludovic Resolution open => suspended
2019-10-28 19:46 ludovic Assigned To => ludovic
2019-12-20 13:06 Christian Mack Status resolved => feedback
2019-12-20 13:06 Christian Mack Resolution suspended => reopened
2019-12-20 13:06 Christian Mack Note Added: 0014006
2019-12-20 13:11 adi Note Added: 0014008
2020-01-22 20:24 jaywalker Note Added: 0014087
2020-01-23 20:10 jaywalker Note Added: 0014098
2020-02-08 09:40 mighty.duck Note Added: 0014147
2020-02-11 15:16 adi Note Added: 0014150
2020-02-11 16:12 mighty.duck Tag Attached: imap
2020-02-11 16:12 mighty.duck Tag Attached: imaps
2020-02-12 08:53 mighty.duck Note Added: 0014152
2020-02-12 08:55 mighty.duck Note Added: 0014153
2020-02-12 09:26 mzch Tag Attached: Debian
2020-02-12 09:26 mzch Tag Attached: Buster
2020-02-12 09:26 mzch Tag Attached: GnuTLS
2020-02-28 10:29 Christian Mack Summary Unable to login to a remote IMAP Server which has MySQL backend => IMAPS (SSL) broken with gnutls in Debian Buster
2020-05-10 12:05 adi Note Added: 0014316
2020-05-12 08:24 the_nic Note Added: 0014327
2020-05-12 10:12 adi Note Added: 0014328
2020-05-12 11:01 the_nic Note Added: 0014329
2020-05-12 11:59 adi Note Added: 0014330
2020-05-12 14:33 the_nic Note Added: 0014331
2020-05-12 16:09 the_nic Note Added: 0014333
2020-05-12 18:09 adi Note Added: 0014334
2020-05-14 20:12 francis Status feedback => resolved
2020-05-14 20:12 francis Fixed in Version => 5.0.0