I'm trialling SOGo and running into some challenges with strange
unprompted logouts.
I'll be using the web interface, and all of a sudden will be dropped
back to login. Login at this point does not work.
Log contains a bunch (60 or 70 in a row) of:
Apr 16 09:20:54 sogod [79477]: [WARN] <0x0x55c361413710[WOElementID]>
tried to increment a non-existing element-id
Apr 16 09:20:54 sogod [79477]: [WARN] <0x0x55c361413710[WOElementID]>
tried to increment a non-existing element-id
Apr 16 09:20:54 sogod [79477]: [WARN] <0x0x55c361413710[WOElementID]>
tried to increment a non-existing element-id
...followed by:
Apr 16 09:20:54 sogod [79477]:
<0x0x55c360e9ea30[SOGoWebAuthenticator]> tried wrong password for user
'QzsX6IKlQ9RuWvMoQbtCB8zaZ... where the string is several hundred
characters, and that line is repeated three times.
Once that happens, no-one can login until sogod is restarted.
What's your DB backend?
Hopefully, you followed this
https://www.sogo.nu/files/docs/SOGoInstallationGuide.html#_database_configuration
and can get more debug?
Yes I followed the instructions on setting up the DB. I am using
mysql. MySQL log is clear at the time of the issue. Configuration is:
/* Database configuration */
OCSFolderInfoURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_folder_info";
SOGoProfileURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_user_profile";
OCSSessionsFolderURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_sessions_folder";
OCSEMailAlarmsFolderURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_alarms_folder";
Authentication is LDAP:
/* LDAP */
domains = {
simonandkate.net = {
SOGoMailDomain = simonandkate.net;
SOGoUserSources = (
{
type = ldap;
CNFieldName = cn;
IDFieldName = uid;
UIDFieldName = uid;
MailFieldNames = (mail);
baseDN = "ou=users,dc=simonandkate,dc=lan";
bindDN = "cn=horde,ou=accounts,dc=simonandkate,dc=lan";
bindFields = (mail);
IMAPLoginFieldName = uid;
bindPassword = password;
bindAsCurrentUser = YES;
userPasswordAlgorithm = ssha512;
canAuthenticate = YES;
displayName = "Global Directory";
hostname = "ldap://ldap.simonandkate.lan/????!StartTLS";;
id = public;
isAddressBook = YES;
}
);
};
};
SOGoEnableDomainBasedUID = YES;
The system seems to be working OK most of the time, but randomly
(has done it three times over last 24 h) throws user out, chucks 70
x WOElementID errors, then the messages with 100s of characters
long "user" trying wrong password, and a blocked system with no
login capable until sogod is restarted.
This is the log's startup sequence, and all looks fine:
Apr 16 18:20:32 sogod [165019]: version 5.8.2 (build root@
202304152116) -- starting
Apr 16 18:20:32 sogod [165019]: vmem size check enabled: shutting
down app when vmem > 384 MB. Currently at 244 MB
Apr 16 18:20:32 sogod [165019]:
<0x0x55c461a29f70[SOGoProductLoader]> SOGo products loaded from
'/usr/lib64/GNUstep/SOGo':
Apr 16 18:20:32 sogod [165019]:
<0x0x55c461a29f70[SOGoProductLoader]> AdministrationUI.SOGo,
Appointments.SOGo, CommonUI.SOGo, Contacts.SOGo, ContactsUI.SOGo,
MailPartViewers.SOGo, Mailer.SOGo, MailerUI.SOGo, MainUI.SOGo,
PreferencesUI.SOGo, SchedulerUI.SOGo, ActiveSync.SOGo
Apr 16 18:20:32 sogod [165019]: All products loaded - current
memory usage at 296 MB
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
listening on 127.0.0.1:20000
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
watchdog process pid: 165019
Apr 16 18:20:32 sogod [165019]: <0x0x7f8c7d878f80[WOWatchDogChild]>
watchdog request timeout set to 60 minutes
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
preparing 3 children
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
child spawned with pid 165020
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
child spawned with pid 165021
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
child spawned with pid 165022
Apr 16 18:20:32 sogod [165021]: <0x0x55c461a653c0[WOHttpAdaptor]>
notified the watchdog that we are ready
Apr 16 18:20:32 sogod [165020]: <0x0x55c461a65410[WOHttpAdaptor]>
notified the watchdog that we are ready
Apr 16 18:20:32 sogod [165022]: <0x0x55c461a65600[WOHttpAdaptor]>
notified the watchdog that we are ready
Apr 16 18:20:32 sogod [165022]: <0x0x55c46185aae0[SOGoCache]> Cache
cleanup interval set every 300.000000 seconds
Apr 16 18:20:32 sogod [165022]: <0x0x55c46185aae0[SOGoCache]> Using
host(s) '127.0.0.1' as server(s)
Apr 16 18:20:32 sogod [165022]: <0x0x55c461836b10[NGImap4Client]>
TLS started successfully.
Apr 16 18:20:33 sogod [165022]:
<0x0x55c4621236c0[SOGoWebDAVAclManager]> entry '{DAV:}write'
already exists in DAV permissions table
Apr 16 18:20:33 sogod [165022]:
<0x0x55c4621236c0[SOGoWebDAVAclManager]> entry
'{DAV:}write-properties' already exists in DAV permissions table
Apr 16 18:20:33 sogod [165022]:
<0x0x55c4621236c0[SOGoWebDAVAclManager]> entry
'{DAV:}write-content' already exists in DAV permissions table
Apr 16 18:20:33 sogod [165022]:
<0x0x55c461c99de0[SOGoActiveSyncDispatcher]> Sleeping 45 seconds
while detecting changes for user [email protected][1] in
Ping...
I'm only evaluating, so I'm not pushing the UI hard, and when it's
happened it's been WebUI kickout. I'll keep poking it, but without
knowing what to look for it will be hard to troubleshoot
further.I've enabled all the debug levels in sogo.conf, will see if
it happens again.
It kicked me out again, with full debug logging, but there are a
*lot* of logs with everything in debug. Is there a best way to
submit bug content?
No WOELementID errors, but still the long User errors followed by
kickout and can't log back in.
Simon.
___________
Simon Wilson
M: 0400 12 11 16
I'm trialling SOGo and running into some challenges with strange
unprompted logouts.
I'll be using the web interface, and all of a sudden will be dropped
back to login. Login at this point does not work.
Log contains a bunch (60 or 70 in a row) of:
Apr 16 09:20:54 sogod [79477]: [WARN] <0x0x55c361413710[WOElementID]>
tried to increment a non-existing element-id
Apr 16 09:20:54 sogod [79477]: [WARN] <0x0x55c361413710[WOElementID]>
tried to increment a non-existing element-id
Apr 16 09:20:54 sogod [79477]: [WARN] <0x0x55c361413710[WOElementID]>
tried to increment a non-existing element-id
...followed by:
Apr 16 09:20:54 sogod [79477]:
<0x0x55c360e9ea30[SOGoWebAuthenticator]> tried wrong password for user
'QzsX6IKlQ9RuWvMoQbtCB8zaZ... where the string is several hundred
characters, and that line is repeated three times.
Once that happens, no-one can login until sogod is restarted.
What's your DB backend?
Hopefully, you followed this
https://www.sogo.nu/files/docs/SOGoInstallationGuide.html#_database_configuration
and can get more debug?
Yes I followed the instructions on setting up the DB. I am using
mysql. MySQL log is clear at the time of the issue. Configuration is:
/* Database configuration */
OCSFolderInfoURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_folder_info";
SOGoProfileURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_user_profile";
OCSSessionsFolderURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_sessions_folder";
OCSEMailAlarmsFolderURL =
"mysql://sogo:password@localhost:3306/sogo/sogo_alarms_folder";
Authentication is LDAP:
/* LDAP */
domains = {
simonandkate.net = {
SOGoMailDomain = simonandkate.net;
SOGoUserSources = (
{
type = ldap;
CNFieldName = cn;
IDFieldName = uid;
UIDFieldName = uid;
MailFieldNames = (mail);
baseDN = "ou=users,dc=simonandkate,dc=lan";
bindDN = "cn=horde,ou=accounts,dc=simonandkate,dc=lan";
bindFields = (mail);
IMAPLoginFieldName = uid;
bindPassword = password;
bindAsCurrentUser = YES;
userPasswordAlgorithm = ssha512;
canAuthenticate = YES;
displayName = "Global Directory";
hostname = "ldap://ldap.simonandkate.lan/????!StartTLS";;
id = public;
isAddressBook = YES;
}
);
};
};
SOGoEnableDomainBasedUID = YES;
The system seems to be working OK most of the time, but randomly
(has done it three times over last 24 h) throws user out, chucks 70
x WOElementID errors, then the messages with 100s of characters long
"user" trying wrong password, and a blocked system with no login
capable until sogod is restarted.
This is the log's startup sequence, and all looks fine:
Apr 16 18:20:32 sogod [165019]: version 5.8.2 (build root@
202304152116) -- starting
Apr 16 18:20:32 sogod [165019]: vmem size check enabled: shutting
down app when vmem > 384 MB. Currently at 244 MB
Apr 16 18:20:32 sogod [165019]:
<0x0x55c461a29f70[SOGoProductLoader]> SOGo products loaded from
'/usr/lib64/GNUstep/SOGo':
Apr 16 18:20:32 sogod [165019]:
<0x0x55c461a29f70[SOGoProductLoader]> AdministrationUI.SOGo,
Appointments.SOGo, CommonUI.SOGo, Contacts.SOGo, ContactsUI.SOGo,
MailPartViewers.SOGo, Mailer.SOGo, MailerUI.SOGo, MainUI.SOGo,
PreferencesUI.SOGo, SchedulerUI.SOGo, ActiveSync.SOGo
Apr 16 18:20:32 sogod [165019]: All products loaded - current memory
usage at 296 MB
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
listening on 127.0.0.1:20000
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
watchdog process pid: 165019
Apr 16 18:20:32 sogod [165019]: <0x0x7f8c7d878f80[WOWatchDogChild]>
watchdog request timeout set to 60 minutes
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]>
preparing 3 children
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]> child
spawned with pid 165020
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]> child
spawned with pid 165021
Apr 16 18:20:32 sogod [165019]: <0x0x55c461a4e970[WOWatchDog]> child
spawned with pid 165022
Apr 16 18:20:32 sogod [165021]: <0x0x55c461a653c0[WOHttpAdaptor]>
notified the watchdog that we are ready
Apr 16 18:20:32 sogod [165020]: <0x0x55c461a65410[WOHttpAdaptor]>
notified the watchdog that we are ready
Apr 16 18:20:32 sogod [165022]: <0x0x55c461a65600[WOHttpAdaptor]>
notified the watchdog that we are ready
Apr 16 18:20:32 sogod [165022]: <0x0x55c46185aae0[SOGoCache]> Cache
cleanup interval set every 300.000000 seconds
Apr 16 18:20:32 sogod [165022]: <0x0x55c46185aae0[SOGoCache]> Using
host(s) '127.0.0.1' as server(s)
Apr 16 18:20:32 sogod [165022]: <0x0x55c461836b10[NGImap4Client]>
TLS started successfully.
Apr 16 18:20:33 sogod [165022]:
<0x0x55c4621236c0[SOGoWebDAVAclManager]> entry '{DAV:}write' already
exists in DAV permissions table
Apr 16 18:20:33 sogod [165022]:
<0x0x55c4621236c0[SOGoWebDAVAclManager]> entry
'{DAV:}write-properties' already exists in DAV permissions table
Apr 16 18:20:33 sogod [165022]:
<0x0x55c4621236c0[SOGoWebDAVAclManager]> entry '{DAV:}write-content'
already exists in DAV permissions table
Apr 16 18:20:33 sogod [165022]:
<0x0x55c461c99de0[SOGoActiveSyncDispatcher]> Sleeping 45 seconds
while detecting changes for user [email protected][1] in Ping...
I'm only evaluating, so I'm not pushing the UI hard, and when it's
happened it's been WebUI kickout. I'll keep poking it, but without
knowing what to look for it will be hard to troubleshoot
further.I've enabled all the debug levels in sogo.conf, will see if
it happens again.
It kicked me out again, with full debug logging, but there are a *lot*
of logs with everything in debug. Is there a best way to submit bug
content?
No WOELementID errors, but still the long User errors followed by
kickout and can't log back in.
Simon.
___________
Simon Wilson
M: 0400 12 11 16
This may be related to intermittent login issues I have, I am not
sure. I think it's probably worth me reviewing here the LDAP settings
to be sure I have that correct, but correct or not it feels like a bug
here as login works with the settings *most of the time* and then
fails randomly before working again.
LDAP setup (OpenLDAP on a separate server, over TLS):
For the domain I am testing with I have users under
"ou=users,dc=simonandkate,dc=lan". Users have configured (e.g.):
cn=Simon Wilson
uid=simon
[email protected]
- I want to have users login with email address/password and uid NOT
to work for login
- LDAP database has indexing set across cn, sn, mail, uid, givenName
as required in SOGo instructions
- The config I have works MOST of the time, but occasionally the test
user (me) gets wrong username or password notification and login
fails. Waiting a while it works again at a later stage. Password is
100% correct.
/* Authentication */
SOGoPasswordChangeEnabled = YES;
/* LDAP */
domains = {
simonandkate.net = {
SOGoMailDomain = simonandkate.net;
SOGoUserSources = (
{
type = ldap;
CNFieldName = cn;
IDFieldName = uid;
UIDFieldName = uid;
MailFieldNames = (mail);
baseDN = "ou=users,dc=simonandkate,dc=lan";
bindDN = "cn=horde,ou=accounts,dc=simonandkate,dc=lan";
bindFields = (mail);
IMAPLoginFieldName = uid;
bindPassword = HordePassword;
bindAsCurrentUser = YES;
userPasswordAlgorithm = ssha512;
canAuthenticate = YES;
displayName = "Global Directory";
hostname = "ldap://ldap.simonandkate.lan/????!StartTLS";;
id = public;
isAddressBook = YES;
}
);
};
};
SOGoEnableDomainBasedUID = YES;
I think I'll drop back to straight LDAP uid login for now to rule out
any correlation - I do need to sort out login by email at some point,
but will try without first.
SW
Links:
------
[1] mailto:[email protected]
___________
Simon Wilson
M: 0400 12 11 16
