Dependency Graph

Dependency Graph
related to related to child of child of duplicate of duplicate of

View Issue Details

IDProjectCategoryView StatusLast Update
0003253SOGoActiveSyncpublic2015-07-22 12:45
ReporterSigurd Holter Assigned Toludovic  
PrioritynormalSeveritymajorReproducibilityrandom
Status resolvedResolutionfixed 
Platform[Server] LinuxOSRHEL/CentOSOS Version7
Product Version2.3.0 
Fixed in Version2.3.1 
Summary0003253: SOGo segfaults on 2.3.0 nightly 20150607 after not managing to connect to LDAP (server1) or MySQL (server2)
Description

SOGo Works fine 99% of the time.
About 2-10 times each day, we see segfaults apparently due to SOGo not being able to Connect to LDAP/Windows AD-server (server1) and/or MySQL server (server2).
All servers (including SOGo) are on local network.
All servers are running at all times.
No network outages, Extreme loads or network congestion has been seen in the same time frames.
There seems to be no regularity to these segfaults.
See log extract of one incident (thread 5353).

These segfaults have been there from several Versions back and are not New.

This is With Stock nightly build 20150607 on Centos 7.1 With MariaDB 5.5.37.

Steps To Reproduce

Normal operation.

Additional Information

Jun 11 22:29:58 sogod [2943]: |SOGo| request took 64.032144 seconds to execute
Jun 11 22:29:58 sogod [2943]: server1 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user1&DeviceId=EECF43C9ADDD437D960CA824D62DA59C&DeviceType=WindowsOutlook15 HTTP/1.1" 200 0/9786 64.034 - - 0
Jun 11 22:29:58 sogod [2943]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user1&DeviceId=EECF43C9ADDD437D960CA824D62DA59C&DeviceType=WindowsOutlook15'
Jun 11 22:29:58 sogod [2943]: <0x0x7f6dd263bb90[NGImap4Client]> TLS started successfully.
Jun 11 22:30:07 sogod [5353]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
2015-06-11 22:30:07.440 sogod[5353] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
Jun 11 22:30:07 sogod [5353]: <0x0x7f6dc255f310[LDAPSource]> <NSException: 0x7f6dc44c9460> NAME:LDAPException REASON:operation bind failed: Invalid credentials (0x31) INFO:{"error_code" = 49; login = "cn=user2,cn=users,dc=domain,dc=no"; }
Jun 11 22:30:07 sogod [5353]: SOGoRootPage Login from 'remoteaddr1' for user 'user2' might not have worked - password policy: 65535 grace: -1 expire: -1 bound: 0
Jun 11 22:30:07 sogod [5353]: |SOGo| request took 0.034072 seconds to execute
Jun 11 22:30:07 sogod [5353]: remoteaddr1 "POST /SOGo/connect HTTP/1.1" 403 34/49 0.035 - - 0
Jun 11 22:30:19 sogod [2943]: <0x0x7f6dd2f6a300[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes...
Jun 11 22:30:21 sogod [5353]: |SOGo| starting method 'REPORT' on uri '/SOGo/dav/user1/Calendar/personal/'
2015-06-11 22:30:21.544 sogod[5353] ERROR: could not open MySQL4 connection to database 'sogo': Can't create TCP/IP socket (24)
Jun 11 22:30:21 sogod [5353]: [ERROR] <0x0x7f6dc2450680[GCSChannelManager]> could not open channel <MySQL4Channel[0x0x7f6dcf942460] connection=0x(null)> for mysql://192.168.21.221/sogo/sogo_folder_info
Jun 11 22:30:21 sogod [5353]: [WARN] <0x0x7f6dc2450680[GCSChannelManager]> will prevent opening of this channel 5 seconds after 2015-06-11 22:30:21 +0200
Jun 11 22:30:21 sogod [5353]: [ERROR] <0xC4F547E0[SOGoAppointmentFolders]:Calendar> a database error occured: database connection could not be open
Jun 11 22:30:21 sogod [5353]: |SOGo| request took 0.032358 seconds to execute
Jun 11 22:30:21 sogod [5353]: server1 "REPORT /SOGo/dav/user1/Calendar/personal/ HTTP/1.1" 503 197/188 0.033 - - 0
Jun 11 22:30:29 sogod [2943]: |SOGo| request took 31.248380 seconds to execute
Jun 11 22:30:29 sogod [2943]: server1 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user1&DeviceId=EECF43C9ADDD437D960CA824D62DA59C&DeviceType=WindowsOutlook15 HTTP/1.1" 200 13/5354 31.250 - - 0
Jun 11 22:30:29 sogod [2943]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user1&DeviceId=EECF43C9ADDD437D960CA824D62DA59C&DeviceType=WindowsOutlook15'
Jun 11 22:30:30 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> TLS started successfully.
Jun 11 22:30:34 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:36 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:40 sogod [5353]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
2015-06-11 22:30:40.007 sogod[5353] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
2015-06-11 22:30:40.011 sogod[5353] ERROR(-[NSNull(misc) forwardInvocation:]): called selector setObject:forKey: on NSNull !
2015-06-11 22:30:40.011 sogod[5353] didn't set return value for type 'v'
Jun 11 22:30:40 sogod [5353]: SOGoRootPage successful login from 'remoteaddr1' for user 'user2' - expire = -1 grace = -1
Jun 11 22:30:40 sogod [5353]: <0x0x7f6dc2450680[GCSChannelManager]> db for mysql://192.168.21.221/sogo/sogo_sessions_folder is now back up
Jun 11 22:30:40 sogod [5353]: |SOGo| request took 0.013096 seconds to execute
Jun 11 22:30:40 sogod [5353]: remoteaddr1 "POST /SOGo/connect HTTP/1.1" 200 27/42 0.014 - - 0
Jun 11 22:30:40 sogod [1797]: <0x0x7f6dc24aa430[WOWatchDogChild]> child 5353 exited
Jun 11 22:30:40 sogod [1797]: <0x0x7f6dc24aa430[WOWatchDogChild]> (terminated due to signal 11)

Jun 11 22:30:40 sogod [12016]: |SOGo| starting method 'GET' on uri '/SOGo/so/user2/Mail/view'
Jun 11 22:30:40 sogod [12016]: <0x0x7f6dc247d270[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Jun 11 22:30:40 sogod [12016]: <0x0x7f6dc247d270[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Jun 11 22:30:40 sogod [1797]: <0x0x7f6dc254c770[WOWatchDog]> child spawned with pid 12075
2015-06-11 22:30:40.177 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
2015-06-11 22:30:40.184 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector setObject:forKey: on NSNull !
2015-06-11 22:30:40.184 sogod[12016] didn't set return value for type 'v'
2015-06-11 22:30:40.186 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
2015-06-11 22:30:40.190 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector setObject:forKey: on NSNull !
2015-06-11 22:30:40.190 sogod[12016] didn't set return value for type 'v'
Jun 11 22:30:40 sogod [12016]: |SOGo| request took 0.052175 seconds to execute
Jun 11 22:30:40 sogod [12016]: remoteaddr1 "GET /SOGo/so/user2/Mail/view HTTP/1.1" 200 4363/0 0.054 12586 65% 5M
Jun 11 22:30:49 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:50 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:51 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:51 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:52 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:53 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:54 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:56 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:30:58 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:03 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:04 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:07 sogod [12016]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
2015-06-11 22:31:07.889 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
2015-06-11 22:31:07.900 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector setObject:forKey: on NSNull !
2015-06-11 22:31:07.900 sogod[12016] didn't set return value for type 'v'
Jun 11 22:31:07 sogod [12016]: SOGoRootPage successful login from 'remoteaddr1' for user 'user2' - expire = -1 grace = -1
Jun 11 22:31:07 sogod [12016]: |SOGo| request took 0.018224 seconds to execute
Jun 11 22:31:07 sogod [12016]: remoteaddr1 "POST /SOGo/connect HTTP/1.1" 200 27/42 0.019 - - 52K
Jun 11 22:31:07 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:08 sogod [12016]: |SOGo| starting method 'GET' on uri '/SOGo/so/user2/Mail/view'
2015-06-11 22:31:08.018 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
2015-06-11 22:31:08.022 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector setObject:forKey: on NSNull !
2015-06-11 22:31:08.022 sogod[12016] didn't set return value for type 'v'
2015-06-11 22:31:08.023 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !
2015-06-11 22:31:08.025 sogod[12016] ERROR(-[NSNull(misc) forwardInvocation:]): called selector setObject:forKey: on NSNull !
2015-06-11 22:31:08.025 sogod[12016] didn't set return value for type 'v'
Jun 11 22:31:08 sogod [12016]: |SOGo| request took 0.013270 seconds to execute
Jun 11 22:31:08 sogod [12016]: remoteaddr1 "GET /SOGo/so/user2/Mail/view HTTP/1.1" 200 4363/0 0.015 12586 65% 0
Jun 11 22:31:10 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:15 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:18 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:20 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:25 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:29 sogod [1797]: [WARN] <0x0x7f6dc2645940[WOWatchDogChild]> pid 2943 has been hanging in the same request for 1 minutes
Jun 11 22:31:31 sogod [12016]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?User=user3&DeviceId=B4389A49654394ACF8174149614DDA60&DeviceType=WP8&Cmd=Sync'
Jun 11 22:31:31 sogod [12016]: [ERROR] [we-rm] did not find locale for language: Norwegian
Jun 11 22:31:31 sogod [12016]: <0x0x7f6dc2c686a0[NGImap4Client]> TLS started successfully.
Jun 11 22:31:32 sogod [12016]: [WARN] <0x0x7f6dc2d3ce90[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Jun 11 22:31:32 sogod [12016]: [WARN] <0x0x7f6dc2d3ce90[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Jun 11 22:31:32 sogod [12016]: [WARN] <0x0x7f6dc2d3ce90[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Jun 11 22:31:32 sogod [12016]: |SOGo| request took 1.079378 seconds to execute
Jun 11 22:31:32 sogod [12016]: 192.168.21.161 "POST /SOGo/Microsoft-Server-ActiveSync?User=user3&DeviceId=B4389A49654394ACF8174149614DDA60&DeviceType=WP8&Cmd=Sync HTTP/1.1" 200 0/266 1.081 - - 5M
Jun 11 22:31:32 sogod [2943]: <0x0x7f6dc390a050[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Jun 11 22:31:32 sogod [12016]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?User=user3&DeviceId=B4389A49654394ACF8174149614DDA60&DeviceType=WP8&Cmd=Sync'
Jun 11 22:31:32 sogod [12016]: [ERROR] [we-rm] did not find locale for language: Norwegian
Jun 11 22:31:32 sogod [12016]: |SOGo| request took 0.002715 seconds to execute
Jun 11 22:31:32 sogod [12016]: 192.168.21.161 "POST /SOGo/Microsoft-Server-ActiveSync?User=user3&DeviceId=B4389A49654394ACF8174149614DDA60&DeviceType=WP8&Cmd=Sync HTTP/1.1" 200 12/15 0.004 - - 0
Jun 11 22:31:33 sogod [12016]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?User=user3&DeviceId=B4389A49654394ACF8174149614DDA60&DeviceType=WP8&Cmd=Sync'
Jun 11 22:31:33 sogod [12016]: [ERROR] [we-rm] did not find locale for language: Norwegian
Jun 11 22:31:33 sogod [12016]: <0x0x7f6dc2a9bec0[NGImap4Client]> TLS started successfully.
Jun 11 22:31:34 sogod [2943]: |SOGo| request took 64.068714 seconds to execute
Jun 11 22:31:34 sogod [2943]: server1 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user1&DeviceId=EECF43C9ADDD437D960CA824D62DA59C&DeviceType=WindowsOutlook15 HTTP/1.1" 200 0/9786 64.070 - - 0
Jun 11 22:31:34 sogod [2943]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user1&DeviceId=EECF43C9ADDD437D960CA824D62DA59C&DeviceType=WindowsOutlook15'
Jun 11 22:31:34 sogod [2943]: <0x0x7f6dd1a72c20[NGImap4Client]> TLS started successfully.
Jun 11 22:31:34 sogod [12016]: <0x0x7f6dc2857630[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes...
Jun 11 22:31:44 sogod [12016]: <0x0x7f6dc2857630[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes...
Jun 11 22:31:50 sogod [12075]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
Jun 11 22:31:50 sogod [12075]: <0x0x7f6dc2234aa0[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Jun 11 22:31:50 sogod [12075]: <0x0x7f6dc2234aa0[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
2015-06-11 22:31:50.864 sogod[12075] ERROR(-[NSNull(misc) forwardInvocation:]): called selector objectForKey: on NSNull !

TagsNo tags attached.

Relationships

duplicate of 0003225 resolvedludovic Cannot login to SOGo web interface: didn't set return value for type 'v' 

Activities

zhb

zhb

2015-07-02 20:38

reporter   ~0008690

Duplicate bugs: 0003231 0003225 0003253

tfu

tfu

2015-07-10 06:25

reporter   ~0008720

Last edited: 2015-07-10 06:38

ERROR: could not open MySQL4 connection to database 'sogo': Can't create TCP/IP socket (24)

#define EMFILE 24 / Too many open files /

I'd suggest to check/monitor number of open files. (/proc/sys/fs/file-max;/proc/sys/fs/file-nr)

Also worth to check:
http://blog.endpoint.com/2013/12/increasing-mysql-55-maxconnections-on.html

ludovic

ludovic

2015-07-22 12:45

administrator   ~0008754

I suspect ABI issues between librairies. Our chroots were updated and all integration tests work. Retry with the upcoming 2.3.1 version.

Issue History

Date Modified Username Field Change
2015-06-12 02:23 Sigurd Holter New Issue
2015-07-02 20:38 zhb Note Added: 0008690
2015-07-10 05:42 Christian Mack Relationship added duplicate of 0003225
2015-07-10 06:25 tfu Note Added: 0008720
2015-07-10 06:38 tfu Note Edited: 0008720
2015-07-22 12:45 ludovic Note Added: 0008754
2015-07-22 12:45 ludovic Status new => resolved
2015-07-22 12:45 ludovic Fixed in Version => 2.3.1
2015-07-22 12:45 ludovic Resolution open => fixed
2015-07-22 12:45 ludovic Assigned To => ludovic