Bug 52000 - Script "usr/bin/python2.7 /usr/share/univention-appcenter-listener-converter owncloud" causing high CPU load
Script "usr/bin/python2.7 /usr/share/univention-appcenter-listener-converter ...
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: App Center
UCS 4.4
amd64 Linux
: P5 normal (vote)
: UCS 5.0-2-errata
Assigned To: Dirk Wiesenthal
Julia Bremer
https://help.univention.com/t/increas...
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2020-09-14 08:58 CEST by Thomas
Modified: 2022-09-29 12:38 CEST (History)
6 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 3: Simply Wrong: The implementation doesn't match the docu
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 2: A Pain – users won’t like this once they notice it
User Pain: 0.069
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments
Top screenshot showing above mentioned script. (87.47 KB, image/jpeg)
2020-09-14 08:58 CEST, Thomas
Details
Chart showing increased CPU load since the update (17.25 KB, image/jpeg)
2020-09-14 09:53 CEST, Thomas
Details
Top screenshot showing listener-converter high load owncloud AND openproject (50.88 KB, image/jpeg)
2020-09-16 18:01 CEST, Thomas
Details
owncloud and openproject listener logs (2.12 KB, application/x-zip-compressed)
2020-09-16 19:02 CEST, Thomas
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Thomas 2020-09-14 08:58:37 CEST
Created attachment 10489 [details]
Top screenshot showing above mentioned script.

Since l have updated owncloud to version 10.4.1 two weeks ago, I see now an increased CPU-Load by 100% (nothing critical yet).

This python script seems to be the culprit: “usr/bin/python2.7 /usr/share/univention-appcenter-listener-converter owncloud”
Right after updating ownCloud to version 10.4.1 this process/script is starting over and over again in a loop - It starts, causes high CPU load and then ends (every 5 seconds).

For some screenshots pls check this link (Univention forum):

https://help.univention.com/t/increased-cpu-load-100-since-update-caused-by-univention-appcenter-listener-converter/16009
Comment 1 Thomas 2020-09-14 09:08:39 CEST
/var/log/univention/listener_modules/owncloud.log shows (since the update):

2020-09-02 08:51:56 INFO    Using App account connection
2020-09-02 08:51:57 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
Comment 2 Thomas 2020-09-14 09:16:01 CEST
/var/log/univention/listener_modules/owncloud.log shows (since the update):

2020-09-02 08:51:56 INFO    Using App account connection
2020-09-02 08:51:57 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
Comment 3 Erik Damrose univentionstaff 2020-09-14 09:36:51 CEST
The ownCloud app from version 10.4.1 onwards uses the App Center listener converter feature (IDM push notifications [1]) to quickly sync new users and changes at existing users from UCS to the ownCloud user database. Previously this was only done every 10 minutes by a cronjob in the docker container.

What are the specs for the UCS instance running ownCloud, especially UCS server role, CPU cores, RAM, harddisc (SSD or magnetic disc)?

[1] https://docs.software-univention.de/app-provider-4.4.html#provisioning:push
Comment 4 Thomas 2020-09-14 09:52:36 CEST
Server role is: "domaincontroller_master" (part of an AD domain)
UCS is running as a VM on HyperV with the following specs:

8GB RAM
4 CPU Cores (logical)
256GB SSD

Please see also attached chart show the increased CPU load since the update - This behaviour can be easily reproduced on my test systems just by installing/updating owncloud 10.4.1.
Comment 5 Thomas 2020-09-14 09:53:10 CEST
Created attachment 10490 [details]
Chart showing increased CPU load since the update
Comment 6 Nico Gulden univentionstaff 2020-09-16 15:44:50 CEST
It would be good to know if other apps using the the App Center listener converter feature show the same behavior. Apps using this feature are for example OpenProject and itslearning.
Comment 7 Thomas 2020-09-16 17:21:26 CEST
/var/log/univention/listener_modules/owncloud.log is full with this 2 records (logged every 5 seconds):

2020-09-16 17:09:24 INFO    Using App account connection
2020-09-16 17:09:24 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:30 INFO    Using App account connection
2020-09-16 17:09:31 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:37 INFO    Using App account connection
2020-09-16 17:09:38 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:44 INFO    Using App account connection
2020-09-16 17:09:44 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:51 INFO    Using App account connection
2020-09-16 17:09:51 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found


univention-app info (prod):

UCS: 4.4-5 errata737
Installed: adconnector=12.0 fetchmail=6.3.26 kde=5.8 kopano-core=8.7.1.0-1 kopano-webapp=3.5.14.2539-2 kopano-webmeetings=3.0.1.100 letsencrypt=1.2.2-8 onlyoffice-ds=5.6.3.2 owncloud=10.4.1 samba-memberserver=4.7 z-push-kopano=2.4.5 4.3/guacamole=0.9.13-univention14

univention-app info (test system):

UCS: 4.4-5 errata750
Installed: bareos=18.2.7 bluespice=3.1.9-ucs.1 fetchmail=6.3.26 kopano-core=8.7.1.0-1 kopano-meet=2.2.3_0-1 kopano-webapp=3.5.14.2539-2 nagios=4.3 onlyoffice-ds=5.6.2.2 owncloud=10.4.1 rocketchat=3.5.3 wordpress=5.2.3 z-push-kopano=2.4.5 4.3/openid-connect-provider=2.0-konnect-0.33.3

