OC8, OC9 Series metadata update causes livescheduling loop

Christoph Reifers

unread,

Apr 15, 2021, 10:36:59 AM4/15/21

to us...@opencast.org

Hello everyone,
we noticed a really odd behaviour in our oc-production instance yesterday. A series with about 30 scheduled events, all scheduled for livestreaming as well had it's metadata edited. This caused a never-ending loop of new mediapackage versions (we racked up about 27000 snapshots for 30 events (999+each) before OC grinded to a halt).

This behaviour is reproducible on our test-instance which runs 0C 8 as well as our dev-instance (OC 9). As soon as a series also contains a scheduled event with livestreaming enabled a change in the series metadata causes the creation of many many livestreaming publications.

Is there anyone who is brave enough to try and reproduce this behaviour? Don't use a production-system ;)

We also tried upping the loglevel for the liveschedule.impl which isn't helpful.
Does someone have an idea what we can do to debug this further?

Tips on how to efficiently get rid of thousands of snapshots are also very appreciated.

Logs are attached from a reproduction of this behaviour, I'll spare you the full version which continues for about 7 hours from our production instance.

regards,
Christoph

Universität zu Köln
Regionales Rechenzentrum (RRZK)
Weyertal 121
D-50931 Köln

opencast.log.2021-04-15

Rute Santos

unread,

Apr 15, 2021, 11:27:48 AM4/15/21

to us...@opencast.org

Hi Christoph,

What's weird in this is that in the log there are several of:

(LiveScheduleServiceImpl:295) - Creating live media package 11e18da5-1936-4e0b-a6e3-1570f88d7c14

which indicates that the LiveScheduleService never found the media package id in the search index (see code in [1]).

Just confirming that you set the LiveScheduleServiceImpl log level to DEBUG? If you did, we should have seen the following DEBUG log message: ""Adding live channel publication element to media package XXX" after the elements were distributed and the media package was published to the search index, which does not appear in your log.

Were there any problems with engage at the time that would cause jobs to not be dispatched/completed? It may be helpful to attach the engage log too.

Can you open a ticket with all the necessary steps to reproduce?

Thanks,

Rute

[1] https://github.com/opencast/opencast/blob/5728b0c8bf77884feb00ebd27e607d592566e448/modules/live-schedule-impl/src/main/java/org/opencastproject/liveschedule/impl/LiveScheduleServiceImpl.java#L236)

--
To unsubscribe from this group and stop receiving emails from it, send an email to users+un...@opencast.org.

reifersc...@gmail.com

unread,

Apr 16, 2021, 3:46:16 AM4/16/21

to Opencast Users, rsa...@g.harvard.edu

Hi Rute,

thank you for looking into this. I created a bug report with steps to reproduce the behaviour. Please let me know if I missed anything, I will gladly provide further information.

regards

Christoph

Ruth Lang

unread,

Apr 16, 2021, 7:37:15 AM4/16/21

to Opencast Users, reifersc...@gmail.com, rsa...@g.harvard.edu

Hi Rute,

attached you can find log files from admin and engage.

Indeed, the LiveScheduleService receives a "Not found" from the search index and therefore creates a new element.

But the main question is : Why does the "AssetManager" always create a new version of the the MP ?

Regards

Ruth

admin node:

2021-04-16T10:45:52,029 | INFO | (AbstractAssetManager:249) - Creating new version 280 of media package 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:45:52,132 | INFO | (AssetManagerWithMessaging:217) - Send update message for snapshot 85595a69-3eea-48be-8afb-7001312c976f, 280 to ActiveMQ

2021-04-16T10:45:52,227 | DEBUG | (LiveScheduleServiceImpl:462) - The search service doesn't know live mediapackage 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:45:52,228 | INFO | (LiveScheduleServiceImpl:295) - Creating live media package 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:45:52,292 | DEBUG | (LiveScheduleServiceImpl:475) - Live media package 85595a69-3eea-48be-8afb-7001312c976f has start Sun Apr 18 09:10:00 CEST 2021 and duration 300000

