Hi,
can anyone tell me how to debug this?
I don't see any error in any logs related to this, only those empty responses,
but i'm no expert :) I'm also running SOGo V2 on the same database which works
pretty well.
Meanwhile i also updated to the latest nightly.
Syncing of calendar data seems to work too.
I enabled the following debugging settings in sogo.conf:
GCSFolderDebugEnabled = YES;
GCSFolderStoreDebugEnabled = YES;
LDAPDebugEnabled = YES;
NGImap4DisableIMAP4Pooling = YES;
ImapDebugEnabled = YES;
SMTPDebugEnabled = YES;
OCSFolderManagerSQLDebugEnabled = YES;
SOGoDebugRequests = YES;
SOGoMailKeepDraftsAfterSend = YES;
SOGoUIxDebugEnabled = YES;
SoDebugObjectTraversal = YES;
SoSecurityManagerDebugEnabled = YES;
WODontZipResponse = YES;
WODebugZipResponse = YES;
SOGoEASDebugEnabled = YES;
MySQL4DebugEnabled = YES;
PGDebugEnabled = YES;
Heres a log with debugging enabled
Apr 27 08:19:11 sogod [13862]: version 5.1.0 (build root@shiva2.inverse
202104260046) -- starting
Apr 27 08:19:11 sogod [13862]: vmem size check enabled: shutting down app when
vmem > 512 MB. Currently at 339 MB
Apr 27 08:19:11 sogod [13862]: <0x0x55796ad1f460[SOGoProductLoader]> SOGo
products loaded from '/usr/lib64/GNUstep/SOGo':
Apr 27 08:19:11 sogod [13862]: <0x0x55796ad1f460[SOGoProductLoader]>
AdministrationUI.SOGo, Appointments.SOGo, CommonUI.SOGo, Contacts.SOGo,
ContactsUI.SOGo, MailPartViewers.SOGo, Mailer.SOGo, MailerUI.SOGo, MainUI.SOGo,
PreferencesUI.SOGo, SchedulerUI.SOGo
Apr 27 08:19:11 sogod [13862]: All products loaded - current memory usage at
377 MB
Apr 27 08:19:11 sogod [13862]: <0x0x55796ab620b0[WOWatchDog]> listening on
127.0.0.1:20000
Apr 27 08:19:11 sogod [13862]: <0x0x55796ab620b0[WOWatchDog]> watchdog process
pid: 13862
Apr 27 08:19:11 sogod [13862]: <0x0x7f4975906c00[WOWatchDogChild]> watchdog
request timeout set to 10 minutes
Apr 27 08:19:11 sogod [13862]: <0x0x55796ab620b0[WOWatchDog]> preparing 3
children
Apr 27 08:19:11 sogod [13862]: <0x0x55796ab620b0[WOWatchDog]> child spawned
with pid 13863
Apr 27 08:19:11 sogod [13862]: <0x0x55796ab620b0[WOWatchDog]> child spawned
with pid 13864
Apr 27 08:19:11 sogod [13862]: <0x0x55796ab620b0[WOWatchDog]> child spawned
with pid 13865
2021-04-27 08:19:11.275 sogod[13863] MySQL4 connection established
0x0x55796ae809c0
2021-04-27 08:19:11.275 sogod[13863] ---------- -[MySQL4Channel openChannel]:
<MySQL4Channel[0x0x55796acf68f0] connection=0x0x55796ae809c0> opens channel
count[0]
2021-04-27 08:19:11.275 sogod[13863] MySQL4 channel 0x0x55796acf68f0 opened
(connection=0x0x55796ae809c0,sogo)
2021-04-27 08:19:11.275 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_user_profile;
2021-04-27 08:19:11.275 sogod[13864] MySQL4 connection established
0x0x55796ae809c0
2021-04-27 08:19:11.275 sogod[13864] ---------- -[MySQL4Channel openChannel]:
<MySQL4Channel[0x0x55796acf68f0] connection=0x0x55796ae809c0> opens channel
count[0]
2021-04-27 08:19:11.276 sogod[13864] MySQL4 channel 0x0x55796acf68f0 opened
(connection=0x0x55796ae809c0,sogo)
2021-04-27 08:19:11.276 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_user_profile;
2021-04-27 08:19:11.276 sogod[13865] MySQL4 connection established
0x0x55796ae809c0
2021-04-27 08:19:11.276 sogod[13865] ---------- -[MySQL4Channel openChannel]:
<MySQL4Channel[0x0x55796acf68f0] connection=0x0x55796ae809c0> opens channel
count[0]
2021-04-27 08:19:11.276 sogod[13865] MySQL4 channel 0x0x55796acf68f0 opened
(connection=0x0x55796ae809c0,sogo)
2021-04-27 08:19:11.276 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_user_profile;
2021-04-27 08:19:11.276 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.276 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_folder_info;
2021-04-27 08:19:11.277 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.277 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_folder_info;
2021-04-27 08:19:11.277 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.277 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_folder_info;
2021-04-27 08:19:11.277 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.279 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_sessions_folder;
2021-04-27 08:19:11.279 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.280 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_sessions_folder;
2021-04-27 08:19:11.280 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.281 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_sessions_folder;
2021-04-27 08:19:11.281 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.281 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_alarms_folder;
2021-04-27 08:19:11.281 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.282 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_alarms_folder;
2021-04-27 08:19:11.282 sogod[13865] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.282 sogod[13865] ---------- -[MySQL4Channel
primaryCloseChannel]: <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> close channel count[1]
Apr 27 08:19:11 sogod [13865]: <0x0x55796ae98e80[WOHttpAdaptor]> notified the
watchdog that we are ready
2021-04-27 08:19:11.283 sogod[13863] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.283 sogod[13863] ---------- -[MySQL4Channel
primaryCloseChannel]: <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> close channel count[1]
Apr 27 08:19:11 sogod [13863]: <0x0x55796ae98e80[WOHttpAdaptor]> notified the
watchdog that we are ready
2021-04-27 08:19:11.283 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.283 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> SQL: SELECT count(*) FROM sogo_alarms_folder;
2021-04-27 08:19:11.284 sogod[13864] <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> query has results, entering fetch-mode.
2021-04-27 08:19:11.284 sogod[13864] ---------- -[MySQL4Channel
primaryCloseChannel]: <MySQL4Channel[0x0x55796acf68f0]
connection=0x0x55796ae809c0> close channel count[1]
Apr 27 08:19:11 sogod [13864]: <0x0x55796ae98e80[WOHttpAdaptor]> notified the
watchdog that we are ready
Apr 27 08:19:52 sogod [13864]: |SOGo| starting method 'GET' on uri '/SOGo'
Apr 27 08:19:52 sogod [13864]: <0x0x55796aeb9a40[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Apr 27 08:19:52 sogod [13864]: <0x0x55796aeb9a40[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Apr 27 08:19:52 sogod [13864]: |SOGo| traverse(acquire): SOGo
Apr 27 08:19:52 sogod [13864]: |SOGo| do traverse name: 'SOGo'
Apr 27 08:19:52 sogod [13864]: |SOGo| set clientObject:
<SOGo[0x0x55796ae17de0]: name=SOGo>
2021-04-27 08:19:52.022 sogod[13864] MySQL4 connection established
0x0x55796b152360
2021-04-27 08:19:52.022 sogod[13864] ---------- -[MySQL4Channel openChannel]:
<MySQL4Channel[0x0x55796b1d4340] connection=0x0x55796b152360> opens channel
count[0]
2021-04-27 08:19:52.022 sogod[13864] MySQL4 channel 0x0x55796b1d4340 opened
(connection=0x0x55796b152360,sogo)
2021-04-27 08:19:52.022 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: SELECT c_defaults FROM sogo_user_profile
WHERE c_uid = 'anonymous';
2021-04-27 08:19:52.023 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has results, entering fetch-mode.
Apr 27 08:19:52 sogod [13864]: |SOGo| request took 0.021992 seconds to execute
Apr 27 08:19:52 sogod [13864]: <0x0x55796ae9a490[WOResponse]> Zipping of
response disabled
Apr 27 08:19:52 sogod [13864]: 12.34.56.78 "GET /SOGo HTTP/1.1" 302 0/0 0.024 -
- 2M - 13
Apr 27 08:19:52 sogod [13864]: |SOGo| starting method 'GET' on uri '/SOGo/'
Apr 27 08:19:52 sogod [13864]: |SOGo| traverse(acquire): SOGo
Apr 27 08:19:52 sogod [13864]: |SOGo| do traverse name: 'SOGo'
Apr 27 08:19:52 sogod [13864]: |SOGo| set clientObject:
<SOGo[0x0x55796ae17de0]: name=SOGo>
Apr 27 08:19:52 sogod [13864]: |SOGo| request took 0.018876 seconds to execute
Apr 27 08:19:52 sogod [13864]: <0x0x55796b13cdf0[WOResponse]> Zipping of
response disabled
Apr 27 08:19:52 sogod [13864]: 12.34.56.78 "GET /SOGo/ HTTP/1.1" 200 30724/0
0.020 - - 1M - 13
Apr 27 08:20:01 sogod [13864]: |SOGo| starting method 'POST' on uri
'/SOGo/connect'
Apr 27 08:20:01 sogod [13864]: |SOGo| traverse(acquire): SOGo => connect
Apr 27 08:20:01 sogod [13864]: |SOGo| do traverse name: 'SOGo'
Apr 27 08:20:01 sogod [13864]: |SOGo| do traverse name: 'connect'
Apr 27 08:20:01 sogod [13864]: |SOGo| set clientObject:
<SOGo[0x0x55796ae17de0]: name=SOGo>
Apr 27 08:20:01 sogod [13864]: <0x0x55796b1df730[NGLdapConnection]> Using
ldap_initialize for LDAP URL: ldaps://our.ldap.server
Apr 27 08:20:01 sogod [13864]: <0x0x55796b1e06a0[NGLdapConnection]> Using
ldap_initialize for LDAP URL: ldaps://our.ldap.server
2021-04-27 08:20:02.050 sogod[13864] -[NGLdapConnection
_searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter
'(objectClass=*)' for attrs 'subschemaSubentry'
2021-04-27 08:20:02.051 sogod[13864] -[NGLdapConnection
_searchAtBaseDN:qualifier:attributes:scope:]: search at base
'CN=Aggregate,CN=Schema,CN=Configuration,DC=samdom,DC=our.domain,DC=de' filter
'(objectClass=*)' for attrs 'objectclasses'
2021-04-27 08:20:02.064 sogod[13864] -[NGLdapConnection
_searchAtBaseDN:qualifier:attributes:scope:]: search at base
'ou=people,dc=samdom,dc=our.domain,dc=de' filter
'(&(mail=some.u...@our.mail.domain)(memberOf=cn=SOGo,ou=Gruppen,dc=samdom,dc=our.domain,dc=de))'
for attrs 'dn'
Apr 27 08:20:02 sogod [13864]: SOGoRootPage successful login from '12.34.56.78'
for user 'some.u...@our.mail.domain' - expire = -1 grace = -1
Apr 27 08:20:02 sogod [13864]: <0x0x55796b443830[NGLdapConnection]> Using
ldap_initialize for LDAP URL: ldaps://our.ldap.server
2021-04-27 08:20:02.136 sogod[13864] -[NGLdapConnection
_searchAtBaseDN:qualifier:attributes:scope:]: search at base
'ou=people,dc=samdom,dc=our.domain,dc=de' filter
'(&(|(mail=some.u...@our.mail.domain)(mail=some.u...@our.mail.domain))(memberOf=cn=SOGo,ou=Gruppen,dc=samdom,dc=our.domain,dc=de))'
for attrs '*'
2021-04-27 08:20:02.139 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: SELECT c_defaults FROM sogo_user_profile
WHERE c_uid = 'some.u...@our.mail.domain';
2021-04-27 08:20:02.141 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has results, entering fetch-mode.
2021-04-27 08:20:02.148 sogod[13864] MySQL4 connection established
0x0x55796b4fb5a0
2021-04-27 08:20:02.148 sogod[13864] ---------- -[MySQL4Channel openChannel]:
<MySQL4Channel[0x0x55796b4fae50] connection=0x0x55796b4fb5a0> opens channel
count[1]
2021-04-27 08:20:02.148 sogod[13864] MySQL4 channel 0x0x55796b4fae50 opened
(connection=0x0x55796b4fb5a0,sogo)
2021-04-27 08:20:02.148 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> SQL: BEGIN;
2021-04-27 08:20:02.148 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> query has no results.
2021-04-27 08:20:02.149 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> SQL: SELECT t1.c_creationdate, t1.c_id,
t1.c_lastseen, t1.c_value FROM sogo_sessions_folder t1 WHERE
t1.c_id='9EWLA8ELU6Y/bgQ9e+st8A==';
2021-04-27 08:20:02.150 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> query has results, entering fetch-mode.
2021-04-27 08:20:02.150 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> SQL: ROLLBACK;
2021-04-27 08:20:02.150 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> query has no results.
2021-04-27 08:20:02.150 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: BEGIN;
2021-04-27 08:20:02.151 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has no results.
2021-04-27 08:20:02.151 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: INSERT INTO sogo_sessions_folder (c_lastseen,
c_creationdate, c_value, c_id) VALUES (1619504402, 1619504402,
'NLJzqtmFdW16SH5MbvFyNFRPeK5SoDA3Rg9N7a4tKgcTU0jxOYIJSBXfJQ/oPkohaCg8owHauPCl/7nplJzLEWZuu2446JsHlV2uYOhBEBnRBA2fgnFtR+kS73n06CPo5MKOUdIIOS00VfsZVHMirQn2nBixDr9uHHkV11M5uVH9Xxldwk6JIeBHCC4p7nxjit5Ewyp15hJ35k/RMDipFA==',
'9EWLA8ELU6Y/bgQ9e+st8A==');
2021-04-27 08:20:02.152 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has no results.
2021-04-27 08:20:02.152 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: COMMIT;
2021-04-27 08:20:02.155 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has no results.
Apr 27 08:20:02 sogod [13864]: [WARN] <0x0x55796b537800[SOGoWebDAVAclManager]>
entry '{DAV:}write' already exists in DAV permissions table
Apr 27 08:20:02 sogod [13864]: [WARN] <0x0x55796b537800[SOGoWebDAVAclManager]>
entry '{DAV:}write-properties' already exists in DAV permissions table
Apr 27 08:20:02 sogod [13864]: [WARN] <0x0x55796b537800[SOGoWebDAVAclManager]>
entry '{DAV:}write-content' already exists in DAV permissions table
2021-04-27 08:20:02.155 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> SQL: SELECT c_settings FROM sogo_user_profile
WHERE c_uid = 'some.u...@our.mail.domain';
2021-04-27 08:20:02.156 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> query has results, entering fetch-mode.
Apr 27 08:20:02 sogod [13864]: |SOGo| request took 0.285965 seconds to execute
Apr 27 08:20:02 sogod [13864]: <0x0x55796b149760[WOResponse]> Zipping of
response disabled
Apr 27 08:20:02 sogod [13864]: 12.34.56.78 "POST /SOGo/connect HTTP/1.1" 200
51/89 0.288 - - 6M - 14
Apr 27 08:20:03 sogod [13864]: |SOGo| starting method 'GET' on uri
'/SOGo/some.u...@our.mail.domain'
Apr 27 08:20:03 sogod [13864]: |SOGo| traverse(acquire): SOGo =>
some.u...@our.mail.domain
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name: 'SOGo'
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:03 sogod [13864]: |SOGo| set clientObject:
<0x55796b240470[SOGoUserFolder]: name=some.u...@our.mail.domain
container=0x55796ae17de0/(null)>
Apr 27 08:20:03 sogod [13864]: |SOGo| request took 0.002198 seconds to execute
Apr 27 08:20:03 sogod [13864]: <0x0x55796b35aab0[WOResponse]> Zipping of
response disabled
Apr 27 08:20:03 sogod [13864]: 12.34.56.78 "GET /SOGo/some.u...@our.mail.domain
HTTP/1.1" 302 0/0 0.003 - - 28K - 14
Apr 27 08:20:03 sogod [13864]: |SOGo| starting method 'GET' on uri
'/SOGo/some.u...@our.mail.domain/view'
Apr 27 08:20:03 sogod [13864]: |SOGo| traverse(acquire): SOGo =>
some.u...@our.mail.domain => view
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name: 'SOGo'
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name: 'view'
Apr 27 08:20:03 sogod [13864]: |SOGo| set clientObject:
<0x55796b3f1640[SOGoUserFolder]: name=some.u...@our.mail.domain
container=0x55796ae17de0/(null)>
Apr 27 08:20:03 sogod [13864]: |SOGo| request took 0.003252 seconds to execute
Apr 27 08:20:03 sogod [13864]: <0x0x55796b150940[WOResponse]> Zipping of
response disabled
Apr 27 08:20:03 sogod [13864]: 12.34.56.78 "GET
/SOGo/some.u...@our.mail.domain/view HTTP/1.1" 302 0/0 0.004 - - 0 - 14
Apr 27 08:20:03 sogod [13864]: |SOGo| starting method 'GET' on uri
'/SOGo/so/some.u...@our.mail.domain/Mail'
Apr 27 08:20:03 sogod [13864]: |SOGo| traverse(acquire):
some.u...@our.mail.domain => Mail
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name: 'Mail'
Apr 27 08:20:03 sogod [13864]: |SOGo| set clientObject:
<0x55796b362c10[SOGoMailAccounts]: name=Mail
container=0x55796b1df730/some.u...@our.mail.domain>
Apr 27 08:20:03 sogod [13864]: |SOGo| request took 0.001401 seconds to execute
Apr 27 08:20:03 sogod [13864]: <0x0x55796b3b24d0[WOResponse]> Zipping of
response disabled
Apr 27 08:20:03 sogod [13864]: 12.34.56.78 "GET
/SOGo/so/some.u...@our.mail.domain/Mail HTTP/1.1" 302 0/0 0.002 - - 0 - 14
Apr 27 08:20:03 sogod [13864]: |SOGo| starting method 'GET' on uri
'/SOGo/so/some.u...@our.mail.domain/Mail/view'
Apr 27 08:20:03 sogod [13864]: |SOGo| traverse(acquire):
some.u...@our.mail.domain => Mail => view
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name: 'Mail'
Apr 27 08:20:03 sogod [13864]: |SOGo| do traverse name: 'view'
Apr 27 08:20:03 sogod [13864]: |SOGo| set clientObject:
<0x55796b1edcb0[SOGoMailAccounts]: name=Mail
container=0x55796b3bc700/some.u...@our.mail.domain>
2021-04-27 08:20:03.413 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: BEGIN;
2021-04-27 08:20:03.414 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has no results.
2021-04-27 08:20:03.415 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: UPDATE sogo_user_profile SET c_defaults =
'{"SOGoJunkFolderName": "Junk", "SOGoCalendarCategoriesColors": {"Lieferanten":
"#aaa", "Ideen": "#aaa", "Persönlich": "#aaa", "Ferien": "#aaa", "Geburtstag":
"#aaa", "Projekte": "#aaa", "Urlaub": "#aaa", "Fragen": "#aaa", "Geschäft":
"#aaa", "Konkurrenz": "#aaa", "Status": "#aaa", "Feiertag": "#aaa",
"Fortsetzung": "#aaa", "Klienten": "#aaa", "Anrufe": "#aaa", "Reise": "#aaa",
"Verschiedenes": "#aaa", "Besprechung": "#aaa", "Kunde": "#aaa", "Jubiläum":
"#aaa", "Geschenke": "#aaa", "Favoriten": "#aaa"},
"SOGoMailDisplayRemoteInlineImages": "never"}' WHERE c_uid =
'some.u...@our.mail.domain';
2021-04-27 08:20:03.417 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has no results.
2021-04-27 08:20:03.417 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> SQL: COMMIT;
2021-04-27 08:20:03.419 sogod[13864] <MySQL4Channel[0x0x55796b1d4340]
connection=0x0x55796b152360> query has no results.
Apr 27 08:20:03 sogod [13864]: |SOGo| request took 0.089898 seconds to execute
Apr 27 08:20:03 sogod [13864]: <0x0x55796b3b0a40[WOResponse]> Zipping of
response disabled
Apr 27 08:20:03 sogod [13864]: 12.34.56.78 "GET
/SOGo/so/some.u...@our.mail.domain/Mail/view HTTP/1.1" 200 102466/0 0.093 - -
1M - 14
Apr 27 08:20:05 sogod [13864]: |SOGo| starting method 'GET' on uri
'/SOGo/so/some.u...@our.mail.domain/Calendar/alarmslist?browserTime=1619504405'
Apr 27 08:20:05 sogod [13864]: |SOGo| traverse(acquire):
some.u...@our.mail.domain => Calendar => alarmslist
Apr 27 08:20:05 sogod [13864]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:05 sogod [13864]: |SOGo| do traverse name: 'Calendar'
Apr 27 08:20:05 sogod [13864]: |SOGo| do traverse name: 'alarmslist'
2021-04-27 08:20:05.523 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> SQL: SELECT c_path4 FROM sogo_folder_info WHERE
c_path2 = 'some.u...@our.mail.domain' AND c_folder_type = 'Appointment';
2021-04-27 08:20:05.524 sogod[13864] <MySQL4Channel[0x0x55796b4fae50]
connection=0x0x55796b4fb5a0> query has results, entering fetch-mode.
Apr 27 08:20:05 sogod [13863]: |SOGo| starting method 'POST' on uri
'/SOGo/so/some.u...@our.mail.domain/Mail/0/folderINBOX/view'
Apr 27 08:20:05 sogod [13863]: <0x0x55796ab81410[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Apr 27 08:20:05 sogod [13863]: <0x0x55796ab81410[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Apr 27 08:20:05 sogod [13865]: |SOGo| starting method 'GET' on uri
'/SOGo/so/some.u...@our.mail.domain/Mail/0/view'
Apr 27 08:20:05 sogod [13865]: <0x0x55796abb9bb0[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Apr 27 08:20:05 sogod [13865]: <0x0x55796abb9bb0[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Apr 27 08:20:05 sogod [13865]: |SOGo| traverse(acquire):
some.u...@our.mail.domain => Mail => 0 => view
Apr 27 08:20:05 sogod [13865]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:05 sogod [13863]: |SOGo| traverse(acquire):
some.u...@our.mail.domain => Mail => 0 => folderINBOX => view
Apr 27 08:20:05 sogod [13863]: |SOGo| do traverse name:
'some.u...@our.mail.domain'
Apr 27 08:20:05 sogod [13864]: |SOGo| set clientObject:
<0x55796b3d45a0[SOGoAppointmentFolders]: name=Calendar
container=0x55796b540f10/some.u...@our.mail.domain>
Apr 27 08:20:05 sogod [13865]: |SOGo| do traverse name: 'Mail'
Apr 27 08:20:05 sogod [13865]: |SOGo| do traverse name: '0'
Apr 27 08:20:05 sogod [13863]: |SOGo| do traverse name: 'Mail'
Apr 27 08:20:05 sogod [13863]: |SOGo| do traverse name: '0'
Apr 27 08:20:05 sogod [13864]: |SOGo| request took 0.017297 seconds to execute
Apr 27 08:20:05 sogod [13864]: <0x0x55796b383970[WOResponse]> Zipping of
response disabled
Apr 27 08:20:05 sogod [13864]: 12.34.56.78 "GET
/SOGo/so/some.u...@our.mail.domain/Calendar/alarmslist?browserTime=1619504405
HTTP/1.1" 500 36/0 0.019 - - 44K - 14
Apr 27 08:20:05 sogod [13865]: |SOGo| do traverse name: 'view'
Apr 27 08:20:05 sogod [13863]: |SOGo| do traverse name: 'folderINBOX'
Apr 27 08:20:05 sogod [13865]: |SOGo| set clientObject:
<0x55796b182770[SOGoMailAccount]: name=0 container=0x55796ad1c2d0/Mail>
Apr 27 08:20:05 sogod [13865]: |SOGo| request took 0.131991 seconds to execute
Apr 27 08:20:05 sogod [13865]: <0x0x55796ae9a490[WOResponse]> Zipping of
response disabled
Apr 27 08:20:05 sogod [13865]: 12.34.56.78 "GET
/SOGo/so/some.u...@our.mail.domain/Mail/0/view HTTP/1.1" 500 36/0 0.133 - - 3M
- 13
Apr 27 08:20:05 sogod [13863]: |SOGo| do traverse name: 'view'
Apr 27 08:20:05 sogod [13863]: |SOGo| set clientObject:
<0x55796b2a7710[SOGoMailFolder]: name=folderINBOX container=0x55796b1874e0/0>
Apr 27 08:20:05 sogod [13863]: |SOGo| request took 0.186415 seconds to execute
Apr 27 08:20:05 sogod [13863]: <0x0x55796abaa880[WOResponse]> Zipping of
response disabled
Apr 27 08:20:05 sogod [13863]: 12.34.56.78 "POST
/SOGo/so/some.u...@our.mail.domain/Mail/0/folderINBOX/view HTTP/1.1" 500 36/126
0.189 - - 3M - 13
Thanks in advance
Juergen
Am Donnerstag, April 22, 2021 13:12 CEST, Jürgen Echter
(j.ech...@echter-kuechen-elektro.de) <users@sogo.nu> schrieb:
Hi,
i updated to latest nightly SOGo 5 today and it seems something is wrong now.
I can login but i don't see my mails.
I have no errors in my httpd logs, not in my sql logs and nothing in my imap
logs.
In my sogo.log i get the following:
Apr 22 12:58:26 sogod [7210]: 12.34.56.78 "GET /SOGo/so/user@domain/Mail/view
HTTP/1.1" 200 26322/0 0.069 106806 75% 272K - 14
Apr 22 12:58:31 sogod [7210]: 12.34.56.78 "GET
/SOGo/so/user@domain/Calendar/alarmslist?browserTime=1619089111 HTTP/1.1" 500
36/0 0.014 - - 0 - 13
Apr 22 12:58:31 sogod [7210]: 12.34.56.78 "GET /SOGo/so/user@domain/Mail/0/view
HTTP/1.1" 500 36/0 0.011 - - 0 - 13
Apr 22 12:58:31 sogod [7208]: 12.34.56.78 "POST
/SOGo/so/user@domain/Mail/0/folderINBOX/view HTTP/1.1" 500 36/126 0.033 - - 0 -
15
I see 500 Request Failed but i cannot figure out where this exactly comes from.
Firefox console tells me the same, for example:
XHR GET
https://our.sogo.domain/SOGo/so/user@domain/Calendar/alarmslist?browserTime=1619088954
[HTTP/1.1 500 Request Failed 311ms]
Here's ssl_request_log from httpd after reloading the page (ctrl + F5):
[22/Apr/2021:13:06:34 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo/so/user@domain/Mail/view HTTP/1.1" 26321
[22/Apr/2021:13:06:34 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/lodash.min.js HTTP/1.1" 73015
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-animate.min.js HTTP/1.1"
26809
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-sanitize.min.js HTTP/1.1"
6526
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-cookies.min.js HTTP/1.1"
1331
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-aria.min.js HTTP/1.1" 4203
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-messages.min.js HTTP/1.1"
3223
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET
/SOGo.woa/WebServerResources/js/Common/sgCkeditor.component.js?lm=1619080177
HTTP/1.1" 11979
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/Preferences.services.js?lm=1619080178
HTTP/1.1" 14407
[22/Apr/2021:13:06:36 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/Contacts.services.js?lm=1619080178
HTTP/1.1" 18903
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/Common.js?lm=1619080178 HTTP/1.1" 83551
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular.min.js HTTP/1.1" 177366
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-ui-router.min.js HTTP/1.1"
117309
[22/Apr/2021:13:06:37 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/Mailer.js?lm=1619080178 HTTP/1.1" 4379
[22/Apr/2021:13:06:37 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/Scheduler.services.js?lm=1619080178
HTTP/1.1" 95849
[22/Apr/2021:13:06:38 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET
/SOGo.woa/WebServerResources/js/vendor/angular-file-upload.min.js?lm=1619080178
HTTP/1.1" 23345
[22/Apr/2021:13:06:38 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/FileSaver.min.js?lm=1619080178
HTTP/1.1" 2685
[22/Apr/2021:13:06:37 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/Mailer.services.js?lm=1619080178 HTTP/1.1"
83894
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/ckeditor/ckeditor.js?lm=1619080178
HTTP/1.1" 642225
[22/Apr/2021:13:06:35 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo.woa/WebServerResources/js/vendor/angular-material.min.js HTTP/1.1"
427753
[22/Apr/2021:13:06:42 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo/so/user@domain/Calendar/alarmslist?browserTime=1619089602 HTTP/1.1"
36
[22/Apr/2021:13:06:42 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"POST /SOGo/so/user@domain/Mail/0/folderINBOX/view HTTP/1.1" 36
[22/Apr/2021:13:06:42 +0200] 12.34.56.78 TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256
"GET /SOGo/so/user@domain/Mail/0/view HTTP/1.1" 36
Any hints what may have changed or what i should change would be nice.
Greetings
Juergen--
users@sogo.nu
https://inverse.ca/sogo/lists
--
users@sogo.nu
https://inverse.ca/sogo/lists
