[Gelöst] VDR fährt nach Timeraufnahme nicht herunter

spitzb · August 25, 2017 at 10:43 AM

Ich mache in letzter Zeit häufiger Aufzeichnungen am späten Abend/Nachts. Wenn ich meine AV-Anlage ausschalte, läuft deshalb häufig eine Aufnahme. VDR meldet dann auch korrekt "VDR schaltet später aus....".

Das Frontend wird detached, und die Anzeige von Graphtft wechselt in den Timer Modus. So weit, so gut.

Blöderweise fährt der VDR aber nicht herunter, wenn die letzte Aufnahme komplett ist. Wenn VDR sich für eine Aufnahme selbst einschaltet, fährt er nach der Aufnahme auch wieder herunter. Wo kann ich mit der Fehlersuche anfangen?

Falk

seahawk1986 · August 25, 2017 at 10:49 AM

Was steht denn im Log?

spitzb · August 25, 2017 at 10:55 AM

Jede Menge ;), aber zum Thema shutdown habe ich nichts gefunden. Gibt es einen bestimmten Begriff, nach dem ich suchen könnte?

Falk

seahawk1986 · August 25, 2017 at 11:09 AM

Da der VDR nicht automatisch herunterfährt, nachdem man ihm gesagt hat, dass er nicht mehr auf die Fernbedienung reagieren soll, übernimmt das Frontend-Skript die weiteren Shutdown-Versuche - falls der VDR oder das lifeguard-Addon dabei den Shutdown verhindert, sollte das frontend-Skript eine entsprechende Meldung ins Log schreiben, die mit "vdr not ready for shutdown" beginnt - das drum herum mit den Meldungen des VDR bzw. dbus2vdr könnte dabei auch noch relevant sein.

spitzb · August 25, 2017 at 11:10 AM

Habe mal einen Auszug aus dem Log gemacht, der nach dem Ende der letzten Aufzeichnung beginnt.

Code