2021-04-16T10:45:52,296 | DEBUG | (LiveScheduleServiceImpl:552) - Creating live track element of flavor presenter/delivery, resolution 1920x1080, and url https://xxx.xxx.de/extron/ngrp:xxx_all/playlist.m3u8

2021-04-16T10:45:52,335 | INFO | (DownloadDistributionServiceRemoteImpl:107) - Distributing 3 elements to engage-live@download

2021-04-16T10:45:57,561 | INFO | (LiveScheduleServiceImpl:412) - Publishing LIVE media package 85595a69-3eea-48be-8afb-7001312c976f to search index

2021-04-16T10:45:57,722 | INFO | (SearchServiceRemoteImpl:81) - Publishing mediapackage '85595a69-3eea-48be-8afb-7001312c976f' using a remote search service

2021-04-16T10:46:02,758 | DEBUG | (LiveScheduleServiceImpl:714) - Adding live channel publication element to media package 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:46:02,830 | INFO | (AbstractAssetManager:249) - Creating new version 281 of media package 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:46:02,929 | INFO | (AssetManagerWithMessaging:217) - Send update message for snapshot 85595a69-3eea-48be-8afb-7001312c976f, 281 to ActiveMQ

2021-04-16T10:46:03,041 | DEBUG | (LiveScheduleServiceImpl:462) - The search service doesn't know live mediapackage 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:46:03,042 | INFO | (LiveScheduleServiceImpl:295) - Creating live media package 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:46:03,110 | DEBUG | (LiveScheduleServiceImpl:475) - Live media package 85595a69-3eea-48be-8afb-7001312c976f has start Sun Apr 18 09:10:00 CEST 2021 and duration 300000

2021-04-16T10:46:03,114 | DEBUG | (LiveScheduleServiceImpl:552) - Creating live track element of flavor presenter/delivery, resolution 1920x1080, and url https://xxx.xxx.de/extron/ngrp:xxx_all/playlist.m3u8

2021-04-16T10:46:03,152 | INFO | (DownloadDistributionServiceRemoteImpl:107) - Distributing 3 elements to engage-live@download

2021-04-16T10:46:08,368 | INFO | (LiveScheduleServiceImpl:412) - Publishing LIVE media package lin to search index

2021-04-16T10:46:08,533 | INFO | (SearchServiceRemoteImpl:81) - Publishing mediapackage '85595a69-3eea-48be-8afb-7001312c976f' using a remote search service

2021-04-16T10:46:13,552 | DEBUG | (LiveScheduleServiceImpl:714) - Adding live channel publication element to media package 85595a69-3eea-48be-8afb-7001312c976f

2021-04-16T10:46:13,634 | INFO | (AbstractAssetManager:249) - Creating new version 282 of media package 85595a69-3eea-48be-8afb-7001312c976f

.

enagage node:

2021-04-16T10:45:40,747 | INFO | (SearchServiceImpl:399) - Added media package `85595a69-3eea-48be-8afb-7001312c976f` to the search index, using ACL `[ROLE_USER_ADMIN is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to write, ROLE_USER_ADMIN is allowed to write]`

2021-04-16T10:45:50,922 | INFO | (SearchServiceImpl:399) - Added media package `85595a69-3eea-48be-8afb-7001312c976f` to the search index, using ACL `[ROLE_USER_ADMIN is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to write, ROLE_USER_ADMIN is allowed to write]`

2021-04-16T10:46:01,025 | INFO | (SearchServiceImpl:399) - Added media package `85595a69-3eea-48be-8afb-7001312c976f` to the search index, using ACL `[ROLE_USER_ADMIN is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to write, ROLE_USER_ADMIN is allowed to write]`

2021-04-16T10:46:11,184 | INFO | (SearchServiceImpl:399) - Added media package `85595a69-3eea-48be-8afb-7001312c976f` to the search index, using ACL `[ROLE_USER_ADMIN is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to read, ROLE_EXTERNAL_APPLICATION is allowed to write, ROLE_USER_ADMIN is allowed to write]`

