Upgrade to UCS 4.4 failing join script for Radius and Appcenter

sccmrb · April 21, 2019, 5:51am

Had to run Join scripts immediately after upgrade to 4.4 from 4.3. I am getting the following errors below on the appcenter and radius join scripts.

RUNNING 30univention-appcenter.inst
2019-04-20 23:29:40.566672017-06:00 (in joinscript_init)
Object exists: cn=apps,cn=univention,dc=skaggscatholiccenter,dc=org
Object exists: cn=ldapschema,cn=univention,dc=skaggscatholiccenter,dc=org
INFO: No change of core data of object univention-app.
Object exists: cn=ldapacl,cn=univention,dc=skaggscatholiccenter,dc=org
INFO: No change of core data of object 66univention-appcenter_app.
Object exists: cn=udm_syntax,cn=univention,dc=skaggscatholiccenter,dc=org
INFO: No change of core data of object app_syntax.
Object exists: cn=udm_module,cn=univention,dc=skaggscatholiccenter,dc=org
INFO: No change of core data of object appcenter/app.
No modification: cn=univention-app,cn=ldapschema,cn=univention,dc=skaggscatholiccenter,dc=org

No modification: cn=66univention-appcenter_app,cn=ldapacl,cn=univention,dc=skaggscatholiccenter,dc=org

No modification: cn=app_syntax,cn=udm_syntax,cn=univention,dc=skaggscatholiccenter,dc=org

No modification: cn=appcenter/app,cn=udm_module,cn=univention,dc=skaggscatholiccenter,dc=org

Waiting for activation of the extension object univention-app: OK
Waiting for activation of the extension object 66univention-appcenter_app: OK
Waiting for activation of the extension object app_syntax:........................................................ERROR: Master did not mark the extension object active within 180 seconds.
ERROR
ucs_registerLDAPExtension: registraton of /usr/share/univention-appcenter/app_syntax.py failed.

EXITCODE=1
cadb298d-3454-46df-8587-3a64de9e6f67

AND

RUNNING 80univention-radius.inst
2019-04-20 23:32:43.769189977-06:00 (in joinscript_init)
Object exists: cn=services,cn=univention,dc=skaggscatholiccenter,dc=org
Object exists: cn=RADIUS,cn=services,cn=univention,dc=skaggscatholiccenter,dc=org
WARNING: cannot append RADIUS to service, value exists
No modification: cn=ad,cn=dc,cn=computers,dc=skaggscatholiccenter,dc=org
Generating DH parameters, 1024 bit long safe prime, generator 2
This is going to take a long time
.......................................................................................+.......+........................................+....................................+...+...............................................................+...................................................................................................................................................................................................................+.................................+.......++*++*++*++*++*
unable to write 'random state'
Object exists: cn=ldapschema,cn=univention,dc=skaggscatholiccenter,dc=org
INFO: No change of core data of object networkaccess.
Object exists: cn=ldapacl,cn=univention,dc=skaggscatholiccenter,dc=org
INFO: No change of core data of object 59univention-radius.
INFO: No change of core data of object 66univention-radius.
No modification: cn=networkaccess,cn=ldapschema,cn=univention,dc=skaggscatholiccenter,dc=org

No modification: cn=59univention-radius,cn=ldapacl,cn=univention,dc=skaggscatholiccenter,dc=org

No modification: cn=66univention-radius,cn=ldapacl,cn=univention,dc=skaggscatholiccenter,dc=org

Waiting for activation of the extension object networkaccess:........................................................ERROR: Master did not mark the extension object active within 180 seconds.
ERROR
ucs_registerLDAPExtension: registraton of /usr/share/univention-radius/networkaccess.schema failed.
EXITCODE=1
b25a725a-6bba-49f4-804f-8572f9c3a294

sccmrb · April 22, 2019, 5:58pm

I followed the thread Problem after Update to 4.4 Join-Script for Appcenter fails But deleting app_syntax and letting it recreate the object is not working.

I got down to checking the listener and had this:

# univention-directory-listener-ctrl status
Listener status:
 run: univention-directory-listener: (pid 16049) 5803s, normally down

