OX / UCS Authentication against ldap server failed

tafkaz · August 23, 2017, 3:48pm

Hi again there…
Coming from here:

https://help.univention.com/t/update-master-slave-fails/6366/50

We now have the strange problem, that no user is able to login to OX anymore:

2017-08-23T17:46:03,797+0200 INFO  [OXTimer-0000073] com.openexchange.usm.session.tasks.USMSessionCacheCleanupLogInfoTask.run(USMSessionCacheCleanupLogInfoTask.java:78)
0 USM sessions (and 0 by JVM) and 0 SyncStates have been removed from memory cache since the last cleanup task.
^C
root@ucs-slave:~# tail -n 200 /var/log/open-xchange/open-xchange.log.0
 com.openexchange.grizzly.userAgent=Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:55.0) Gecko/20100101 Firefox/55.0
 com.openexchange.login.authId=46ce9bc6a3c743f394e87273a753c5f5
 com.openexchange.login.client=open-xchange-appsuite
 com.openexchange.login.clientIp=10.191.184.118
 com.openexchange.login.login=aljo
 com.openexchange.login.userAgent=Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:55.0) Gecko/20100101 Firefox/55.0
 com.openexchange.login.version=7.8.4-9
 com.openexchange.request.trackingId=1318957517-659478772
javax.naming.AuthenticationException: [LDAP: error code 49 - Invalid Credentials]
        at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3088)
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3034)
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2836)
        at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2750)
        at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:317)
        at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:193)
        at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:211)
        at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:154)
        at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:84)
        at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684)
        at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:307)
        at javax.naming.InitialContext.init(InitialContext.java:242)
        at javax.naming.InitialContext.<init>(InitialContext.java:216)
        at javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:101)
        at com.openexchange.authentication.ucs.impl.UCSAuthentication.handleLoginInfo(UCSAuthentication.java:162)
        at com.openexchange.authentication.service.Authentication.login(Authentication.java:111)
        at com.openexchange.authentication.service.Authentication.login(Authentication.java:98)
        at com.openexchange.login.internal.NormalLoginMethod.doAuthentication(NormalLoginMethod.java:83)
        at com.openexchange.login.internal.LoginPerformer.doLogin(LoginPerformer.java:213)
        at com.openexchange.login.internal.LoginPerformer.doLogin(LoginPerformer.java:155)
        at com.openexchange.login.internal.LoginPerformer.doLogin(LoginPerformer.java:143)
        at com.openexchange.ajax.login.Login$1.doLogin(Login.java:109)
        at com.openexchange.ajax.login.AbstractLoginRequestHandler.loginOperation(AbstractLoginRequestHandler.java:222)
        at com.openexchange.ajax.login.AbstractLoginRequestHandler.loginOperation(AbstractLoginRequestHandler.java:181)
        at com.openexchange.ajax.login.Login.doLogin(Login.java:97)
        at com.openexchange.ajax.login.Login.handleRequest(Login.java:90)
        at com.openexchange.ajax.LoginServlet.doJSONAuth(LoginServlet.java:792)
        at com.openexchange.ajax.LoginServlet.doGet(LoginServlet.java:757)
        at com.openexchange.ajax.LoginServlet.doPost(LoginServlet.java:877)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at com.openexchange.ajax.AJAXServlet.doService(AJAXServlet.java:549)
        at com.openexchange.ajax.LoginServlet.service(LoginServlet.java:737)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:147)
        at com.openexchange.http.grizzly.servletfilter.RequestReportingFilter.doFilter(RequestReportingFilter.java:132)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:137)
        at com.openexchange.http.grizzly.servletfilter.WrappingFilter.doFilter(WrappingFilter.java:204)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:137)
        at com.openexchange.http.grizzly.service.http.OSGiAuthFilter.doFilter(OSGiAuthFilter.java:140)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:137)
        at org.glassfish.grizzly.servlet.FilterChainImpl.invokeFilterChain(FilterChainImpl.java:106)
        at org.glassfish.grizzly.servlet.ServletHandler.doServletService(ServletHandler.java:224)
        at org.glassfish.grizzly.servlet.ServletHandler.service(ServletHandler.java:178)
        at com.openexchange.http.grizzly.service.http.OSGiMainHandler.service(OSGiMainHandler.java:223)
        at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:224)
        at com.openexchange.threadpool.internal.CustomThreadPoolExecutor$MDCProvidingRunnable.run(CustomThreadPoolExecutor.java:2570)
        at com.openexchange.threadpool.internal.CustomThreadPoolExecutor$Worker.runTask(CustomThreadPoolExecutor.java:840)
        at com.openexchange.threadpool.internal.CustomThreadPoolExecutor$Worker.run(CustomThreadPoolExecutor.java:867)
        at java.lang.Thread.run(Thread.java:745)
