0003074: Single SOGo thread seems to misbehave with IMAP/TLS before exiting - SOGo | BTS

ID	Project	Category	View Status	Date Submitted	Last Update

0003074	SOGo	Backend General	public	2015-01-23 17:34	2015-02-05 09:24

Reporter	Sigurd Holter	Assigned To
Priority	normal	Severity	minor	Reproducibility	random
Status	new	Resolution	open
Platform	[Server] Linux	OS	RHEL/CentOS	OS Version	7
Product Version	2.2.14

Summary	0003074: Single SOGo thread seems to misbehave with IMAP/TLS before exiting
Description	In the last 36 hours we have had 6 occurences of this : Jan 23 17:39:19 sogod [44766]: <0x0x7f292e7fb210[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGCouldNotOpenStreamException: could not open stream 2015-01-23 17:39:19.721 sogod[44766] -[NGInternetSocketAddress _fillHost]: couldn't lookup host .. 2015-01-23 17:39:19.721 sogod[44766] could not get DNS name of address 192.168.21.XXX in domain <InternetDomain[0x0x7f2922d3dbf0]>: 2 This repeats for a while until : Jan 23 17:41:48 sogod [44766]: [ERROR] <0x0x7f2922f41560[NGImap4ConnectionManager]> IMAP4 login failed: Jan 23 17:41:48 sogod [44766]: <0x2E264280[SOGoMailAccount]:0> renewing imap4 password Jan 23 17:41:48 sogod [44766]: [ERROR] <0x0x7f2922f41560[NGImap4ConnectionManager]> IMAP4 login failed: Jan 23 17:41:48 sogod [44766]: [ERROR] <0x2E264280[SOGoMailAccount]:0> Could not connect IMAP4 Jan 23 17:41:48 sogod [44766]: \|SOGo\| request took 0.042772 seconds to execute Jan 23 17:42:48 sogod [44766]: \|SOGo\| starting method 'POST' on uri '/SOGo/so/user1/Mail/0/folderINBOX/unseenCount' Jan 23 17:42:48 sogod [44766]: <0x0x7f292ea03860[NGImap4Client]> TLS started successfully. Jan 23 17:42:48 sogod [44766]: \|SOGo\| request took 0.346492 seconds to execute Jan 23 17:43:08 sogod [44765]: \|SOGo\| starting method 'PROPFIND' on uri '/SOGo/dav/user2/Contacts/personal'Jan 23 17:43:08 sogod [44766]: \|SOGo\| starting method 'PROPFIND' on uri '/SOGo/dav/user2/Calendar/personal' 2015-01-23 17:43:08.736 sogod[44766] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='Outlook DAV' Jan 23 17:43:08 sogod [44766]: \|SOGo\| request took 0.006616 seconds to execute Jan 23 17:43:48 sogod [44751]: <0x0x7f2922bc9f90[WOWatchDogChild]> child 44766 exited Dovecot has these errors : Jan 23 17:39:21 imap-login: Info: Disconnected (no auth attempts in 0 secs): user=<>, rip=192.168.21.XXX, lip=192.168.21.YYY, TLS handshaking: SSL_accept() failed: error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol, session=<a0w4blQN5QDAqBU7> Both SOGo and Dovecot serve other requests to/from the same servers fine during the same timeframe. The problem seems to be bound to the one thread. Server loads seem normal during the same time.
Tags	No tags attached.

Sigurd Holter 2015-02-05 09:24 reporter ~0008138	This is still happening. SOGo tries to connect to Dovecot. There seems to be some SSL handshake error. After several attempts, SOGo exits SOGo log : Feb 05 09:21:18 sogod [46134]: \|SOGo\| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user&DeviceId=011AB1BD11DE4E7EAAADD9CEC4F11DBC&DeviceType=WindowsOutlook15' Feb 05 09:21:18 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> TLS started successfully. Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null) Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGCouldNotOpenStreamException: could not open stream Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGSocketConnectionResetException: reached end of stream <NGActiveSocket[0x0x7fae46733c70]: mode=rw address=<0x0x7fae425217e0[NGInternetSocketAddress]: host=LOCAL_SERVER port=57954> connectedTo=<0x0x7fae5113e2c0[NGInternetSocketAddress]: host=192.168.21.YY port=143>> Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGSocketShutdownDuringWriteException: the socket was shutdown Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGSocketConnectionResetException: reached end of stream <NGActiveSocket[0x0x7fae4cfe7ce0]: mode=rw address=<0x0x7fae4c4f5480[NGInternetSocketAddress]: host=LOCAL_SERVER port=57955> connectedTo=<0x0x7fae5113e2c0[NGInternetSocketAddress]: host=192.168.21.YY port=143>>2015-02-05 09:21:19.422 sogod[46134] ERROR(-[NSException(NGMiscellaneous) initWithFormat:]): missing format! Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGSocketConnectionResetException: reached end of stream <NGActiveSocket[0x0x7fae4cfe7ce0]: mode=rw address=<0x0x7fae4bbe79d0[NGInternetSocketAddress]: host=LOCAL_SERVER port=57956> connectedTo=<0x0x7fae5113e2c0[NGInternetSocketAddress]: host=192.168.21.YY port=143>> Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGSocketShutdownDuringWriteException: the socket was shutdown Feb 05 09:21:19 sogod [46134]: <0x0x7fae44077ba0[NGImap4Client]> ERROR(-[NGImap4Client _processUnknownCommandParserException:]): catched non-IMAP4 parsing exception NGSocketConnectionResetException: reached end of stream <NGActiveSocket[0x0x7fae4cfd2680]: mode=rw address=<0x0x7fae44eee930[NGInternetSocketAddress]: host=LOCAL_SERVER port=57957> connectedTo=<0x0x7fae5113e2c0[NGInternetSocketAddress]: host=192.168.21.YY port=143>> Dovecot log : Feb 05 09:21:18 imap-login: Info: Login: user=<user>, method=PLAIN, rip=192.168.21.XX, lip=192.168.21.YY, mpid=13379, TLS, session=<IfcB/VIOYQDAqBU7> Feb 05 09:21:19 imap(user): Info: Connection closed: Connection reset by peer in=3889 out=266642 Feb 05 09:21:19 imap-login: Info: Disconnected (no auth attempts in 0 secs): user=<>, rip=192.168.21.XX, lip=192.168.21.YY, TLS handshaking: SSL_accept() failed: error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol, session=<MysR/VIOYgDAqBU7> Feb 05 09:21:19 imap-login: Info: Disconnected (no auth attempts in 0 secs): user=<>, rip=192.168.21.XX, lip=192.168.21.YY, TLS handshaking: SSL_accept() failed: error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol, session=<PzER/VIOYwDAqBU7> Feb 05 09:21:19 imap-login: Info: Disconnected (no auth attempts in 0 secs): user=<>, rip=192.168.21.XX, lip=192.168.21.YY, TLS handshaking: SSL_accept() failed: error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol, session=<3zYR/VIOZADAqBU7> Feb 05 09:21:19 imap-login: Info: Disconnected (no auth attempts in 0 secs): user=<>, rip=192.168.21.XX, lip=192.168.21.YY, TLS handshaking: SSL_accept() failed: error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol, session=<vjwR/VIOZQDAqBU7> SOGo crashes with a segfault : sogod[39268]: segfault at 0 ip 00007fae37c93a34 sp 00007fff34179c40 error 4 in libc-2.17.so[7fae37c28000+1b6000]

Date Modified	Username	Field	Change
2015-01-23 17:34	Sigurd Holter	New Issue
2015-02-05 09:24	Sigurd Holter	Note Added: 0008138