Error: [Errno 111] Connection refused
Current Notifier ID on "ad.skaggscatholiccenter.org"
 

/usr/sbin/univention-directory-listener-ctrl: line 100: [: : integer expression expected
Last Notifier ID processed by local Listener:
 27230362

Last transaction processed:
 27301727 dc=skaggscatholiccenter,dc=org m

Modules:
0	app_attributes	/usr/lib/univention-directory-listener/system/app_attributes.py
3	bind	/usr/lib/univention-directory-listener/system/bind.py
3	faillog	/usr/lib/univention-directory-listener/system/faillog.py
3	gencertificate	/usr/lib/univention-directory-listener/system/gencertificate.py
3	google-apps-group	/usr/lib/univention-directory-listener/system/google-apps-group.py
3	google-apps-user	/usr/lib/univention-directory-listener/system/google-apps-user.py
3	hosteddomains	/usr/lib/univention-directory-listener/system/hosteddomains.py
3	keytab-member	/usr/lib/univention-directory-listener/system/keytab-member.py
3	keytab	/usr/lib/univention-directory-listener/system/keytab.py
3	ldap_extension	/usr/lib/univention-directory-listener/system/ldap_extension.py
3	ldap_server	/usr/lib/univention-directory-listener/system/ldap_server.py
0	license_uuid	/usr/lib/univention-directory-listener/system/license_uuid.py
3	nagios-client	/usr/lib/univention-directory-listener/system/nagios-client.py
3	nfs-homes	/usr/lib/univention-directory-listener/system/nfs-homes.py
3	nfs-shares	/usr/lib/univention-directory-listener/system/nfs-shares.py
3	nscd_update	/usr/lib/univention-directory-listener/system/nscd.py
3	nss	/usr/lib/univention-directory-listener/system/nss.py
3	pkgdb	/usr/lib/univention-directory-listener/system/pkgdb.py
3	pkgdb-watch	/usr/lib/univention-directory-listener/system/pkgdb-watch.py
0	portal_groups	/usr/lib/univention-directory-listener/system/portal_groups.py
0	portal_server	/usr/lib/univention-directory-listener/system/portal_server.py
3	prometheus-targets	/usr/lib/univention-directory-listener/system/prometheus-targets.py
3	quota	/usr/lib/univention-directory-listener/system/quota.py
3	s4-connector	/usr/lib/univention-directory-listener/system/s4-connector.py
3	samba4-idmap	/usr/lib/univention-directory-listener/system/samba4-idmap.py
3	samba-shares	/usr/lib/univention-directory-listener/system/samba-shares.py
3	udm_extension	/usr/lib/univention-directory-listener/system/udm_extension.py
3	umc-service-providers	/usr/lib/univention-directory-listener/system/umc-service-providers.py
0	univention-admin-diary-backend	/usr/lib/univention-directory-listener/system/univention-admin-diary-backend.py
0		/usr/lib/univention-directory-listener/system/univention-radius.py
3	univention-saml-idp-config	/usr/lib/univention-directory-listener/system/univention-saml-idp-config.py
3	univention-saml-servers	/usr/lib/univention-directory-listener/system/univention-saml-servers.py
3	univention-saml-simplesamlphp-configuration	/usr/lib/univention-directory-listener/system/univention-saml-simplesamlphp-configuration.py
3	well-known-sid-name-mapping	/usr/lib/univention-directory-listener/system/well-known-sid-name-mapping.py

I don’t know why on the domain master it would say the connection is refused. I couldn’t find out how to resolve this specifically, it was mentioned in the thread that I should reset the listener cache in the “solution” Troubleshooting: Listener-/Notifier

But that has only made things worse and it wants me to rejoin my member servers which isn’t working either and yes it can look up the domainmaster in DNS. Requirements for a successful join into the UCS domain

HELP! (please)

sccmrb · April 22, 2019, 6:00pm

My notifier log is growing out of control too. Over the course of a day it filled up 20% of my hard drive.

sccmrb · April 22, 2019, 10:42pm

This error from the /var/log/univention/notifier.log is repeating over and over and over:

2019-04-22 17:39:14,629:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object
2019-04-22 17:39:14,731:ERROR:ldap_add(Transaction(tid=27230362, dn='dc=skaggscatholiccenter,dc=org', command='m')): Already exists
2019-04-22 17:39:14,731:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}
2019-04-22 17:39:20,128:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object
2019-04-22 17:39:20,228:ERROR:ldap_add(Transaction(tid=27230362, dn='dc=skaggscatholiccenter,dc=org', command='m')): Already exists
2019-04-22 17:39:20,228:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}
2019-04-22 17:39:25,613:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object
2019-04-22 17:39:25,694:ERROR:ldap_add(Transaction(tid=27230362, dn='dc=skaggscatholiccenter,dc=org', command='m')): Already exists
2019-04-22 17:39:25,694:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}

