View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0002813SOGoWeb Preferencespublic2014-06-11 14:202017-07-13 05:34
ReporterGunnar Weissmann Assigned Toludovic  
PrioritynormalSeverityminorReproducibilityalways
Status assignedResolutionreopened 
PlatformMac ProOSOS X/VM-WindowsOS Version10.9.3/8.1
Product Version2.2.5 
Target Version2.2.6Fixed in Version2.2.6 
Summary0002813: Persistent database connection problem
Description

Setup:
Server: Debian 7.5 with nginx/1.2.1,SOGo 2.2.5, external Maria DB Server 5.5.31
Client: MAC OSX 10.9.3 with Firefox 29.0.1/IE 11.0.9600.1707, Windows 8.1 with Firefox 29.0.1/Safari 7.0.4/Chrome 35.0.916.153

Initial situation:
(We get the same result with all tested os/clients combinations)

When we connect on the SOGo Webinterface and open the preferences link (e.g.https://sogo.url.com/SOGo/so/name/preferences) to show the preferences everything react normal.
When we wait 2 or 3 minutes an open the preferences link again we became a 502 bad gateway error from the nginx.
Otherwise when we open other links like calendar,address book or mail and wait the same time there is no 502 error.

Our expectation:
I expect that all links opens without a 502 error when you wait a few minutes.

We consider it is a bug because:
SOGo uses persistent connection pooling. Normally you don't do this because they are "expensive" and need a lot of ressources on the database server.
On demand connections are "cheaper". But this would be not the real problem if SOGo could handle connection drops from the connection pool from the database in every situation.
On all "links" except the preferences link SOGo can handle the connection drops.
On the next request (eg. 1 minute) when the database connection timeout (30 sec.) terminates the connection an exception is thrown because of the returned null-value and kills the child process
as seen in the log file.
We think it is a bug, because it only happens on the preference link.

Workaround:
To avoid this we terminate the connection from the pool itself (15 sec) before the database timeout (30 sec) drops them. We check the pool every 25 seconds and drop all inactive connections.
We activate this behavior with the following settings in the sogo.conf file:
GCSChannelCollectionTimer = 25;
GCSChannelExpireAge = 15;
With this workaround we obviously correct the bug; it would be better if SOGo itself could handle the connections.

Our suggestion:
Is it possible that SOGO doesn't use persistent database connections like already implemented with the "NGImap4DisableIMAP4Pooling = no" setting described in the following bug:
http://www.sogo.nu/bugs/view.php?id=1243

Thank's for your support.

Kind regards,

Gunnar Weissmann

TagsNo tags attached.

Activities

Gunnar Weissmann

Gunnar Weissmann

2014-06-16 14:42

reporter   ~0007214

for better analysis you will find attached the debug log:

Jun 04 16:14:17 sogod [25783]: |SOGo| starting method 'GET' on uri '/SOGo/so/gunnarweissmann/preferences'
2014-06-04 16:14:17.617 sogod[25783] <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'gunnarweissmann' AND c_folder_type = 'Contact';
2014-06-04 16:14:17.621 sogod[25783] <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0> query has results, entering fetch-mode.
2014-06-04 16:14:17.621 sogod[25783] <MySQL4Channel[0x0x7fd33b7e8db0] connection=0x0x7fd33bdb6d60> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'gunnarweissmann' AND c_folder_type = 'Contact';
2014-06-04 16:14:17.623 sogod[25783] <MySQL4Channel[0x0x7fd33b7e8db0] connection=0x0x7fd33bdb6d60> query has results, entering fetch-mode.
2014-06-04 16:14:17.624 sogod[25783] <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0> SQL: SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/gunnarweissmann/Contacts/collected';
2014-06-04 16:14:17.624 sogod[25783] <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0> query has results, entering fetch-mode.
2014-06-04 16:14:17.624 sogod[25783] <MySQL4Channel[0x0x7fd33b7e8db0] connection=0x0x7fd33bdb6d60> SQL: SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/gunnarweissmann/Contacts/3AE5-5379C400-1-2AF07C40';
2014-06-04 16:14:17.625 sogod[25783] <MySQL4Channel[0x0x7fd33b7e8db0] connection=0x0x7fd33bdb6d60> query has results, entering fetch-mode.
2014-06-04 16:14:17.625 sogod[25783] <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0> SQL: SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/gunnarweissmann/Contacts/personal';
2014-06-04 16:14:17.625 sogod[25783] <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0> query has results, entering fetch-mode.
2014-06-04 16:14:17.625 sogod[25783] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7fd33bd805c0] connection=0x0x7fd33bdcbfe0>: got no value for column:
attribute=c_foldername
valueClass=NSString
type=VARCHAR
MySQL4 connection dropped 0x0x7fd33b745c10 (channel=0x0x7fd33ba0c890)
MySQL4 connection dropped 0x0x7fd33bcd35a0 (channel=0x0x7fd33ba2b6b0)
MySQL4 connection dropped 0x0x7fd33bcd35a0 (channel=0x0x7fd33ba23480)
MySQL4 connection dropped 0x0x7fd33bd0bbc0 (channel=0x0x7fd33b901d80)
MySQL4 connection dropped 0x0x7fd33bdb6d60 (channel=0x0x7fd33bc93a80)
MySQL4 connection dropped 0x0x7fd33bcd35a0 (channel=0x0x7fd33bcc7840)
EXCEPTION: <NSException: 0x7fd33c053770> NAME:NSInvalidArgumentException REASON:Tried to add nil to array INFO:(null)
Jun 04 16:14:17 sogod [25312]: <0x0x7fd33baac010[WOWatchDogChild]> child 25783 exited
Jun 04 16:14:17 sogod [25312]: <0x0x7fd33baac010[WOWatchDogChild]> (terminated due to signal 6)
Jun 04 16:14:17 sogod [25312]: <0x0x7fd33baf1c60[WOWatchDog]> child spawned with pid 28449
2014-06-04 16:14:17.729 sogod[28449] MySQL4 connection established 0x0x7fd33b745c10
2014-06-04 16:14:17.729 sogod[28449] MySQL4 channel 0x0x7fd33ba0c890 opened (connection=0x0x7fd33b745c10,sogo)
2014-06-04 16:14:17.729 sogod[28449] <MySQL4Channel[0x0x7fd33ba0c890] connection=0x0x7fd33b745c10> SQL: SELECT count() FROM sogo_user_profile;
2014-06-04 16:14:17.730 sogod[28449] <MySQL4Channel[0x0x7fd33ba0c890] connection=0x0x7fd33b745c10> query has results, entering fetch-mode.
2014-06-04 16:14:17.730 sogod[28449] <MySQL4Channel[0x0x7fd33ba0c890] connection=0x0x7fd33b745c10> SQL: SELECT count() FROM sogo_folder_info;
2014-06-04 16:14:17.731 sogod[28449] <MySQL4Channel[0x0x7fd33ba0c890] connection=0x0x7fd33b745c10> query has results, entering fetch-mode.
2014-06-04 16:14:17.732 sogod[28449] <MySQL4Channel[0x0x7fd33ba0c890] connection=0x0x7fd33b745c10> SQL: SELECT count(*) FROM sogo_sessions_folder;
2014-06-04 16:14:17.732 sogod[28449] <MySQL4Channel[0x0x7fd33ba0c890] connection=0x0x7fd33b745c10> query has results, entering fetch-mode.