Aug 25 00:10:00 vdrwozi vdr: [1415] buffer stats: 1003356 (4%) used
Aug 25 00:10:00 vdrwozi vdr: [1415] timer 1 (28 2308-0010 'Stargate: SG-1~Neue Dimensionen') stop
Aug 25 00:10:00 vdrwozi vdr: [4408] TS buffer on device 3 thread ended (pid=1415, tid=4408)
Aug 25 00:10:00 vdrwozi vdr: [4407] buffer stats: 350056 (8%) used
Aug 25 00:10:00 vdrwozi vdr: [4407] device 3 receiver thread ended (pid=1415, tid=4407)
Aug 25 00:10:00 vdrwozi vdr: [1415] executing '/usr/lib/vdr/vdr-recordingaction after "/srv/vdr/video/Stargate#3A_SG-1/Neue_Dimensionen/2017-08-24.23.08.28-0.rec"'
Aug 25 00:10:00 vdrwozi recordingaction: executing /usr/share/vdr/recording-hooks/R50correct_videodirs after recording /srv/vdr/video/Stargate#3A_SG-1/Neue_Dimensionen/2017-08-24.23.08.28-0.rec
Aug 25 00:10:00 vdrwozi recordingaction: executing /usr/share/vdr/recording-hooks/R60copy_epgimage after recording /srv/vdr/video/Stargate#3A_SG-1/Neue_Dimensionen/2017-08-24.23.08.28-0.rec
Aug 25 00:10:00 vdrwozi vdr: [1595] EPGSearch: search timer update started
Aug 25 00:10:00 vdrwozi vdr: [1595] timer 1 (6 0003-0107 'Gotham') set to event Mi. 30.08.2017 00:05-00:57 'Gotham'
Aug 25 00:10:00 vdrwozi vdr: [1595] timer 1 (9 2303-0010 'How to Get Away with Murder') set to event Mi. 30.08.2017 23:05-00:00 'How to Get Away with Murder'
... Mehrere Timer Updates
Aug 25 00:10:00 vdrwozi vdr: [1793] VNSI: Timers state changed (5)
Aug 25 00:10:00 vdrwozi vdr: [1793] VNSI: Requesting clients to reload timers
Aug 25 00:10:01 vdrwozi vdr: [1415] connect from 127.0.0.1, port 44466 - accepted
Aug 25 00:10:01 vdrwozi vdr: [1415] deleting timer 1 (28 2308-0010 'Stargate: SG-1~Neue Dimensionen')
Aug 25 00:10:01 vdrwozi vdr: [1415] closing SVDRP connection
Aug 25 00:10:01 vdrwozi vdr: [1595] EPGSearch: search timer update finished
Aug 25 00:10:01 vdrwozi vdr: [1793] VNSI: Timers state changed (6)
Aug 25 00:10:01 vdrwozi vdr: [1793] VNSI: Requesting clients to reload timers
Aug 25 00:10:09 vdrwozi vdr: [1576] changing ca descriptors of channel 737 (ALQUILER XX)
Aug 25 00:10:09 vdrwozi vdr: [1793] VNSI: Requesting clients to reload channel list
Aug 25 00:10:10 vdrwozi vdr: [1576] changing pids of channel 743 (ALQUILER 4) from 170+170=2:120=esl@4,121=eng@4:0:62 to 170+170=2:120=esl@4:0:0
Aug 25 00:10:10 vdrwozi vdr: [1576] changing caids of channel 743 (ALQUILER 4) from 100,1810 to 0
Aug 25 00:10:10 vdrwozi vdr: [1576] changing ca descriptors of channel 743 (ALQUILER 4)
Aug 25 00:11:19 vdrwozi vdr: [1585] frontend 3/0 timed out while tuning to channel 0 (), tp 211567
Aug 25 00:11:53 vdrwozi vdr: [1539] ERROR: can't set filter (pid=65535, tid=02, mask=FF): Das Argument ist ungültig
Aug 25 00:11:53 vdrwozi kernel: [13386.495499] DVB (dvb_dmxdev_filter_start): could not set feed
Aug 25 00:11:53 vdrwozi kernel: [13386.495508] dvb_demux_feed_del: feed not in list (type=1 state=0 pid=ffff)
Aug 25 00:12:01 vdrwozi vdr: [1585] frontend 3/0 timed out while tuning to channel 0 (), tp 211856
Aug 25 00:13:46 vdrwozi vdr: [1575] frontend 2/0 timed out while tuning to channel 0 (), tp 212610
Aug 25 00:15:08 vdrwozi vdr: [4406] ecmhandler 2/0 filter thread ended (pid=1415, tid=4406)
Aug 25 00:15:08 vdrwozi vdr: [4409] logger 2/0 filter thread ended (pid=1415, tid=4409)
Aug 25 00:16:34 vdrwozi vdr: [1517] frontend 0/0 timed out while tuning to channel 0 (), tp 111641
Aug 25 00:17:01 vdrwozi CRON[5893]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 25 00:17:09 vdrwozi vdr: [1576] changing name of channel 237 from '356 - 22:30,;' to '356 - 00:30,;'
Aug 25 00:17:09 vdrwozi vdr: [1793] VNSI: Requesting clients to reload channel list
Aug 25 00:18:20 vdrwozi vdr: [1518] read incomplete section - len = 681, r = 3610
Aug 25 00:19:01 vdrwozi vdr: [1538] frontend 1/0 timed out while tuning to channel 0 (), tp 112721
Aug 25 00:21:07 vdrwozi vdr: [1575] frontend 2/0 timed out while tuning to channel 0 (), tp 211567
Aug 25 00:21:41 vdrwozi vdr: [1518] ERROR: can't set filter (pid=65535, tid=02, mask=FF): Das Argument ist ungültig
Aug 25 00:21:41 vdrwozi kernel: [13974.833173] DVB (dvb_dmxdev_filter_start): could not set feed
Aug 25 00:21:41 vdrwozi kernel: [13974.833181] dvb_demux_feed_del: feed not in list (type=1 state=0 pid=ffff)
Aug 25 00:21:49 vdrwozi vdr: [1575] frontend 2/0 timed out while tuning to channel 0 (), tp 211856
Aug 25 00:23:36 vdrwozi vdr: [1538] frontend 1/0 timed out while tuning to channel 0 (), tp 212610
Aug 25 00:23:47 vdrwozi vdr: [1518] changing pids of channel 216 (Test-R) from 501+501=2:502=deu@3:0:0 to 401+401=2:402=deu@3:0:0
Aug 25 00:26:01 vdrwozi vdr: [1517] frontend 0/0 timed out while tuning to channel 0 (), tp 111641
Aug 25 00:26:14 vdrwozi vdr: [1576] changing pids of channel 381 (Motorvision TV) from 1279+1279=27:1280=deu@3:0:0 to 1279+1279=27:1280=deu@3,1281=eng@3:0:0
Aug 25 00:26:15 vdrwozi vdr: [1793] VNSI: Requesting clients to reload channel list
Aug 25 00:26:36 vdrwozi vdr: [1576] changing name of channel 238 from '367 - 21:00,;' to '367 - 00:30,;'
Aug 25 00:26:36 vdrwozi vdr: [1576] linking channel 114 (Sky Select) from 236 240 239 237 to 236 240 238 239 237
Aug 25 00:27:03 vdrwozi vdr: [1518] read incomplete section - len = 1828, r = 3981
Aug 25 00:27:14 vdrwozi vdr: [1518] read incomplete section - len = 428, r = 3646
Aug 25 00:28:29 vdrwozi vdr: [1538] frontend 1/0 timed out while tuning to channel 0 (), tp 112721
Aug 25 00:29:00 vdrwozi vdr: [1596] EPGSearch: timer conflict check started