Christian_Voelker · April 23, 2019, 3:01pm

Hi,

do you have the last mentioned issues (notifier.log) on your master server?

Or are they shown on your member?

/CV

sccmrb · April 23, 2019, 3:18pm

Yes that was from the master server.

sccmrb · April 23, 2019, 3:45pm

From /var/lib/univention-ldap/notify/transaction I see this.

27301721 dc=skaggscatholiccenter,dc=org m
27301722 dc=skaggscatholiccenter,dc=org m
27301723 dc=skaggscatholiccenter,dc=org m
27301724 dc=skaggscatholiccenter,dc=org m
27301725 dc=skaggscatholiccenter,dc=org m
27301726 dc=skaggscatholiccenter,dc=org m
27301727 dc=skaggscatholiccenter,dc=org m

Christian_Voelker · April 23, 2019, 4:53pm

Ok, on the master is it.
You need to make sure your listener starts. Check this article.

If you do not get it up and running post the error lost as described in the article.

/CV

sccmrb · April 23, 2019, 7:37pm

Listener state is run but it’s log is showing this:

I also noticed it’s bind dn is cn=admin instead of cn=administrator

23.04.19 13:55:58.115  LISTENER    ( WARN    ) : Notifier/LDAP server is ad.skaggscatholiccenter.org:7389
23.04.19 13:55:58.115  LDAP        ( PROCESS ) : connecting to ldap://ad.skaggscatholiccenter.org:7389
23.04.19 13:55:58.119  LDAP        ( INFO    ) : simple_bind as cn=admin,dc=skaggscatholiccenter,dc=org
23.04.19 13:55:58.120  LISTENER    ( INFO    ) : connecting to notifier ad.skaggscatholiccenter.org:6669
23.04.19 13:55:58.120  LISTENER    ( INFO    ) : connection to 172.16.0.9 failed with errorcode 111: Connection refused
23.04.19 13:55:58.120  LISTENER    ( ERROR   ) : failed to connect to any notifier
23.04.19 13:55:58.120  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
23.04.19 13:56:28.120  LISTENER    ( WARN    ) : Notifier/LDAP server is ad.skaggscatholiccenter.org:7389
23.04.19 13:56:28.120  LDAP        ( PROCESS ) : connecting to ldap://ad.skaggscatholiccenter.org:7389
23.04.19 13:56:28.124  LDAP        ( INFO    ) : simple_bind as cn=admin,dc=skaggscatholiccenter,dc=org
23.04.19 13:56:28.124  LISTENER    ( INFO    ) : connecting to notifier ad.skaggscatholiccenter.org:6669
23.04.19 13:56:28.124  LISTENER    ( INFO    ) : connection to 172.16.0.9 failed with errorcode 111: Connection refused
23.04.19 13:56:28.124  LISTENER    ( ERROR   ) : failed to connect to any notifier
23.04.19 13:56:28.124  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds

The Notifier state is finish and it’s log is showing this:

2019-04-23 13:32:38,518:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}
2019-04-23 13:32:43,863:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object
2019-04-23 13:32:43,945:ERROR:ldap_add(Transaction(tid=27230362, dn='dc=skaggscatholiccenter,dc=org', command='m')): Already exists
2019-04-23 13:32:43,946:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}
2019-04-23 13:32:49,196:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object
2019-04-23 13:32:49,252:ERROR:ldap_add(Transaction(tid=27230362, dn='dc=skaggscatholiccenter,dc=org', command='m')): Already exists
2019-04-23 13:32:49,252:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}
2019-04-23 13:32:54,495:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object
2019-04-23 13:32:54,552:ERROR:ldap_add(Transaction(tid=27230362, dn='dc=skaggscatholiccenter,dc=org', command='m')): Already exists
2019-04-23 13:32:54,552:CRITICAL:ldap_add(Transaction(tid=27230363, dn='dc=skaggscatholiccenter,dc=org', command='m')): {'info': 'txn_commit failed', 'desc': 'Other (e.g., implementation specific) error'}
2019-04-23 13:32:59,891:CRITICAL:ldap_search(reqSession=27301727,cn=translog): No such object

The notifier will not stay running. Yes, I set the debug level per the article you linked.

Christian_Voelker · April 24, 2019, 5:04am

Hi,
so your issue is with the notifier.
The log you posted is not where the notifier tries to start. When you attempt to start with systemctl start univention-directory-notifier you will see a line as shown with the current time stamp of the start command:

11.04.19 09:02:06.194  DEBUG_INIT

Post the output starting from there.

/CV

sccmrb · April 24, 2019, 1:54pm

Christian, I searched the log file and it does not contain “DEBUG”. I moved the log file so it would create a new one and repeated the procedure and it does not contain debug at all. It is still exactly as I posted above.

# ucr set notifier/debug/level=4
Setting notifier/debug/level
File: /etc/runit/univention-directory-notifier/run
# systemctl start univention-directory-notifier
# tail -f /var/log/univention/notifier.log

Christian_Voelker · April 24, 2019, 2:34pm

Hi,

this is strange.
Is it running, but stalled?

ps ax | grep notifier
killall univention-directory-notifier
killall -9 univention-directory-notifier

Is it enabled?

ucr get notifier/autostart
systemctl enable univention-directory-notifier
systemctl start univention-directory-notifier

Still no success? Start it manually:
/usr/sbin/univention-directory-notifier -o -d 4 -v 2 -F

Now any useable output?

Is your /-disk full?

df -h

/CV

sccmrb · April 24, 2019, 2:48pm

#ps ax | grep notifier
  627 ?        Ss     0:21 runsv univention-directory-notifier
30535 pts/0    S+     0:00 grep notifier

# killall univention-directory-notifier
univention-directory-notifier: no process found

# killall -9 univention-directory-notifier
univention-directory-notifier: no process found

# ucr get notifier/autostart
yes

# systemctl enable univention-directory-notifier
univention-directory-notifier.service is not a native service, redirecting to systemd-sysv-install.
Executing: /lib/systemd/systemd-sysv-install enable univention-directory-notifier

# systemctl start univention-directory-notifier
#

No my disk is only 23% used

# df -h
Filesystem               Size  Used Avail Use% Mounted on
udev                      10M     0   10M   0% /dev
tmpfs                    1.6G   18M  1.6G   2% /run
/dev/mapper/vg_ucs-root  101G   22G   74G  23% /
tmpfs                    3.9G  4.0K  3.9G   1% /dev/shm
tmpfs                    5.0M     0  5.0M   0% /run/lock
tmpfs                    3.9G     0  3.9G   0% /sys/fs/cgroup
/dev/sda1                472M  160M  289M  36% /boot
overlay                  101G   22G   74G  23% /var/lib/docker/overlay/5f8da78642e9b01a402fae6e7c180ecba2ffc186461688b891f670724cd627ce/merged
overlay                  101G   22G   74G  23% /var/lib/docker/overlay/226f123eb0b19215472697a2eab671ce645ad3ef439d632ff1d996da3df01837/merged
shm                       64M     0   64M   0% /var/lib/docker/containers/d2cad879bbef2b2aa93d4283c318c95207327a5ea10abb10ea10a8037e0f1165/shm
shm                       64M     0   64M   0% /var/lib/docker/containers/7c68103d3bcc556f8efe8c0d2bf7e442e4447e9078d1d01306207ae44950d11b/shm
tmpfs                    796M     0  796M   0% /run/user/0