Thank you,

Kind regards,

Gunnar Weissmann
ludovic

ludovic

2014-06-16 15:01

administrator   ~0007215

https://github.com/inverse-inc/sogo/commit/50c0b49a6fe210b438d2e5a7abac7219bdb15b8f
Gunnar Weissmann

Gunnar Weissmann

2014-08-26 08:56

reporter   ~0007428

We checked this incident again in 2.2.7 an found out that the problem still exists.

After our database timeout we get the 502 bad gateway error from the nginx, because the database connection doesn't exists yet.

Could you please verify this again?

Thank you.
ludovic

ludovic

2017-07-12 16:59

administrator   ~0012096

Is your MySQL server running on localhost or a remote host to SOGo?
Gunnar Weissmann

Gunnar Weissmann

2017-07-13 05:34

reporter   ~0012097

The MySQL Server is running on a remote host.

Issue History

Date Modified Username Field Change
2014-06-11 14:20 Gunnar Weissmann New Issue
2014-06-16 14:42 Gunnar Weissmann Note Added: 0007214
2014-06-16 15:01 ludovic Target Version => 2.2.6
2014-06-16 15:01 ludovic Note Added: 0007215
2014-06-16 15:01 ludovic Status new => resolved
2014-06-16 15:01 ludovic Fixed in Version => 2.2.6
2014-06-16 15:01 ludovic Resolution open => fixed
2014-06-16 15:01 ludovic Assigned To => ludovic
2014-08-26 08:56 Gunnar Weissmann Note Added: 0007428
2014-08-26 08:56 Gunnar Weissmann Status resolved => feedback
2014-08-26 08:56 Gunnar Weissmann Resolution fixed => reopened
2017-07-12 16:59 ludovic Note Added: 0012096
2017-07-13 05:34 Gunnar Weissmann Note Added: 0012097
2017-07-13 05:34 Gunnar Weissmann Status feedback => assigned