2017-08-23T17:37:58,347+0200 INFO  [OXWorker-0000072] com.openexchange.login.internal.LoginPerformer.logLoginRequest(LoginPerformer.java:673)
Login:aljo IP:10.191.184.118 AuthID:46ce9bc6a3c743f394e87273a753c5f5 Agent:Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:55.0) Gecko/20100101 Firefox/55.0 Client:open-xchange-appsuite(7.8.4-9) Interface:HTTP_JSON No session created.
 com.openexchange.grizzly.method=POST
 com.openexchange.grizzly.queryString=<none>
 com.openexchange.grizzly.remoteAddress=10.191.184.118
 com.openexchange.grizzly.remotePort=35930
 com.openexchange.grizzly.requestURI=/ajax/login
 com.openexchange.grizzly.serverName=192.168.111.240
 com.openexchange.grizzly.servletPath=/ajax/login
 com.openexchange.grizzly.threadName=OXWorker-0000072
 com.openexchange.grizzly.userAgent=Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:55.0) Gecko/20100101 Firefox/55.0
 com.openexchange.login.authId=46ce9bc6a3c743f394e87273a753c5f5
 com.openexchange.login.client=open-xchange-appsuite
 com.openexchange.login.clientIp=10.191.184.118
 com.openexchange.login.login=aljo
 com.openexchange.login.userAgent=Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:55.0) Gecko/20100101 Firefox/55.0
 com.openexchange.login.version=7.8.4-9
 com.openexchange.request.trackingId=1318957517-659478772
2017-08-23T17:38:13,820+0200 INFO  [OXTimer-0000072] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:39:13,819+0200 INFO  [OXTimer-0000073] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:40:13,820+0200 INFO  [OXTimer-0000022] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:40:58,850+0200 INFO  [OXTimer-0000022] com.openexchange.monitoring.internal.memory.MemoryMonitoring.run(MemoryMonitoring.java:154)

        Garbage collection consumed 0.0% of uptime within 5 minutes. All fine.

2017-08-23T17:41:03,797+0200 INFO  [OXTimer-0000073] com.openexchange.usm.session.tasks.USMSessionCacheCleanupLogInfoTask.run(USMSessionCacheCleanupLogInfoTask.java:78)
0 USM sessions (and 0 by JVM) and 0 SyncStates have been removed from memory cache since the last cleanup task.
2017-08-23T17:41:13,821+0200 INFO  [OXTimer-0000073] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:41:36,824+0200 INFO  [OXWorker-0000072] com.openexchange.authentication.ucs.impl.UCSAuthentication.handleLoginInfo(UCSAuthentication.java:317)
Authentication against ldap server failed
 com.openexchange.grizzly.method=POST
 com.openexchange.grizzly.queryString=client=USM-EAS&version=7.8.4-3-188f7b01799214be39555cb4f9fab9aa8c0363cb-+7084&authId=3542bae3-6454-4d69-a5a5-a1418f3c92c0&clientIP=80.187.106.97
 com.openexchange.grizzly.remoteAddress=127.0.0.1
 com.openexchange.grizzly.remotePort=35994
 com.openexchange.grizzly.requestURI=/ajax/login
 com.openexchange.grizzly.serverName=localhost
 com.openexchange.grizzly.servletPath=/ajax/login
 com.openexchange.grizzly.session=1109396207063481766.APP1
 com.openexchange.grizzly.threadName=OXWorker-0000072
 com.openexchange.grizzly.userAgent=Open-Xchange USM HTTP Client
 com.openexchange.login.authId=3542bae3-6454-4d69-a5a5-a1418f3c92c0
 com.openexchange.login.client=USM-EAS
 com.openexchange.login.clientIp=80.187.106.97
 com.openexchange.login.login=fjbe
 com.openexchange.login.userAgent=Open-Xchange USM HTTP Client
 com.openexchange.login.version=7.8.4-3-188f7b01799214be39555cb4f9fab9aa8c0363cb- 7084
 com.openexchange.request.trackingId=1318957517-659478774
