invalid lock sequence report

kfb77 · 3. Januar 2022

Hallo kls

ich bräuchte mal deinen Support. Fourty2 bekommt diesen invalid lock sequence report:

Code

Jan  3 09:41:56 vdr: [2863] markad: RunningRecording(): WANT   timers READ
Jan  3 09:41:56 vdr: [2863] --- begin invalid lock sequence report
Jan  3 09:41:56 vdr: [2863]  2934  -  U  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2934  -  U  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2930  -  W  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2930  -  U  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2930  -  W  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2930  -  *  -  -  W  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2930  -  *  -  -  U  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2930  -  U  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2934  -  W  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2934  -  *  -  -  W  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2934  -  *  -  -  U  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2934  -  U  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2930  -  W  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2930  -  U  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2863  R  -  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2863  U  -  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2863  R  -  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2863  U  -  -  -  -  -  -  -  -  -  U
Jan  3 09:41:56 vdr: [2863]  2863  -  R  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2863  R  *  -  -  -  -  -  -  -  -  L
Jan  3 09:41:56 vdr: [2863]  2863 invalid lock sequence: 1 Timers
Jan  3 09:41:56 vdr: [2863] full backtrace:
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr cStateLock::Lock(cStateKey&, bool, int) calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr cTimers::GetTimersRead(cStateKey&, int) calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] /usr/lib/vdr/plugins/libvdr-markad.so.2.4.7 cStatusMarkAd::RunningRecording() at status.cpp:497
Jan  3 09:41:57 vdr: [2863] /usr/lib/vdr/plugins/libvdr-markad.so.2.4.7 cStatusMarkAd::Recording(cDevice const*, char const*, char const*, bool) at status.cpp:787 at cStatusMarkAd::Recording(cDevice const*, char const*, char const*, bool) at status.cpp:720
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr cStatus::MsgRecording(cDevice const*, char const*, char const*, bool) calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr cRecordControl::Stop(bool) calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr cRecordControls::ChannelDataModified(cChannel const*) calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr main calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] /lib/x86_64-linux-gnu/libc.so.6 __libc_start_main at libc-start.c:342
Jan  3 09:41:57 vdr: [2863] /usr/bin/vdr _start calling ?? at ??:0
Jan  3 09:41:57 vdr: [2863] --- end invalid lock sequence report
Jan  3 09:41:57 vdr: [2863] --- THERE WILL BE NO FURTHER REPORTS UNTIL VDR IS RESTARTED!

Alles anzeigen

Das Problem ist ja wohl der Channel Lock vor dem Timer Lock bei markad.

Mein Problem ist, dass markad keinen Channel Lock an der Stelle macht, zumindest finde ich ihn nicht. Es gibt nur eine Stelle im markad Code, der einen Channel Lock macht, der wird aber nur aus dem Konfigurations Menu aufgerufen. Außerdem ist er mit Debug Meldungen versehen, siehe hier, die wie erwartet, nicht im Log auftauchen.

Meine Frage: Gibt es irgendwas anderes, außer "cChannels::GetChannelsRead(StateKey)" und LOCK_CHANNELS_READ, was implizit einen Channel Read Lock macht ? Wo kommt mein Lock her ?

Das Problem ist reproduzierbar nach dem Abbruch einer Aufnahme wegen PID Änderung:

Code

Jan  3 09:41:56 vdr: [2930] changing pids of channel 1862
Jan  3 09:41:56 vdr: [2934] changing pids of channel 101
Jan  3 09:41:56 vdr: [2930] changing pids of channel 1862
Jan  3 09:41:56 vdr: [2863] retuning: TMR, CHN Read Lock
Jan  3 09:41:56 vdr: [2863] stopping recording due to modification of channel 101
Jan  3 09:41:56 vdr: [3303] recording thread ended (pid=2863, tid=3303)
Jan  3 09:41:56 vdr: [2863] SendCaPmts CAM 1: [1] actives in CAM: 2 -> 1 (3 pids)
Jan  3 09:41:56 vdr: [2863] CAM 1: unassigned from device 2

Weitere Details und Logs ab hier im markad Thread.

kamel5 · 3. Januar 2022

Zitat von kfb77

Gibt es irgendwas anderes, außer "cChannels::GetChannelsRead(StateKey)" und LOCK_CHANNELS_READ

Soweit ich das bisher verstanden habe, nicht.

Was mir an dem Log aufgefallen ist, dort fehlen Informationen: die Fragezeichen

/usr/bin/vdr cRecordControl::Stop(bool) calling ?? at ??:0

Schau mal, ob in "thread.c" alle Debug-Optonen aktiv sind:

- #define DEBUG_LOCKING

- #define DEBUG_LOCKSEQ

- #define DEBUG_LOCKCALL

Dann sollten auch die Fragezeichen durch Sinnvolles ersetzt sein. Vielleicht lässt sich dann besser erkennen, wo diese Aufrufe herkommen.

Grüße

kamel5

Fourty2 · 3. Januar 2022

Habe ich schon versucht. Produzierte leider ruck zuck eine Schutzverletzung.

Wo die Aufrufe herkommen, sieht man aber auch so gut genug, daher tat es ein isyslog hier und da ...

Grüße,

Stefan

kfb77 · 4. Januar 2022

kls

Wir sind jetzt ein wenig weitergekommen: Die Id 2863 im o.g. Log ist gar nicht markad, sondern VDR. Der Channel Lock kommt vom VDR, der Timer Lock von markad, in dieser Reihenfolge. So weit so schlecht.

Eigentlich dachte ich immer, der VDR führt Plugin Methoden immer in einem eigenen Thread aus und somit hat jedes Plugin sein eigenes Lock Universum. Dem ist offensichtlich nicht so.

Aber jetzt meine Frage: Darf der VDR einen Lock haben, wenn er eine Plugin Methode aufruft ? Ich kann mir nicht vorstellen, dass das gut ist, dann laufe ich im Plugin ja blind in einen Sequenz Fehler rein, oder ?

Fourty2 · 4. Januar 2022

Ich kann mir so ungefähr denken, was Klaus dazu sagt:

skindesigner - bad locking order for vdr-2.3.x

"Dann starte halt einen Thread, der die Timer besorgt"

Grüße,

42

kfb77 · 4. Januar 2022

Stimmt, das ist genau das gleiche Problem.

invalid lock sequence report

Jetzt mitmachen!

Teilen