.

Rute Santos

unread,

Apr 16, 2021, 11:40:22 AM4/16/21

to Ruth Lang, Opencast Users, reifersc...@gmail.com

Hi Ruth,

I'm looking at the code... Unfortunately, I don't have a working Opencast 9.x to reproduce the problem and I wasn't able to do it in our Opencast 5.x+6.x+8.x mix :)

The LiveSchedulerService takes a snapshot when it first creates a "live" media package in the engage search index because it adds a publication element to it. It also takes one when the media package is deleted from the engage search index. When updating, no snapshots are taken. The problem seems to be that, since it never finds the media package in the search index, it always "creates" one and thus takes a snapshot, causing the loop.

My hunch is that it doesn't find it because of the ACL, but I'm still investigating...

Thanks,

Rute

Ludwig Willmann

unread,

Apr 23, 2021, 5:45:02 AM4/23/21

to us...@opencast.org, Rute Santos, Ruth Lang, reifersc...@gmail.com

Hi all,

we had a similar problem at Switch where the LiveScheduler was unable to find existing entries in the engage search index. We fixed this by querying the index with administrative rights.
As Switch is not using engage or the engage search index in the common Opencast way I thought the problem is a result of these modifications and thus didn't create a PR for this issue. Anyhow I see no harm in querying the index with administrative rights and it might fix this issue. If I'm wrong please correct me.

Regards,
Ludwig

Am 16.04.21 um 17:39 schrieb Rute Santos:

-- 
Ludwig Willmann (Dipl.-Wirt.-Inf., M.Sc.)
ELAN e.V.

Zentrum für Digitale Lehre, Campus-Management und Hochschuldidaktik
(virtUOS)
Raum 42/209, Heger-Tor-Wall 12, 49074 Osnabrück

E-Mail: will...@elan-ev.de
Telefon: +49 (0)541/969-6520
Webseite: http://elan-ev.de, http://www.virtuos.uni-osnabrueck.de

Ruth Lang

unread,

Apr 30, 2021, 10:12:54 AM4/30/21

to Opencast Users, will...@elan-ev.de, Christoph, rsa...@g.harvard.edu, Ruth Lang

Hi Ludwig,

a very simple example, done as an non privileged user of Opencast (8.10)

1.) create a series with the following ACLs (read and write) ROLE_USER_LANGR, ROLE_ADMIN

2.) add a scheduled live event

—> success

3.) update some metadata of the episode

—> success

4.) change the series title

—> SUCCESS !!!

Remove the role ROLE_ADMIN and 4. will end in an endless loop between Assetmanager and Livescheduling creating new snapshots, because the SearchQuery for the episode returns "not found"

The LIveScheduler always use the same query for searching the episode and it remains a mystery (for me) why this query is successfully after 3) but not after 4)

Regards

Ruth

Rute Santos

unread,

Apr 30, 2021, 10:48:29 AM4/30/21

to Opencast Users

Hi,

Just fyi, all the debugging details are in the ticket: https://github.com/opencast/opencast/issues/2504. I hope to provide a fix soon :)

Thanks!

Rute

Ruth Lang

unread,

Apr 30, 2021, 12:45:25 PM4/30/21

to Opencast Users, rsa...@g.harvard.edu

Hi Rute,

sorry, I didn't noticed that issue.

Thanks

Ruth

Rute Santos

unread,

May 4, 2021, 11:35:11 AM5/4/21

to Opencast Users

Hi Ruth,

Here's the PR for the fix: https://github.com/opencast/opencast/pull/2567. Could you check if it fixes your issue?

Thanks,

Rute

Ruth Lang

unread,

May 4, 2021, 11:41:10 AM5/4/21

to Opencast Users, rsa...@g.harvard.edu

Hi Rute,

sure, I will test it and let you know the results