javax.naming.AuthenticationException: [LDAP: error code 49 - Invalid Credentials]
        at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3088)
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3034)
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2836)
        at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2750)
        at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:317)
        at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:193)
        at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:211)
        at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:154)
        at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:84)
        at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684)
        at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:307)
        at javax.naming.InitialContext.init(InitialContext.java:242)
        at javax.naming.InitialContext.<init>(InitialContext.java:216)
        at javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:101)
        at com.openexchange.authentication.ucs.impl.UCSAuthentication.handleLoginInfo(UCSAuthentication.java:162)
        at com.openexchange.authentication.service.Authentication.login(Authentication.java:111)
        at com.openexchange.authentication.service.Authentication.login(Authentication.java:98)
        at com.openexchange.login.internal.NormalLoginMethod.doAuthentication(NormalLoginMethod.java:83)
        at com.openexchange.login.internal.LoginPerformer.doLogin(LoginPerformer.java:213)
        at com.openexchange.login.internal.LoginPerformer.doLogin(LoginPerformer.java:155)
        at com.openexchange.login.internal.LoginPerformer.doLogin(LoginPerformer.java:143)
        at com.openexchange.ajax.login.Login$1.doLogin(Login.java:109)
        at com.openexchange.ajax.login.AbstractLoginRequestHandler.loginOperation(AbstractLoginRequestHandler.java:222)
        at com.openexchange.ajax.login.AbstractLoginRequestHandler.loginOperation(AbstractLoginRequestHandler.java:181)
        at com.openexchange.ajax.login.Login.doLogin(Login.java:97)
        at com.openexchange.ajax.login.Login.handleRequest(Login.java:90)
        at com.openexchange.ajax.LoginServlet.doJSONAuth(LoginServlet.java:792)
        at com.openexchange.ajax.LoginServlet.doGet(LoginServlet.java:757)
        at com.openexchange.ajax.LoginServlet.doPost(LoginServlet.java:877)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at com.openexchange.ajax.AJAXServlet.doService(AJAXServlet.java:549)
        at com.openexchange.ajax.LoginServlet.service(LoginServlet.java:737)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:147)
        at com.openexchange.http.grizzly.servletfilter.RequestReportingFilter.doFilter(RequestReportingFilter.java:132)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:137)
        at com.openexchange.http.grizzly.servletfilter.WrappingFilter.doFilter(WrappingFilter.java:204)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:137)
        at com.openexchange.http.grizzly.service.http.OSGiAuthFilter.doFilter(OSGiAuthFilter.java:140)
        at org.glassfish.grizzly.servlet.FilterChainImpl.doFilter(FilterChainImpl.java:137)
        at org.glassfish.grizzly.servlet.FilterChainImpl.invokeFilterChain(FilterChainImpl.java:106)
        at org.glassfish.grizzly.servlet.ServletHandler.doServletService(ServletHandler.java:224)
        at org.glassfish.grizzly.servlet.ServletHandler.service(ServletHandler.java:178)
        at com.openexchange.http.grizzly.service.http.OSGiMainHandler.service(OSGiMainHandler.java:223)
        at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:224)
        at com.openexchange.threadpool.internal.CustomThreadPoolExecutor$MDCProvidingRunnable.run(CustomThreadPoolExecutor.java:2570)
        at com.openexchange.threadpool.internal.CustomThreadPoolExecutor$Worker.runTask(CustomThreadPoolExecutor.java:840)
        at com.openexchange.threadpool.internal.CustomThreadPoolExecutor$Worker.run(CustomThreadPoolExecutor.java:867)
        at java.lang.Thread.run(Thread.java:745)