And I just searched the notifier/log for DEBUG and it’s still not there.

Christian_Voelker · April 24, 2019, 2:52pm

You have not tried to start it manually as requested:

/usr/sbin/univention-directory-notifier -o -d 4 -v 2 -F

sccmrb · April 24, 2019, 2:56pm

Sorry missed that.

# /usr/sbin/univention-directory-notifier -o -d 4 -v 2 -F
Aborted

Christian_Voelker · April 24, 2019, 6:06pm

Strange!

Do you see any hints when starting it with strace?

/CV

sccmrb · April 24, 2019, 6:58pm

This is the output of strace

# strace /usr/sbin/univention-directory-notifier
execve("/usr/sbin/univention-directory-notifier", ["/usr/sbin/univention-directory-n"...], [/* 18 vars */]) = 0
brk(NULL)                               = 0x56434b52e000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=49456, ...}) = 0
mmap(NULL, 49456, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6bd72a5000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/x86_64-linux-gnu/libuniventiondebug.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=10424, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6bd72a3000
mmap(NULL, 2105528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd6e8c000
mprotect(0x7f6bd6e8e000, 2093056, PROT_NONE) = 0
mmap(0x7f6bd708d000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7f6bd708d000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0Pa\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=135440, ...}) = 0
mmap(NULL, 2212936, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd6c6f000
mprotect(0x7f6bd6c87000, 2093056, PROT_NONE) = 0
mmap(0x7f6bd6e86000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7f6bd6e86000
mmap(0x7f6bd6e88000, 13384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6bd6e88000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20\354\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=327088, ...}) = 0
mmap(NULL, 2431720, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd6a1d000
mprotect(0x7f6bd6a6a000, 2097152, PROT_NONE) = 0
mmap(0x7f6bd6c6a000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4d000) = 0x7f6bd6c6a000
mmap(0x7f6bd6c6d000, 6888, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6bd6c6d000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\4\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1689360, ...}) = 0
mmap(NULL, 3795296, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd667e000
mprotect(0x7f6bd6813000, 2097152, PROT_NONE) = 0
mmap(0x7f6bd6a13000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x195000) = 0x7f6bd6a13000
mmap(0x7f6bd6a19000, 14688, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6bd6a19000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/x86_64-linux-gnu/liblber-2.4.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3001\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=59576, ...}) = 0
mmap(NULL, 2154920, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd646f000
mprotect(0x7f6bd647c000, 2097152, PROT_NONE) = 0
mmap(0x7f6bd667c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xd000) = 0x7f6bd667c000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libresolv.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p9\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=84848, ...}) = 0
mmap(NULL, 2189896, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd6258000
mprotect(0x7f6bd626c000, 2093056, PROT_NONE) = 0
mmap(0x7f6bd646b000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13000) = 0x7f6bd646b000
mmap(0x7f6bd646d000, 6728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6bd646d000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/x86_64-linux-gnu/libsasl2.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360-\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=109296, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6bd72a1000
mmap(NULL, 2204648, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd603d000
mprotect(0x7f6bd6057000, 2093056, PROT_NONE) = 0
mmap(0x7f6bd6256000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19000) = 0x7f6bd6256000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/x86_64-linux-gnu/libssl.so.1.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\212\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=442984, ...}) = 0
mmap(NULL, 2538440, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd5dd1000
mprotect(0x7f6bd5e34000, 2093056, PROT_NONE) = 0
mmap(0x7f6bd6033000, 40960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x62000) = 0x7f6bd6033000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/x86_64-linux-gnu/libcrypto.so.1.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\360\7\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=2711616, ...}) = 0
mmap(NULL, 4820864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd5938000
mprotect(0x7f6bd5ba2000, 2097152, PROT_NONE) = 0
mmap(0x7f6bd5da2000, 180224, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26a000) = 0x7f6bd5da2000
mmap(0x7f6bd5dce000, 12160, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6bd5dce000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200\r\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=14640, ...}) = 0
mmap(NULL, 2109680, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6bd5734000
mprotect(0x7f6bd5737000, 2093056, PROT_NONE) = 0
mmap(0x7f6bd5936000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f6bd5936000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6bd729f000
arch_prctl(ARCH_SET_FS, 0x7f6bd72a0140) = 0
mprotect(0x7f6bd6a13000, 16384, PROT_READ) = 0
mprotect(0x7f6bd5936000, 4096, PROT_READ) = 0
mprotect(0x7f6bd6e86000, 4096, PROT_READ) = 0
mprotect(0x7f6bd5da2000, 122880, PROT_READ) = 0
mprotect(0x7f6bd6033000, 16384, PROT_READ) = 0
mprotect(0x7f6bd646b000, 4096, PROT_READ) = 0
mprotect(0x7f6bd6256000, 4096, PROT_READ) = 0
mprotect(0x7f6bd667c000, 4096, PROT_READ) = 0
mprotect(0x7f6bd6c6a000, 8192, PROT_READ) = 0
mprotect(0x7f6bd708d000, 4096, PROT_READ) = 0
mprotect(0x56434973a000, 4096, PROT_READ) = 0
mprotect(0x7f6bd72b2000, 4096, PROT_READ) = 0
munmap(0x7f6bd72a5000, 49456)           = 0
set_tid_address(0x7f6bd72a0410)         = 905
set_robust_list(0x7f6bd72a0420, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f6bd6c74bd0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f6bd6c800e0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f6bd6c74c60, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f6bd6c800e0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
semget(0x64, 1, 0666)                   = -1 ENOENT (No such file or directory)
semctl(-1, 0, SETVAL, 0x7f6b00000001)   = -1 EINVAL (Invalid argument)
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f6bd72a0410) = 907
exit_group(0)                           = ?
+++ exited with 0 +++

Christian_Voelker · April 25, 2019, 11:28am

Eeeeehmmmm… well…

Could you start the strace of the notifier with the mentioned parameters?

/CV

sccmrb · April 25, 2019, 1:43pm

With the startup parameters it’s quite long, about 1.7MB.

https://drive.google.com/file/d/1fxPsDHxihd8VwxEYNZSZKnbDWZ4Ahncw/view?usp=sharing

Christian_Voelker · April 25, 2019, 2:46pm

Hi,

strace output is indeed difficult to read and understand. But usually it gives some hints, mostly at the end of the file. So here, too:

write(3, "25.04.19 07:37:51.221  TRANSFILE"..., 114) = 114
write(3, "25.04.19 07:37:51.221  TRANSFILE"..., 65) = 65
write(9, "0\201\322\2\1\2h\201\314\4\37reqSession=27301728,c"..., 213) = 213
poll([{fd=9, events=POLLIN|POLLPRI}], 1, -1) = 1 ([{fd=9, revents=POLLIN}])
read(9, "0\35\2\1\2i\30\n", 8)          = 8
read(9, "\1P\4\0\4\21txn_commit failed", 23) = 23
write(3, "25.04.19 07:37:51.221  TRANSFILE"..., 114) = 114
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
getpid()                                = 3628
gettid()                                = 3628
tgkill(3628, 3628, SIGABRT)             = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
--- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=3628, si_uid=0} ---
+++ killed by SIGABRT +++
Aborted

“killed by” is a sign of failure. Some lines above your see again a “failed” and below “TRANSFILE”.
And on the top of my quote you see a successful write command:
write(3, "25.04.19 07:37:51.221 TRANSFILE"..., 65) = 65
where it has written successful (!) 65bytes to the file with the file descriptor 3. Which is:

cv@pc:~/Downloads$ grep -E "^open.*3$" strace.txt| tail -1
open("/var/log/univention/notifier.log", O_RDWR|O_CREAT|O_APPEND, 0666) = 3

So I am pretty sure it writes it’s output to the logfile. So please post the logfile as it will for sure give some hints.

Oh, and I see:
write(3, "25.04.19 07:37:50.529 DEBUG_INI"..., 34) = 34
which is the DEBUG_INIT I was asking for.

You mentioned you do not see it in the logfile? I see it has been written to…

/CV