On both systmes only "listener-converter owncloud" is showing this behavior.
Comment 8 Thomas 2020-09-16 17:22:07 CEST
/var/log/univention/listener_modules/owncloud.log is full with this 2 records (logged every 5 seconds):

2020-09-16 17:09:24 INFO    Using App account connection
2020-09-16 17:09:24 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:30 INFO    Using App account connection
2020-09-16 17:09:31 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:37 INFO    Using App account connection
2020-09-16 17:09:38 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:44 INFO    Using App account connection
2020-09-16 17:09:44 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found
2020-09-16 17:09:51 INFO    Using App account connection
2020-09-16 17:09:51 INFO    EntryUUID 97d7d956-c86f-1037-94ec-572fc949ef04 not found


univention-app info (prod):

UCS: 4.4-5 errata737
Installed: adconnector=12.0 fetchmail=6.3.26 kde=5.8 kopano-core=8.7.1.0-1 kopano-webapp=3.5.14.2539-2 kopano-webmeetings=3.0.1.100 letsencrypt=1.2.2-8 onlyoffice-ds=5.6.3.2 owncloud=10.4.1 samba-memberserver=4.7 z-push-kopano=2.4.5 4.3/guacamole=0.9.13-univention14

univention-app info (test system):

UCS: 4.4-5 errata750
Installed: bareos=18.2.7 bluespice=3.1.9-ucs.1 fetchmail=6.3.26 kopano-core=8.7.1.0-1 kopano-meet=2.2.3_0-1 kopano-webapp=3.5.14.2539-2 nagios=4.3 onlyoffice-ds=5.6.2.2 owncloud=10.4.1 rocketchat=3.5.3 wordpress=5.2.3 z-push-kopano=2.4.5 4.3/openid-connect-provider=2.0-konnect-0.33.3

On both systmes only "listener-converter owncloud" is showing this behavior.
Comment 9 Thomas 2020-09-16 17:59:43 CEST
update: I have also deployed OpenProject from the App-Center on my test-system and it shows the same behavior (see attched screenshot)
Comment 10 Thomas 2020-09-16 18:01:28 CEST
Created attachment 10493 [details]
Top screenshot showing listener-converter high load owncloud AND openproject
Comment 12 Thomas 2020-09-16 19:02:50 CEST
Created attachment 10494 [details]
owncloud and openproject listener logs
Comment 13 Thomas 2020-09-16 19:03:27 CEST
the “EntryUUID … not found” I can see only on my production system (needs to be fixed also but I dont think this is the root cause).

Nevertheless „listener-converters“ (owncloud AND openproject) are causing high load on my test system as well (identical to prod-system).

Please find attached the listener.logs from my test envrionment.
Comment 14 Erik Damrose univentionstaff 2020-09-17 21:46:50 CEST
A listener converter will start every 5 seconds, and if a user or group change did happen in that time, the converter will start the respective trigger for the app.

In the case of owncloud, the following script is run in the container.  http://appcenter.software-univention.de/univention-repository/4.4/maintained/component/owncloud_20200417143931/listener_trigger

Depending on the amount of users in LDAP, that sync might take a while and put load on the system.

One could debug the runtime some more by executing the above listener trigger manually in the owncloud container, while creating an empty json file in /var/lib/univention-appcenter/apps/owncloud/data/listener/ beforehand.

Is the bug flag "How will those affected feel about the bug?" accurate with the setting "2: A pain - users won't like it once they notice it"?
Comment 15 Thomas 2020-09-18 08:19:54 CEST
"Is the bug flag "How will those affected feel about the bug?" accurate?"

its difficult for me to classify this bug with the given categories. 
Depending of the general overall load of your system this bug can become critical very quickly - in my case the overall system load went from average 25% to 50% (plus 100%).

Me personally I would set the criticality of this ticket a bit higher therefore.
Comment 16 Gerard de Leeuw 2022-01-11 07:18:08 CET
I just ran into the same 'issue', in my case my CPU cooler would spin up every 5 seconds and then slow down (due to the peak in load). 
That quickly became very annoying, so I increased the restart time to 10 minutes.

For other people trying to the same, simply run this command:

systemctl edit univention-appcenter-listener-converter@owncloud.service

and paste this in the editor:

[Service]
RestartSec=600
Comment 17 Dirk Wiesenthal univentionstaff 2022-09-24 21:43:24 CEST
Restarting the service every 5 seconds was meant to make the listener integration "robust" in the sense that no long running process gets outdated by an app update, an old LDAP connection or something similar.

We now make sure that the listener or the converter service gets restarted properly on an app update. This allows us to add an infinite loop inside the converter.

univention-appcenter.yaml
b066d45e36ff | Bug #52000: YAML

univention-appcenter (9.0.3-3)
76b785172594 | Bug #52000: Loop inside the listener converter in order to reduce CPU load

ucs-test (10.0.7-24)
76b76b9c6cd1 | Bug #52000: Adjust App Center listener test - it is now a long running process
Comment 18 Julia Bremer univentionstaff 2022-09-26 17:03:19 CEST
OK: No more CPU load peaks by "from univention.appcenter.app_cache import Apps; app = Apps().find("owncloud")"
OK: App upgrade restarts listener-converter
OK: App registration restarts listener-converter
OK: Package update
OK: Tests
OK: Yaml

Verified