2017-08-23T17:41:36,825+0200 INFO  [OXWorker-0000072] com.openexchange.login.internal.LoginPerformer.logLoginRequest(LoginPerformer.java:673)
Login:fjbe IP:80.187.106.97 AuthID:3542bae3-6454-4d69-a5a5-a1418f3c92c0 Agent:Open-Xchange USM HTTP Client Client:USM-EAS(7.8.4-3-188f7b01799214be39555cb4f9fab9aa8c0363cb- 7084) Interface:HTTP_JSON No session created.
 com.openexchange.grizzly.method=POST
 com.openexchange.grizzly.queryString=client=USM-EAS&version=7.8.4-3-188f7b01799214be39555cb4f9fab9aa8c0363cb-+7084&authId=3542bae3-6454-4d69-a5a5-a1418f3c92c0&clientIP=80.187.106.97
 com.openexchange.grizzly.remoteAddress=127.0.0.1
 com.openexchange.grizzly.remotePort=35994
 com.openexchange.grizzly.requestURI=/ajax/login
 com.openexchange.grizzly.serverName=localhost
 com.openexchange.grizzly.servletPath=/ajax/login
 com.openexchange.grizzly.session=1109396207063481766.APP1
 com.openexchange.grizzly.threadName=OXWorker-0000072
 com.openexchange.grizzly.userAgent=Open-Xchange USM HTTP Client
 com.openexchange.login.authId=3542bae3-6454-4d69-a5a5-a1418f3c92c0
 com.openexchange.login.client=USM-EAS
 com.openexchange.login.clientIp=80.187.106.97
 com.openexchange.login.login=fjbe
 com.openexchange.login.userAgent=Open-Xchange USM HTTP Client
 com.openexchange.login.version=7.8.4-3-188f7b01799214be39555cb4f9fab9aa8c0363cb- 7084
 com.openexchange.request.trackingId=1318957517-659478774
2017-08-23T17:42:13,828+0200 INFO  [OXTimer-0000022] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:43:13,828+0200 INFO  [OXTimer-0000022] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:44:13,823+0200 INFO  [OXTimer-0000073] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:45:13,819+0200 INFO  [OXTimer-0000022] com.openexchange.usm.session.tasks.USMSessionCleanupTask.run(USMSessionCleanupTask.java:110)
Checked for old USM sessions, 0 were removed
 com.openexchange.database.schema=localhost_5
2017-08-23T17:45:58,849+0200 INFO  [OXTimer-0000072] com.openexchange.monitoring.internal.memory.MemoryMonitoring.run(MemoryMonitoring.java:154)

here’s the join.log:
join.log (1.6 MB)

All join scripts have been run … successfully…again,…
This is really odd now…
Any idea how to resolve this quickly?
thanks
Sascha

Moritz_Bunkus · August 24, 2017, 6:35am

Hey,

looks like the authentication data used for binding to the LDAP server for the initial search for the user account is wrong. Normally OX uses the server’s machine account for this. Please verify the following two settings in the file /opt/open-xchange/etc/authplugin.properties:

com.openexchange.authentication.ucs.bindDn — this should contain the DN of current server’s LDAP object (it should equal the output of ucr get ldap/hostdn)
com.openexchange.authentication.ucs.bindPassword — the corresponding password. It should be the same as the content of /etc/machine.secret

Kind regards,
mosu

tafkaz · August 24, 2017, 7:15am

Hi Moritz,

yup…wrong Password…
Ox Login works again…you’re the man!

What strikes me though is that we have
ox/cfg/authplugin.properties/com.openexchange.authentication.ucs.bindPassword
@&@/etc/machine.secret@&@
and still the password in /opt/open-xchange/etc/authplugin.properties was not the one in /etc/machine.secret.
How the hell can this happen?
We defo did not change any of these parameters manually.
cheers and thanks again
Sascha

tafkaz · August 24, 2017, 2:48pm

ok…password is changed everytime we rejoin the slave…
Just did a univention-join on the OX Slave, and /etc/machine.secret is a new one…
However the value inside /opt/open-xchange/etc/authplugin.properties is still the old one.
Damn…what is happening here?

best
Sascha

tafkaz · August 24, 2017, 3:11pm

also one user can’t use EAS with his device…
2017-08-24T17:10:08,125+0200 INFO [OXWorker-0000097] com.openexchange.usm.eas.servlet.EASServlet.handleRequest(EASServlet.java:411)
haki: EAS access disabled for user
Allthough i checked that in the User settings on the master (and rechecked…)
Seems like OX doesn’t get all these changes…

Gohmann · August 25, 2017, 5:54am

I would check the listener logfile: /var/log/univention/listener.log. Maybe you have to increase the listener log level to 4 (ucr set listener/debug/level=4).

Moritz_Bunkus · August 25, 2017, 6:43am

Hey,

That is normal and expected. During the join process a new computer account is created (any old, existing ones will be deleted automatically before that), and new account means new password.

