----- Message from Odhiambo Washington <[email protected]> ---------
Date: Sun, 16 Apr 2023 11:02:25 +0300
From: Odhiambo Washington <[email protected]>
Subject: Re: [SOGo] Logout and errors
To: [email protected]
Cc: [email protected]
On Sun, Apr 16, 2023 at 4:57 AM Simon Wilson <[email protected]> wrote:
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] 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.
--
Simon Wilson
M: 0400 12 11 16