Thanks a lot

Ruth

Ruth Lang

unread,

May 5, 2021, 3:36:00 AM5/5/21

to Opencast Users, Ruth Lang, rsa...@g.harvard.edu

Hi Rute,

I have tried your changes in our development cluster (current OC 9 version) and can confirm that the error no longer occurs.

But I found a bug when I try to change scheduling data.

- if I want to change the time for a scheduled recording, I unfortunately see only the hours and no more the fields for the minutes.

- there are error messages in the logfile after I have made changes in this tab. In my opinion, these are not related to the LiveScheduler, but to the ScheduleService itself

Attached you can see snippets from the log file for various changes in a planned live event.

In any case, I would say your changes have solved the problem. Many, many thanks for your support.

Regard

Ruth

1. Change date of schedule event

2021-05-05T08:47:35,245 | INFO | (LiveScheduleServiceImpl:356) - Updating live media package 01ac6b59-6369-4930-b505-6e17afb8e70e

2021-05-05T08:47:35,341 | INFO | (DownloadDistributionServiceRemoteImpl:107) - Distributing 3 elements to engage-live@download

2021-05-05T08:47:40,524 | INFO | (LiveScheduleServiceImpl:416) - Publishing LIVE media package 01ac6b59-6369-4930-b505-6e17afb8e70e to search index

2021-05-05T08:47:40,624 | INFO | (SearchServiceRemoteImpl:81) - Publishing mediapackage '01ac6b59-6369-4930-b505-6e17afb8e70e' using a remote search service

2021-05-05T08:47:45,640 | INFO | (DownloadDistributionServiceRemoteImpl:130) - Retracting 1 elements from engage-live@download

2021-05-05T08:47:50,887 | INFO | (LiveScheduleServiceImpl:356) - Updating live media package 01ac6b59-6369-4930-b505-6e17afb8e70e

2021-05-05T08:47:50,937 | INFO | (DownloadDistributionServiceRemoteImpl:107) - Distributing 3 elements to engage-live@download

2021-05-05T08:47:56,067 | WARN | (SchedulerUpdateHandler:112) - Exception occurred for mp 01ac6b59-6369-4930-b505-6e17afb8e70e, event type UpdateStart

org.opencastproject.liveschedule.api.LiveScheduleException: Element(s) for live media package 01ac6b59-6369-4930-b505-6e17afb8e70e could not be distributed

at org.opencastproject.liveschedule.impl.LiveScheduleServiceImpl.addAndDistributeElements(LiveScheduleServiceImpl.java:668) ~[!/:?]

at org.opencastproject.liveschedule.impl.LiveScheduleServiceImpl.updateLiveEvent(LiveScheduleServiceImpl.java:358) ~[!/:?]

at org.opencastproject.liveschedule.impl.LiveScheduleServiceImpl.createOrUpdateLiveEvent(LiveScheduleServiceImpl.java:258) ~[!/:?]

at org.opencastproject.liveschedule.message.SchedulerUpdateHandler.executeSingle(SchedulerUpdateHandler.java:95) [!/:?]

at org.opencastproject.liveschedule.message.SchedulerUpdateHandler.execute(SchedulerUpdateHandler.java:54) [!/:?]

at org.opencastproject.liveschedule.message.LiveScheduleMessageReceiver$MessageWatcher$1.run(LiveScheduleMessageReceiver.java:117) [!/:?]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_292]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_292]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_292]

2021-05-05T08:47:56,171 | INFO | (LiveScheduleServiceImpl:356) - Updating live media package 01ac6b59-6369-4930-b505-6e17afb8e70e

2021-05-05T08:47:56,202 | INFO | (DownloadDistributionServiceRemoteImpl:107) - Distributing 3 elements to engage-live@download

2021-05-05T08:48:01,344 | WARN | (SchedulerUpdateHandler:112) - Exception occurred for mp 01ac6b59-6369-4930-b505-6e17afb8e70e, event type UpdateEnd