OX / UCS Authentication against ldap server failed

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…

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).

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:

  1. The content of /etc/machine.secret
  2. The value of ucr get ox/cfg/authplugin.properties/com.openexchange.authentication.ucs.bindPassword
  3. 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:

  1. On the slave server: the content of /var/lib/univention-directory-listener/notifier_id
  2. 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

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…

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

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

thanks
Sascha

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.

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

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:

  1. This should regenerate /usr/lib/pymodules/python2.7/univention/ox/listener_tools.py from /usr/share/pyshared/univention/ox/listener_tools.py.
  2. 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.
  3. This one restarts the Directory Listener so that it’ll use the new code.
  4. 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.

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.

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!

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.

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.

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?

@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

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…

The file is now owned and therefore writeable by the listener, it was owned by the root user before. The sqlite3.OperationalError: attempt to write a readonly database error from the listener log should not occur anymore after you restarted the service, is that correct?

You should now probably follow the advice from my colleague and retry to do changes with the high listener debug level OX / UCS Authentication against ldap server failed

Hi,
sorry for reopening here, but unfortunately i have experienced the same issue again now.
I understood, that a rejoin will result in a new machine.secret file.
But does anyone have an idea why, although ucr get ox/cfg/authplugin.properties/com.openexchange.authentication.ucs.bindPassword shows the (i think) correct value
@&@/etc/machine.secret@&@
Even after ucr commit /opt/open-xchange/etc/authplugin.properties the file /opt/open-xchange/etc/authplugin.properties would still show the old value and therefore a login will not work until i set that new machine.secret pw manually?

Thanks
Sascha

1 Like

You can resolve the machine.secret problem by executing
commit-ox-ucr-variables
followed by:
service open-xchange restart
to write the open-xchange config set by the UCR.

Alternativly you can trigger the password rotation via:
/usr/lib/univention-server/server_password_change.d/univention-ox postchange
This is also going to reload the ox service.

This can be found in our knowledge base article 13747

Hi Dirk,

good to hear, thanks a lot for your explanations.

Best
Sascha