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. |
---|
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 ! |
---|