It’s quite possible that this is a bug in the OX packages. The OX packages do include a script that’s triggered whenever the server password changes, and that script does set the corresponding UCR variable (which in turn should rewrite the file /opt/open-xchange/etc/authplugin.properties automatically. I don’t know why that isn’t the case.

If you run into this again, please check the following three values:

The content of /etc/machine.secret
The value of ucr get ox/cfg/authplugin.properties/com.openexchange.authentication.ucs.bindPassword
The value of com.openexchange.authentication.ucs.bindPassword in /opt/open-xchange/etc/authplugin.properties

If 1 and 2 match but 3 doesn’t, then running ucr commit /opt/open-xchange/etc/authplugin.properties should fix this. You’ll have to reload the OX configuration after changing that file, BTW, either by restarting the service or by running /opt/open-xchange/sbin/reloadconfiguration.

Please verify that the Directory Listener mechanism is up to date on the slave. Check that these two values match:

On the slave server: the content of /var/lib/univention-directory-listener/notifier_id
On the DC Master: the first number in the last line of /var/lib/univention-ldap/notify/transaction

If they don’t, then checking the listener.log file as suggested by @Gohmann is a good idea.

Kind regards,
mosu

tafkaz · August 25, 2017, 9:22am

Hi Moritz,

root@ucs-slave:~# cat /var/lib/univention-directory-listener/notifier_id
6153

tail /var/lib/univention-ldap/notify/transaction
[...]
6153 uid=haki,cn=foo-bar-User,cn=users,dc=foo-bar,dc=de m

looks good to me…really strange…

tafkaz · August 25, 2017, 9:32am

ok…found someting in the listener.logs, when changing some users attribute (ox-mobility “off”)

in the slaves log:

25.08.17 11:29:50.049  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=foo-User,cn=users,dc=bar-foo,dc=de' command m
25.08.17 11:29:50.066  LISTENER    ( WARN    ) : replication: Can't contact LDAP server: retrying

in the masters log:
25.08.17 11:29:50.049  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=foo-User,cn=users,dc=bar-foo,dc=de'

Hope you would have an idea now?
thanks
Sascha

tafkaz · August 28, 2017, 12:44pm

noone has an idea?
What could be the problem with contacting the ldap server?
join works perfectly…

thanks
Sascha

Gohmann · August 29, 2017, 3:46am

I would increase the debug level of the listener and try it again. The message ‘replication: Can’t contact LDAP server: retrying’ is only a warning and can be ignored.

tafkaz · August 29, 2017, 12:58pm

Hi,
ok increased it to 4 with ucr set listener/debug/level=4
then changed the User on the master (5 changes, saved settings after each edition), and this is what i get:

29.08.17 14:54:28.674  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=bar-User,cn=users,dc=foo-bar,dc=de' command m
29.08.17 14:55:22.253  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=bar-User,cn=users,dc=foo-bar,dc=de' command m
29.08.17 14:55:40.249  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=bar-User,cn=users,dc=foo-bar,dc=de' command m
29.08.17 14:55:51.242  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=bar-User,cn=users,dc=foo-bar,dc=de' command m
29.08.17 14:55:59.641  LISTENER    ( PROCESS ) : updating 'uid=haki,cn=bar-User,cn=users,dc=foo-bar,dc=de' command m

looks great to me, not?

However i have found this in the listener.log showing problems we seemed to have yesterday morning…
Of course we haven’t been doing anything manually at this time of day, so i guess that some automatic script was called?

28.08.17 06:25:10.769  DEBUG_INIT
28.08.17 06:25:10.788  LISTENER    ( ERROR   ) : failed to connect to any notifier
28.08.17 06:25:10.789  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
28.08.17 06:25:40.789  LISTENER    ( WARN    ) : chosen server: ucs-master.foo-bar.de:7389
28.08.17 06:25:41.589  LISTENER    ( WARN    ) : ox-user(OXUserIdCache): rebuilding cache...
28.08.17 06:25:41.589  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ox-user.py failed
Traceback (most recent call last):
  File "/usr/lib/univention-directory-listener/system/ox-user.py", line 167, in <module>
    _ox_user_id_cache.rebuild_cache(raise_exceptions=False)
  File "/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py", line 118, in rebuild_cache
    self.__clear_database()
  File "/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py", line 107, in __clear_database
    self.cursor.execute('DELETE FROM user_id_cache')
sqlite3.OperationalError: attempt to write a readonly database
28.08.17 06:25:41.589  LISTENER    ( ERROR   ) : import of filename=/usr/lib/univention-directory-listener/system/ox-user.py failed in module_import()
UNIVENTION_DEBUG_BEGIN  : uldap.__open host=ucs-master.foo-bar.de port=7389 base=dc=foo-bar,dc=de
UNIVENTION_DEBUG_END    : uldap.__open host=ucs-master.foo-bar.de port=7389 base=dc=foo-bar,dc=de

Moritz_Bunkus · August 29, 2017, 2:12pm

I’m somewhat surprised to see this error. On my rather new OX installation that file (listener_tools.py) exists, but it doesn’t contain the code shown in your log. Grepping recursively for __clear_database in /usr/lib/pymodules shows no hit at all. I’m therefore guessing that you still have old code lying around for some reason.

Unfortunately I’m not really used to how Python modules are installed on the system. The package univention-ox contains the file /usr/share/pyshared/univention/ox/listener_tools.py, and I guess that from that file the files for the different Python versions are created — including the aforementioned /usr/lib/pymodules/python2.7/univention/ox/listener_tools.py. Looking at the .postinst file for univention-ox reveals that the command update-python-modules is used.

So please execute the following:

update-python-modules  univention-ox.public univention-ox.private
grep -r __clear_database /usr/lib/pymodules
service univention-directory-listener restart
univention-directory-listener-ctrl  resync ox-user

The commands are their meaning are:

This should regenerate /usr/lib/pymodules/python2.7/univention/ox/listener_tools.py from /usr/share/pyshared/univention/ox/listener_tools.py.
The second command is just to make sure that the file is indeed updated and that the old code __clear_database isn’t present anymore. It should not output anything.
This one restarts the Directory Listener so that it’ll use the new code.
This tells the Directory Listener to treat the ox-user module as if it had just been installed.

Then observer the listener.log file again.

damrose · August 29, 2017, 2:26pm

Hi,

the code that causes the sqlite3.OperationalError error was introduced in the latest OX app update, thats why you may not see it on your system @Moritz_Bunkus. We introduced an sqlite cache for the userids and contexts, to speed up processing group changes in large environments. The cache will be updated every time the listener is restarted and kept up to date by the listener while running.

@tafkaz: It seems the cache file has wrong file permissions, thats why the error occurs. I would remove the cache file completely, and then restart the univention-directory-listener. This will recreate the cache file with correct permissions.

tafkaz · August 29, 2017, 2:29pm

hi!
so what would you suppose to do?
Just do what damrose implies or go on with Moritz commands as well?
Thanks for your great help!

tafkaz · August 29, 2017, 2:35pm

root@ucs-slave:~# update-python-modules univention-ox.public univention-ox.private
root@ucs-slave:~# grep -r __clear_database /usr/lib/pymodules
Übereinstimmungen in Binärdatei /usr/lib/pymodules/python2.7/univention/ox/listener_tools.pyc.

damrose · August 29, 2017, 2:36pm

Sorry, i meant to write the filename, but forgot it. It is /var/cache/univention-ox/ox-user-id-cache.db. Before deleting it, please check and post the permissions with ls -l /var/cache/univention-ox/ox-user-id-cache.db, although we may not find out how it was changed.

tafkaz · August 29, 2017, 2:39pm

ls -l /var/cache/univention-ox/ox-user-id-cache.db
-rw-r–r-- 1 root nogroup 4096 Aug 19 13:33 /var/cache/univention-ox/ox-user-id-cache.db

mv /var/cache/univention-ox/ox-user-id-cache.db /root/

univention-directory-listener
29.08.17 16:40:25.287 DEBUG_INIT
29.08.17 16:40:25.287 LISTENER ( ERROR ) : Could not get lock for database [/var/lib/univention-directory-listener/cache.lock]; Is another listener processs running?

Moritz_Bunkus · August 29, 2017, 2:44pm

@damrose Ah, thanks for the explanation.

@tafakz You cannot restart the listener simply by executing univention-directory-listener. Instead, run service univention-directory-listener restart

tafkaz · August 29, 2017, 2:46pm

yup…sorry, my bad!

root@ucs-slave:~# service univention-directory-listener restart
root@ucs-slave:~# ls -l /var/cache/univention-ox/ox-user-id-cache.db
-rw-r--r-- 1 listener nogroup 4096 Aug 29 16:45 /var/cache/univention-ox/ox-user-id-cache.db

Well…looks pretty much the same to me…