Display More

Danach wiederholen sich im halbstündlichen Rhythmus die Suchtimer-Updates und Konfliktprüfungen.

Falk

spitzb · August 25, 2017 at 11:15 AM

Hier noch der Auszug vom Ausschalten:

Code

Aug 24 23:02:20 vdrwozi vdr: [1415] Power button pressed
Aug 24 23:02:20 vdrwozi vdr: [1415] warning: VDR schaltet später aus - Power zum Erzwingen
Aug 24 23:02:35 vdrwozi vdr: [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'menu'
Aug 24 23:02:35 vdrwozi vdr: [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'back'
Aug 24 23:02:36 vdrwozi vdr: message repeated 4 times: [ [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'back']
Aug 24 23:02:36 vdrwozi vdr: [4981] [softhddev]SetPlayMode: 0
Aug 24 23:02:36 vdrwozi vdr: video: decoder buffer empty, duping frame (5691/133250) 0 v-buf
Aug 24 23:02:36 vdrwozi vdr: video: --:--:--.---   +0    0   0/\ms   0+5+4 v-buf
Aug 24 23:02:36 vdrwozi vdr: [4981] [softhddev]SetVideoDisplayFormat: 1
Aug 24 23:02:36 vdrwozi vdr: [4981] [softhddev]GetSpuDecoder:

seahawk1986 · August 25, 2017 at 11:18 AM

Gab es zu dem Zeitpunkt eventuell noch einen oder mehrere aktive vnsi-Clients im Netzwerk?

fnu · August 25, 2017 at 11:20 AM

Kann es sein, das bei Deiner Ausschaltaktion sich schlicht wieder eine User-Interaktion einstreut und dadurch der Ausschaltzyklus ausgehebelt wird?

Dann müsste der Inaktivitätstimer aktiv werden, default ist meine ich 300min. Evtl. hast Du diesen deaktiviert ... ?

Regards

fnu

spitzb · August 25, 2017 at 11:27 AM

Quote from seahawk1986

Gab es zu dem Zeitpunkt eventuell noch einen oder mehrere aktive vnsi-Clients im Netzwerk?

Nein, das ist ausgeschlossen.

spitzb · August 25, 2017 at 11:31 AM

Quote from fnu

Kann es sein, das bei Deiner Ausschaltaktion sich schlicht wieder eine User-Interaktion einstreut und dadurch der Ausschaltzyklus ausgehebelt wird?

Dann müsste der Inaktivitätstimer aktiv werden, default ist meine ich 300min. Evtl. hast Du diesen deaktiviert ... ?

Regards

fnu

Eigentlich nicht. Du beziehst dich da wohl auf diese Einträge:

Code

Aug 24 23:02:35 vdrwozi vdr: [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'menu'
Aug 24 23:02:35 vdrwozi vdr: [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'back'
Aug 24 23:02:36 vdrwozi vdr: message repeated 4 times: [ [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'back']

woher die kommen, ist mir schleierhaft. VDR bleibt aber ein paar Sekunden auf der meldung "VDR schaltet später aus...."

Der Inaktivitätstimer ist tatsächlich deaktiviert. Es nervt, wenn man den ganzen Abend einen Sender schaut und VDR dann plötzlich runterfährt.

spitzb · August 25, 2017 at 11:34 AM

Ach ja, wenn kein Timer läuft, fährt VDR auch brav herunter.

seahawk1986 · August 25, 2017 at 11:55 AM

Quote from spitzb
Eigentlich nicht. Du beziehst dich da wohl auf diese Einträge:
Code
Aug 24 23:02:35 vdrwozi vdr: [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'menu'
Aug 24 23:02:35 vdrwozi vdr: [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'back'
Aug 24 23:02:36 vdrwozi vdr: message repeated 4 times: [ [4981] dbus2vdr: de.tvdr.vdr.remote.HitKeys: get key 'back']
woher die kommen, ist mir schleierhaft. VDR bleibt aber ein paar Sekunden auf der meldung "VDR schaltet später aus...."

Das kommt aus https://github.com/yavdr/yavdr-ba…n/frontend#L221 und soll sicher zu stellen, dass das OSD geschlossen ist, bevor der GPU-Cache des Skindesigner abgeräumt wird. Danach wird der Nutzer inaktiv gesetzt.

Quote from spitzb

Der Inaktivitätstimer ist tatsächlich deaktiviert. Es nervt, wenn man den ganzen Abend einen Sender schaut und VDR dann plötzlich runterfährt.

Das könnte die Ursache sein - denn dann wird der Nutzer nie vom VDR als inaktiv gesehen und die Abfrage über dbus2vdr gibt dann immer zurück, dass der Nutzer noch aktiv ist. Könntest du mit einer für die normale Nutzung ausreichend langen Zeitspanne (z.B. 600 Minuten oder mehr) leben? Wichtig ist nur, dass man den VDR soweit bekommen kann, dass er den Nutzer für inaktiv hält.

spitzb · August 25, 2017 at 12:31 PM

Ok, ich probiere das mal aus. Habe den Timer mal auf 500 Min. gestellt.

Falk

fnu · August 25, 2017 at 1:57 PM

Quote from spitzb

Ach ja, wenn kein Timer läuft, fährt VDR auch brav herunter.

Jo, das ist für mich eher noch ein Zeichen, das genau beim beschriebenen Vorgehen durch Tastenaktivität der Ausschaltzyklus ausgehebelt wird.

Quote from spitzb

Habe den Timer mal auf 500 Min. gestellt.

Ich habe bei mir (schon immer) 150min definiert, lang genug für die meisten Filme, kurz genug das der VDR nicht ewig läuft, sollte mal jemand versehentlich eine Taste auslösen ...

Der VDR fährt ja nicht unangekündigt runter, sondern meldet 5min lang das er nun runterfährt.

Regards

fnu

spitzb · August 28, 2017 at 8:30 AM

So, VDR ist zwar nach der letzten Aufzeichnung heruntergefahren, aber nur, weil der Inaktivitätstimer nach 500 Min. abgelaufen war, also 500 Min. nach der letzten Useraktion (Power).

Ich habe das log nochmal nach Useraktionen (Tasten) durchsucht, die den normalen Prozess stören könnten, aber nach der Meldung "VDR schaltet später aus..." kamen nur noch die Aktionen, die ich weiter oben schon genannt hatte. Danach bis zum shutdown nichts mehr.

Es ist also weiterhin so, dass VDR nicht herunterfährt, wenn während einer laufenden Aufnahme der Shutdown per Power-Button ausgelöst wird. Es war ja ursprünglich mal so, dass er den ausstehenden Shutdown unmittelbar nach Ende der letzten Aufzeichnung nachgeholt hat.

Hat noch jemand eine Idee, woran es scheitern könnte?

Falk

seahawk1986 · August 28, 2017 at 8:54 AM

Kannst du mir bitte mal ein ungekürztes Log zukommen lassen, damit ich nachvollziehen kann was Frontend-Skript und VDR da genau gemacht haben?

fnu · August 28, 2017 at 11:39 AM

Quote from spitzb

aber nach der Meldung "VDR schaltet später aus..." kamen nur noch die Aktionen, die ich weiter oben schon genannt hatte.

Ja, aber genau das halte ich für das Problem ... nach "VDR schaltet später aus..." darf nichts mehr kommen ...

Insofern arbeitet VDR korrekt.

Regards

fnu

spitzb · August 28, 2017 at 12:42 PM

Da hat seahawk1986 mir was anderes geschrieben:

Quote

Das kommt aus https://github.com/yavdr/yavdr…ter/usr/bin/frontend#L221 und soll sicher zu stellen, dass das OSD geschlossen ist, bevor der GPU-Cache des Skindesigner abgeräumt wird. Danach wird der Nutzer inaktiv gesetzt.

und danach kommt tatsächlich nichts mehr.

seahawk1986 scheint das Problem aber gefunden zu haben. Ich soll jedenfalls nach einem Update nochmal probieren.

Falk

spitzb · August 29, 2017 at 8:11 AM

Problem durch update gelöst. VDR unmittelbar nach Ende der letzten Aufzeichnung heruntergefahren.

Danke an seahawk1986

Falk

Leo · August 30, 2017 at 5:56 AM

Quote from spitzb

Problem durch update gelöst. VDR unmittelbar nach Ende der letzten Aufzeichnung heruntergefahren.

Danke an seahawk1986

Falk

Hallo,

Sorry für die dumme Frage. Wann war den das update ? War das per apt-get distupgrade ?

Welches Package ?

Habe genau das gleiche Problem, nach Aufnahme kein runterfahren.

Danke und Gruss

Leo

[Gelöst] VDR fährt nach Timeraufnahme nicht herunter

Participate now!

Users Viewing This Thread