View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0005449SOGoBackend Generalpublic2021-12-17 08:262022-01-17 14:10
Reporterdaduke Assigned To 
PrioritynormalSeveritymajorReproducibilityalways
Status closedResolutionno change required 
Platformamd64OSDebianOS Version11
Product Version5.2.0 
Summary0005449: can't upgrade from 5.0.1 to anything newer due to "the called object returned no result" error
Description

Hi,

we manage two ansible-deployed bullseye servers that run 5.0.1 just fine. However, we can't update either machine to neither 5.2, 5.3 or now 5.4 since we get the red "Internal server error" popup that's caused by "XML Parsing Error: syntax error"s on calls to

/SOGo/so/<uid>/Calendar/alarmslist?browserTime=1639726363 and
/SOGo/so/<uid>/Calendar/eventsblocks?ed=20211219&sd=20211213&view=weekview

Those contain "the called object returned no result" instead of valid XML or JSON. We found several other similar reports like

https://community.mailcow.email/d/854-cant-use-sogo-after-login

without a clear path towards a solution. Goin back to 5.0.1 solves the problem but is hardly sustainable.

HOWEVER: we have a third test server that was installed from bullseye netinstall without ansible, with the OS + Apache configured manually. That one doesn't show the error. Apache + sogo config is identical (modulo LDAP) and we compared package lists, Apache modules and everything else we could think of, to no avail. We have no idea why this one works and the other two don't.

There's nothing in the log files (all debuggin levels on max) and we've spent many hours on trying to tackle the problem from all possible sides, but we're running out of ideas.

The "the called object returned no result" seems to come from libsope1 which we've also tried in several versions.

Any ideas what we could do to identify the root cause?

thanks,
-Christian

TagsNo tags attached.

Activities

daduke

daduke

2021-12-20 08:51

reporter   ~0015701

I just noticed the URLs were cut off: the failing calls go to

/SOGo/so/daduke/Calendar/alarmslist?browserTime=1639990205 and
/SOGo/so/daduke/Contacts/personal/view

TIA for any hints
daduke

daduke

2022-01-06 12:50

reporter   ~0015726

no-one?
daduke

daduke

2022-01-07 08:18

reporter   ~0015727

Last edited: 2022-01-11 15:15

in another desperate attempt to make some progress here, I now logged the mysql queries generated by a reload of the calendar view.

working instance:

220107  9:07:41     30 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            30 Query    SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/daduke/Calendar/personal'
            30 Query    SELECT c_component, c_status FROM sogodaduke00168ec5f0c_quick WHERE ((c_component = 'vtodo') AND (c_status != 1) AND (c_status != 3))
            31 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            31 Quit 
            30 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            35 Connect  sogo@localhost on sogo using TCP/IP
            35 Query    SET CHARACTER SET utf8mb4
            35 Query    SELECT b.c_name,b.c_content,b.c_creationdate,b.c_lastmodified,b.c_version,a.c_component,a.c_title,a.c_location,a.c_orgmail,a.c_status,a.c_category,a.c_classification,a.c_isallday,a.c_isopaque,a.c_participants,a.c_partmails,a.c_partstates,a.c_sequence,a.c_priority,a.c_cycleinfo,a.c_iscycle,a.c_nextalarm,a.c_description,a.c_uid,a.c_startdate,a.c_enddate FROM sogodaduke00168ec5f0c_quick a, sogodaduke00168ec5f0c b WHERE ((c_component = 'vevent') AND ((c_startdate IS NULL) OR (c_startdate &lt;= 1641686399)) AND ((c_enddate IS NULL) OR (c_enddate >= 1641081600)) AND (c_iscycle = 0)) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL)
            35 Query    SELECT b.c_name,b.c_content,b.c_creationdate,b.c_lastmodified,b.c_version,a.c_component,a.c_title,a.c_location,a.c_orgmail,a.c_status,a.c_category,a.c_classification,a.c_isallday,a.c_isopaque,a.c_participants,a.c_partmails,a.c_partstates,a.c_sequence,a.c_priority,a.c_cycleinfo,a.c_iscycle,a.c_nextalarm,a.c_description,a.c_uid,a.c_startdate,a.c_enddate FROM sogodaduke00168ec5f0c_quick a, sogodaduke00168ec5f0c b WHERE ((c_component = 'vevent') AND ((c_startdate IS NULL) OR (c_startdate &lt;= 1641686399)) AND ((c_cycleenddate IS NULL) OR (c_cycleenddate >= 1641081600)) AND (c_iscycle = 1)) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL)
            30 Query    SELECT c_name, c_nextalarm, c_iscycle FROM sogodaduke00168ec5f0c_quick WHERE (((c_nextalarm &lt;= 1641715661) AND (c_nextalarm >= 1641542861)) OR ((c_nextalarm > 0) AND (c_nextalarm &lt;= 1641542861) AND (c_enddate > 1641542861)))
            35 Query    SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/daduke/Calendar/personal'
            35 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            30 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            30 Query    BEGIN
            30 Query    UPDATE sogo_user_profile     SET c_settings = '{&quot;Calendar&quot;: {&quot;FoldersOrder&quot;: [&quot;personal&quot;], &quot;View&quot;: &quot;weekview&quot;, &quot;FolderColors&quot;: {&quot;daduke:Calendar\\/personal&quot;: &quot;#33FF33&quot;}, &quot;NotifyOnPersonalModifications&quot;: {&quot;daduke:Calendar\\/personal&quot;: 0}, &quot;EventsFilterState&quot;: &quot;view_next7&quot;, &quot;SelectedList&quot;: &quot;eventsListView&quot;, &quot;FreeBusyExclusions&quot;: {&quot;daduke:Calendar\\/personal&quot;: 0}, &quot;InactiveFolders&quot;: [], &quot;NotifyOnExternalModifications&quot;: {&quot;daduke:Calendar\\/personal&quot;: 0}, &quot;NotifyUserOnPersonalModifications&quot;: {&quot;daduke:Calendar\\/personal&quot;: 0}, &quot;FolderSynchronize&quot;: {&quot;daduke:Calendar\\/personal&quot;: 1}, &quot;ListState&quot;: &quot;collapse&quot;, &quot;EventsSortingState&quot;: [&quot;start&quot;, &quot;1&quot;]}, &quot;General&quot;: {&quot;Salt&quot;: &quot;814b30c9302ff041e06689a3c2fa63720d10cbe4&quot;}}'   WHERE c_uid = 'daduke'
            30 Query    COMMIT
            35 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            35 Query    BEGIN
[...] more queries

non-working instance:

220107  9:11:21     32 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            32 Query    BEGIN
            32 Query    UPDATE sogo_user_profile     SET c_settings = '{&quot;Calendar&quot;: {&quot;FoldersOrder&quot;: [&quot;personal&quot;]}}'   WHERE c_uid = 'daduke'
            32 Query    COMMIT
            32 Query    SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/daduke/Calendar/personal'
            32 Query    SELECT c_component, c_status FROM sogo_quick_appointment WHERE c_folder_id = 1 AND ((c_component = 'vtodo') AND (c_status != 1) AND (c_status != 3))
220107  9:11:22     32 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
            30 Query    SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment'
and that's all

maybe "the called object returned no result" is no XML error per se, but simply a correct statement since there is no data to be converted into XML. But then why does it not query the DB in the same way?
daduke

daduke

2022-01-07 08:31

reporter   ~0015728

Last edited: 2022-01-11 15:15

corresponding sogo log w/ all debug options enabled:

Jan 07 09:28:29 sogod [1885338]: |SOGo| starting method 'GET' on uri '/SOGo/so/daduke/Calendar/view'
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad042710[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad042710[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
2022-01-07 09:28:29.688 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: BEGIN;
2022-01-07 09:28:29.689 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has no results.
2022-01-07 09:28:29.689 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='fXQ6GRehH5nMkqUtWoc8tg==';
2022-01-07 09:28:29.690 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has results, entering fetch-mode.
2022-01-07 09:28:29.690 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: ROLLBACK;
2022-01-07 09:28:29.691 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has no results.
2022-01-07 09:28:29.694 sogod[1885338:1885338] MySQL4 connection established 0x0x55cfad37f300
2022-01-07 09:28:29.694 sogod[1885338:1885338] ---------- -[MySQL4Channel openChannel]: &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> opens channel count[1]
2022-01-07 09:28:29.694 sogod[1885338:1885338] MySQL4 channel 0x0x55cfad1d72e0 opened (connection=0x0x55cfad37f300,sogo)
2022-01-07 09:28:29.694 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: BEGIN;
2022-01-07 09:28:29.695 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has no results.
2022-01-07 09:28:29.695 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='fXQ6GRehH5nMkqUtWoc8tg==';
2022-01-07 09:28:29.696 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has results, entering fetch-mode.
2022-01-07 09:28:29.696 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: ROLLBACK;
2022-01-07 09:28:29.696 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has no results.
2022-01-07 09:28:29.696 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: BEGIN;
2022-01-07 09:28:29.697 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has no results.
2022-01-07 09:28:29.697 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: UPDATE sogo_sessions_folder SET c_lastseen = 1641544109, c_creationdate = 1641477852, c_value = 'v2cJ8mJyffpGSZccjvXnaVvLuSqLLR41qhGsx8mr0Jn9P9FL9kGuwai/c+lWaHWjja+SUnEBZiYIFxQPzC3pcM/5d8+CibATLRRraI6vHATIlioVnuKlnCZafvmXQV7lcGAhYHSJe2l4W9BVFWNQ+05xMI/NemkhW8cfgYTLLgR3JqTjfQ842OSAo8cCK7yb3qGbuF40b70jLmicUexVsA==', c_id = 'fXQ6GRehH5nMkqUtWoc8tg==' WHERE c_id='fXQ6GRehH5nMkqUtWoc8tg==';
2022-01-07 09:28:29.698 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has no results.
2022-01-07 09:28:29.698 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: COMMIT;
2022-01-07 09:28:29.701 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has no results.
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad084550[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldaps.phys.ethz.ch/????!StartTLS
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad4380a0[LDAPSource]> &lt;NSException: 0x55cfad1a55f0> NAME:LDAPException REASON:operation bind failed: Invalid credentials (0x31) INFO:{&quot;error_code&quot; = 49; login = &quot;cn=daduke,ou=groups,dc=phys,dc=ethz,dc=ch&quot;; }
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad073760[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldaps.phys.ethz.ch/????!StartTLS
Jan 07 09:28:29 sogod [1885338]: |SOGo| traverse(acquire): daduke => Calendar => view
Jan 07 09:28:29 sogod [1885338]: |SOGo|   do traverse name: 'daduke'
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad42dbc0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldaps.phys.ethz.ch/????!StartTLS
2022-01-07 09:28:29.872 sogod[1885338:1885338] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectClass=*)' for attrs 'subschemaSubentry'
2022-01-07 09:28:29.874 sogod[1885338:1885338] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'cn=Subschema' filter '(objectClass=*)' for attrs 'objectclasses'
2022-01-07 09:28:29.912 sogod[1885338:1885338] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=groups,dc=phys,dc=ethz,dc=ch' filter '(&(|(cn=daduke)(mail=daduke))(objectClass=dphysGroup))' for attrs '*'
Jan 07 09:28:29 sogod [1885338]: &lt;0x0x55cfad768a00[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldaps.phys.ethz.ch/????!StartTLS
2022-01-07 09:28:29.943 sogod[1885338:1885338] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectClass=*)' for attrs 'subschemaSubentry'
2022-01-07 09:28:29.944 sogod[1885338:1885338] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'cn=Subschema' filter '(objectClass=*)' for attrs 'objectclasses'
2022-01-07 09:28:29.981 sogod[1885338:1885338] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=phys,dc=ethz,dc=ch' filter '(&(|(uid=daduke)(mail=daduke))(objectClass=dphysUser)(!(blocked=yes))(accessRight=studentUser))' for attrs '*'
Jan 07 09:28:29 sogod [1885338]: |SOGo|   do traverse name: 'Calendar'
Jan 07 09:28:29 sogod [1885338]: [WARN] &lt;0x0x55cfad877850[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Jan 07 09:28:29 sogod [1885338]: [WARN] &lt;0x0x55cfad877850[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Jan 07 09:28:29 sogod [1885338]: [WARN] &lt;0x0x55cfad877850[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Jan 07 09:28:29 sogod [1885338]: |SOGo|   do traverse name: 'view'
2022-01-07 09:28:29.987 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'daduke';
2022-01-07 09:28:29.988 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has results, entering fetch-mode.
2022-01-07 09:28:29.989 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment';
2022-01-07 09:28:29.990 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has results, entering fetch-mode.
2022-01-07 09:28:29.992 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: SELECT c_settings FROM sogo_user_profile WHERE c_uid = 'daduke';
2022-01-07 09:28:29.992 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has results, entering fetch-mode.
Jan 07 09:28:30 sogod [1885338]: [WARN] &lt;0x0x7ff09d64df60[WOxElemBuilder]> could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder
Jan 07 09:28:30 sogod [1885338]: |SOGo| set clientObject: &lt;0x55cfad866610[SOGoAppointmentFolders]: name=Calendar container=0x55cfad867ae0/daduke>
2022-01-07 09:28:30.071 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190> SQL: SELECT c_foldername FROM sogo_folder_info WHERE c_path = '/Users/daduke/Calendar/personal';
2022-01-07 09:28:30.072 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad42b900] connection=0x0x55cfad086190>   query has results, entering fetch-mode.
2022-01-07 09:28:30.073 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: SELECT c_folder_id, c_path, c_location, c_quick_location, c_acl_location, c_folder_type FROM sogo_folder_info WHERE c_path1 = 'Users' AND c_path2 = 'daduke' AND c_path3 = 'Calendar' AND c_path4 = 'personal';
2022-01-07 09:28:30.074 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has results, entering fetch-mode.
2022-01-07 09:28:30.075 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: SELECT c_component, c_status FROM sogo_quick_appointment WHERE c_folder_id = 1 AND ((c_component = 'vtodo') AND (c_status != 1) AND (c_status != 3));
2022-01-07 09:28:30.076 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has results, entering fetch-mode.
Jan 07 09:28:30 sogod [1885338]: |SOGo| request took 0.441900 seconds to execute
Jan 07 09:28:30 sogod [1885338]: &lt;0x0x55cfad064820[WOResponse]> Zipping of response disabled
Jan 07 09:28:30 sogod [1885338]: 10.6.199.191 &quot;GET /SOGo/so/daduke/Calendar/view HTTP/1.1&quot; 200 78781/0 0.446 - - 10M - 13
Jan 07 09:28:30 sogod [1885338]: |SOGo| starting method 'GET' on uri '/SOGo/so/daduke/Calendar/alarmslist?browserTime=1641544110'
Jan 07 09:28:30 sogod [1885338]: |SOGo| traverse(acquire): daduke => Calendar => alarmslist
Jan 07 09:28:30 sogod [1885338]: |SOGo|   do traverse name: 'daduke'
Jan 07 09:28:30 sogod [1885338]: |SOGo|   do traverse name: 'Calendar'
Jan 07 09:28:30 sogod [1885338]: |SOGo|   do traverse name: 'alarmslist'
2022-01-07 09:28:30.519 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment';
2022-01-07 09:28:30.520 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has results, entering fetch-mode.
Jan 07 09:28:30 sogod [1885338]: |SOGo| set clientObject: &lt;0x55cfada7ddf0[SOGoAppointmentFolders]: name=Calendar container=0x55cfacfe1980/daduke>
Jan 07 09:28:30 sogod [1885338]: |SOGo| request took 0.007734 seconds to execute
Jan 07 09:28:30 sogod [1885338]: &lt;0x0x55cfad1ff530[WOResponse]> Zipping of response disabled
Jan 07 09:28:30 sogod [1885338]: 10.6.199.191 &quot;GET /SOGo/so/daduke/Calendar/alarmslist?browserTime=1641544110 HTTP/1.1&quot; 500 36/0 0.010 - - 0 - 13
Jan 07 09:28:30 sogod [1885338]: |SOGo| starting method 'GET' on uri '/SOGo/so/daduke/Calendar/eventsblocks?ed=20220109&sd=20220103&view=weekview'
Jan 07 09:28:30 sogod [1885338]: |SOGo| traverse(acquire): daduke => Calendar => eventsblocks
Jan 07 09:28:30 sogod [1885338]: |SOGo|   do traverse name: 'daduke'
Jan 07 09:28:30 sogod [1885338]: |SOGo|   do traverse name: 'Calendar'
Jan 07 09:28:30 sogod [1885338]: |SOGo|   do traverse name: 'eventsblocks'
2022-01-07 09:28:30.536 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'daduke' AND c_folder_type = 'Appointment';
2022-01-07 09:28:30.537 sogod[1885338:1885338] &lt;MySQL4Channel[0x0x55cfad1d72e0] connection=0x0x55cfad37f300>   query has results, entering fetch-mode.
Jan 07 09:28:30 sogod [1885338]: |SOGo| set clientObject: &lt;0x55cfada64030[SOGoAppointmentFolders]: name=Calendar container=0x55cfacfdaf90/daduke>
Jan 07 09:28:30 sogod [1885338]: |SOGo| request took 0.006514 seconds to execute
Jan 07 09:28:30 sogod [1885338]: &lt;0x0x55cfad964340[WOResponse]> Zipping of response disabled
Jan 07 09:28:30 sogod [1885338]: 10.6.199.191 &quot;GET /SOGo/so/daduke/Calendar/eventsblocks?ed=20220109&sd=20220103&view=weekview HTTP/1.1&quot; 500 36/0 0.009 - - 0 - 13
francis

francis

2022-01-11 15:23

administrator   ~0015740

Please use gdb to print a stack trace when reaching SoObjectRequestHandler.m:595.
daduke

daduke

2022-01-12 07:56

reporter   ~0015753

We found out a bit more:

  • switched from apache to nginx: sogo works!
  • switched maria DB from local to dedicated DB server: sogo stops working
  • mess around with browsers, DB, random things: sogo works again

right now the best I can say is that changing something while the user is logged in and browser is open might cause the "internal server error". It seems to be some session/caching/? issue. One can usually recover by forcing the browser to load /SOGo/so/uid/Preferences instead of /Calendar and force a logout.

Somebody with sogo code knowledge should probably look into this...
daduke

daduke

2022-01-14 06:27

reporter   ~0015769

Hi again,

we found the apache config line that reproducibly triggers the problem:

Header edit Set-Cookie ^(.*)$ $1;HttpOnly;Secure

it can be mitigated by using

Header always edit Set-Cookie ^(.*)$ $1;HttpOnly;Secure

in this case you can still trigger the "internal server error" by messing with the session (web server restart followed by logout), but it can be fixed by requesting /SOGo/so/&lt;uid>/Preferences.

Something is broken with 5.2+ session handling...
francis

francis

2022-01-17 14:01

administrator   ~0015774

Don't mess with the HttpOnly and Secure parameters of the the Set-Cookie header; SOGo will handle them. You will also break XSRF validation if you set them in your Web server configuration.
daduke

daduke

2022-01-17 14:07

reporter   ~0015775

thanks for the heads-up. It's part of our web server ansible deployment and hasn't caused any issues in the past, so it took us a while to find it. Feel free to close this issue. Thanks!

Issue History

Date Modified Username Field Change
2021-12-17 08:26 daduke New Issue
2021-12-20 08:51 daduke Note Added: 0015701
2022-01-06 12:50 daduke Note Added: 0015726
2022-01-07 08:18 daduke Note Added: 0015727
2022-01-07 08:31 daduke Note Added: 0015728
2022-01-11 15:15 francis Note Edited: 0015728
2022-01-11 15:15 francis Note Edited: 0015727
2022-01-11 15:23 francis Note Added: 0015740
2022-01-12 07:56 daduke Note Added: 0015753
2022-01-14 06:27 daduke Note Added: 0015769
2022-01-17 14:01 francis Note Added: 0015774
2022-01-17 14:07 daduke Note Added: 0015775
2022-01-17 14:10 francis Status new => closed
2022-01-17 14:10 francis Resolution open => no change required