yaVDR 0.5 Frontend detached im Play Mode -> kein Ton / keine Reaktion mehr auf FB

aragorn · 29. April 2013

Hi,

wir haben hier seit ein paar Wochen das Problem, dass das Detachen/Attachen des softhddevice mit der Fernbedienung nicht zuverlässig funktioniert.
Mit einer Ur-yavdr-Installation 0.5 ging das mehrere Monate sehr zuverlässig - und spart zwischen 7-10W

Folgene Phänomene treten dabei auf:
- VDR reagiert gar nicht mehr auf Fernbedienung -
- VDR reagiert noch auf den ersten FB Befehl, Bild kommt zurück, aber danach weder Ton noch weitere Reaktion auf FB
- VDR reagiert auf ersten FB-Befehl im ersten Moment nicht wie erwartet, falsches Menü geöffnet (selten)

Syslog - so sieht es aus, wenn "DETA" noch funktioniert, danach aber die FB gar nichts mehr bewirkt (kein "ATTA" o.ä.): :

Code

Apr 29 16:02:38 vdr vdr: [25415] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 29 16:02:38 vdr vdr: [25415] dbus2vdr: 1 idle message handler, reusing 0x7f3ee8001be0
Apr 29 16:02:38 vdr vdr: [30931] dbus2vdr message handler thread started (pid=25327, tid=30931, prio=high)
Apr 29 16:02:38 vdr vdr: [30931] dbus2vdr: invoking softhddevice.SVDRPCommand("STAT", "None")
Apr 29 16:02:38 vdr vdr: [30931] dbus2vdr: moving message handler 0x7f3ee8001be0 from active to finished
Apr 29 16:02:38 vdr vdr: [30931] dbus2vdr message handler thread ended (pid=25327, tid=30931)
Apr 29 16:02:38 vdr vdr: [25415] dbus2vdr: connection has messages to send, flushing
Apr 29 16:02:38 vdr vdr: [25415] dbus2vdr: done flushing
Apr 29 16:02:38 vdr vdr: [30933] Text2Skin: menu display update thread started (pid=25327, tid=30933, prio=high)
Apr 29 16:02:38 vdr vdr: [25327] loading menuorg config file from /var/lib/vdr/plugins/menuorg.xml
Apr 29 16:02:38 vdr vdr: [25415] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 29 16:02:38 vdr vdr: [25415] dbus2vdr: 1 idle message handler, reusing 0x7f3ee8001be0
Apr 29 16:02:38 vdr vdr: video: speed up video, droping frame
Apr 29 16:02:38 vdr vdr: video: 11:29:09.174  -15  303   0/\ms   5+5 v-buf
Apr 29 16:02:38 vdr vdr: [30934] dbus2vdr message handler thread started (pid=25327, tid=30934, prio=high)
Apr 29 16:02:38 vdr vdr: [30934] dbus2vdr: invoking softhddevice.SVDRPCommand("DETA", "None")
Apr 29 16:02:38 vdr vdr: [30934] [softhddev]SetPlayMode: 0
Apr 29 16:02:38 vdr vdr: [30934] [softhddev]SetVideoDisplayFormat: 1
Apr 29 16:02:38 vdr vdr: [30934] [softhddev]GetSpuDecoder:
Apr 29 16:02:38 vdr vdr: [30934] [softhddev]SetPlayMode: 1
Apr 29 16:02:38 vdr vdr: video: fatal i/o error
Apr 29 16:04:49 vdr vdr: [25327] [softhddev]SetVolumeDevice: 80
Apr 29 16:04:49 vdr vdr: [25327] [softhddev]SetVolumeDevice: 0
Apr 29 16:04:50 vdr vdr: [25327] [softhddev]SetVolumeDevice: 80
Apr 29 16:08:00 vdr vdr: [25405] channel 1 (Das Erste) event Mon 29.04.2013 16:00-16:10 (VPS: 29.04. 16:00) 'Tagesschau' status 1
Apr 29 16:08:01 vdr vdr: [25405] channel 1 (Das Erste) event Mon 29.04.2013 16:10-17:00 (VPS: 29.04. 16:10) 'Leopard, Seebär & Co. (138)' status 2
Apr 29 16:08:59 vdr vdr: [25405] channel 1 (Das Erste) event Mon 29.04.2013 16:10-17:00 (VPS: 29.04. 16:10) 'Leopard, Seebär & Co. (138)' status 4

Alles anzeigen

Das sind die logs, wenn es funktioniert wie es soll:

Code

Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: 1 idle message handler, reusing 0x7f8184004ac0
Apr 29 16:23:17 vdr vdr: [31733] dbus2vdr message handler thread started (pid=31269, tid=31733, prio=high)
Apr 29 16:23:17 vdr vdr: [31733] dbus2vdr: invoking softhddevice.SVDRPCommand("STAT", "None")
Apr 29 16:23:17 vdr vdr: [31733] dbus2vdr: moving message handler 0x7f8184004ac0 from active to finished
Apr 29 16:23:17 vdr vdr: [31733] dbus2vdr message handler thread ended (pid=31269, tid=31733)
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: connection has messages to send, flushing
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: done flushing
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: 1 idle message handler, reusing 0x7f8184004ac0
Apr 29 16:23:17 vdr vdr: [31735] dbus2vdr message handler thread started (pid=31269, tid=31735, prio=high)
Apr 29 16:23:17 vdr vdr: [31735] dbus2vdr: invoking softhddevice.SVDRPCommand("ATTA", "-d :1.0")
Apr 29 16:23:17 vdr vdr: [31735] [softhddev]SetPlayMode: 0
Apr 29 16:23:17 vdr vdr: [31735] [softhddev]SetVideoDisplayFormat: 1
Apr 29 16:23:17 vdr vdr: [31735] [softhddev]GetSpuDecoder:
Apr 29 16:23:17 vdr vdr: [31735] [softhddev]~cSoftHdControl: dummy player stopped
Apr 29 16:23:17 vdr vdr: video/vdpau: VDPAU API version: 1
Apr 29 16:23:17 vdr vdr: video/vdpau: VDPAU information: NVIDIA VDPAU Driver Shared Library  304.88  Wed Mar 27 14:49:27 PDT 2013
Apr 29 16:23:17 vdr vdr: video/vdpau: highest supported high quality scaling 1
Apr 29 16:23:17 vdr vdr: video/vdpau: feature deinterlace temporal supported
Apr 29 16:23:17 vdr vdr: video/vdpau: feature deinterlace temporal spatial supported
Apr 29 16:23:17 vdr vdr: video/vdpau: attribute skip chroma deinterlace supported
Apr 29 16:23:17 vdr vdr: video/vdpau: 4:2:0 chroma format with 4096x4096 supported
Apr 29 16:23:17 vdr vdr: video/vdpau: 4:2:2 chroma format with 4096x4096 supported
Apr 29 16:23:17 vdr vdr: video/vdpau: 8bit BGRA format with 16384x16384 supported
Apr 29 16:23:17 vdr vdr: video/vdpau: 10bit RGBA format with 16384x16384 supported
Apr 29 16:23:17 vdr vdr: audio: 'alsa' output module used
Apr 29 16:23:17 vdr vdr: audio/alsa: supports pause: no
Apr 29 16:23:17 vdr vdr: audio:  44100Hz supports 1 2 3 4 5 6 7 8 channels
Apr 29 16:23:17 vdr vdr: audio:  48000Hz supports 1 2 3 4 5 6 7 8 channels
Apr 29 16:23:17 vdr vdr: audio: 192000Hz supports 0 0 0 0 0 0 0 0 channels
Apr 29 16:23:17 vdr vdr: [31735] dbus2vdr: moving message handler 0x7f8184004ac0 from active to finished
Apr 29 16:23:17 vdr vdr: [31735] dbus2vdr message handler thread ended (pid=31269, tid=31735)
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: connection has messages to send, flushing
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: done flushing
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: new message, object /Remote, interface de.tvdr.vdr.remote, member Enable
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: 1 idle message handler, reusing 0x7f8184004ac0
Apr 29 16:23:17 vdr vdr: [31737] dbus2vdr message handler thread started (pid=31269, tid=31737, prio=high)
Apr 29 16:23:17 vdr vdr: [31737] dbus2vdr: moving message handler 0x7f8184004ac0 from active to finished
Apr 29 16:23:17 vdr vdr: [31737] dbus2vdr message handler thread ended (pid=31269, tid=31737)
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: connection has messages to send, flushing
Apr 29 16:23:17 vdr vdr: [31357] dbus2vdr: done flushing
Apr 29 16:23:18 vdr vdr: [31269] switching to channel 1
Apr 29 16:23:18 vdr vdr: [31715] osdteletext-receiver thread ended (pid=31269, tid=31715)
Apr 29 16:23:18 vdr vdr: [31269] buffer stats: 0 (0%) used
Apr 29 16:23:18 vdr vdr: [31716] TS buffer on device 1 thread ended (pid=31269, tid=31716)
Apr 29 16:23:18 vdr vdr: [31714] buffer stats: 139308 (2%) used
Apr 29 16:23:18 vdr vdr: [31714] receiver on device 1 thread ended (pid=31269, tid=31714)
Apr 29 16:23:18 vdr vdr: [31738] receiver on device 1 thread started (pid=31269, tid=31738, prio=high)
Apr 29 16:23:18 vdr vdr: [31740] osdteletext-receiver thread started (pid=31269, tid=31740, prio=high)
Apr 29 16:23:18 vdr vdr: [31739] TS buffer on device 1 thread started (pid=31269, tid=31739, prio=high)
Apr 29 16:23:19 vdr vdr: [31269] [softhddev]SetPlayMode: 1
Apr 29 16:23:19 vdr vdr: audio/alsa: broken driver -5 state 'OPEN'
Apr 29 16:23:19 vdr vdr: [softhddev] invalid PES video packet
Apr 29 16:23:19 vdr vdr: [softhddev] invalid PES video packet
Apr 29 16:23:19 vdr vdr: codec: buggy libav, use ffmpeg
Apr 29 16:23:20 vdr vdr: audio/alsa: broken driver -5 state 'OPEN'
Apr 29 16:23:27  vdr: last message repeated 63 times
Apr 29 16:23:27 vdr vdr: [31738] [softhddev]Clear:
Apr 29 16:23:27 vdr vdr: audio/alsa: using device 'default'
Apr 29 16:23:27 vdr vdr: [31738] ERROR: TS packet not accepted in Transfer Mode
Apr 29 16:23:27 vdr vdr: audio/alsa: start delay 336ms
Apr 29 16:23:27 vdr vdr: video: slow down video, duping frame
Apr 29 16:23:27 vdr vdr: video: decoder buffer empty, duping frame (1/282) 0 v-buf
Apr 29 16:23:27 vdr vdr: video: --:--:--.---   +0    0   0/\ms   0+5 v-buf
Apr 29 16:23:27 vdr vdr: video: decoder buffer empty, duping frame (13/282) 3 v-buf
Apr 29 16:23:27 vdr vdr: video: slow down video, duping frame
Apr 29 16:23:27 vdr vdr: video: 11:49:58.294 +105  312   0/\ms   3+7 v-buf


Apr 29 16:23:52 vdr vdr: [31357] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 29 16:23:52 vdr vdr: [31357] dbus2vdr: 1 idle message handler, reusing 0x7f8184004ac0
Apr 29 16:23:52 vdr vdr: [31741] dbus2vdr message handler thread started (pid=31269, tid=31741, prio=high)
Apr 29 16:23:52 vdr vdr: [31741] dbus2vdr: invoking softhddevice.SVDRPCommand("STAT", "None")
Apr 29 16:23:52 vdr vdr: [31741] dbus2vdr: moving message handler 0x7f8184004ac0 from active to finished
Apr 29 16:23:52 vdr vdr: [31741] dbus2vdr message handler thread ended (pid=31269, tid=31741)
Apr 29 16:23:52 vdr vdr: [31720] Text2Skin: menu display update thread ended (pid=31269, tid=31720)
Apr 29 16:23:52 vdr vdr: [31357] dbus2vdr: connection has messages to send, flushing
Apr 29 16:23:52 vdr vdr: [31357] dbus2vdr: done flushing
Apr 29 16:23:52 vdr vdr: [31357] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 29 16:23:52 vdr vdr: [31357] dbus2vdr: 1 idle message handler, reusing 0x7f8184004ac0
Apr 29 16:23:52 vdr vdr: [31743] dbus2vdr message handler thread started (pid=31269, tid=31743, prio=high)
Apr 29 16:23:52 vdr vdr: [31743] dbus2vdr: invoking softhddevice.SVDRPCommand("DETA", "None")
Apr 29 16:23:52 vdr vdr: [31743] [softhddev]SetPlayMode: 0
Apr 29 16:23:52 vdr vdr: [31743] [softhddev]SetVideoDisplayFormat: 1
Apr 29 16:23:52 vdr vdr: [31743] [softhddev]GetSpuDecoder:
Apr 29 16:23:52 vdr vdr: [31743] [softhddev]SetPlayMode: 1
Apr 29 16:23:53 vdr vdr: [31743] dbus2vdr: moving message handler 0x7f8184004ac0 from active to finished
Apr 29 16:23:53 vdr vdr: [31743] dbus2vdr message handler thread ended (pid=31269, tid=31743)
Apr 29 16:23:53 vdr vdr: [31357] dbus2vdr: connection has messages to send, flushing
Apr 29 16:23:53 vdr vdr: [31357] dbus2vdr: done flushing
Apr 29 16:23:53 vdr vdr: [31357] dbus2vdr: new message, object /Remote, interface de.tvdr.vdr.remote, member Disable
Apr 29 16:23:53 vdr vdr: [31357] dbus2vdr: 1 idle message handler, reusing 0x7f8184004ac0
Apr 29 16:23:53 vdr vdr: [31744] dbus2vdr message handler thread started (pid=31269, tid=31744, prio=high)
Apr 29 16:23:53 vdr vdr: [31744] dbus2vdr: moving message handler 0x7f8184004ac0 from active to finished
Apr 29 16:23:53 vdr vdr: [31744] dbus2vdr message handler thread ended (pid=31269, tid=31744)
Apr 29 16:23:53 vdr vdr: [31357] dbus2vdr: connection has messages to send, flushing
Apr 29 16:23:53 vdr vdr: [31357] dbus2vdr: done flushing

Alles anzeigen

Man kann nach dem VDR restart normalerweise mehrere Male attachen und detachen, ohne dass sich das Verhalten provozieren lässt.
Nach ein paar Stunden ist dann aber die FB nicht mehr als Trigger zu benutzen. Irgendwo ist da der Wurm drin.

Irgendeine Idee, wo sich ansetzen ließe?

vg, aragorn

Boss666 · 29. April 2013

Kleiner Querverweis, da vermutlich gleiche Problematik.

seahawk1986 · 29. April 2013

Zitat von aragorn

Irgendeine Idee, wo sich ansetzen ließe?

Klappt denn in dem Zusand ein manuelles Attachen?

Code

vdr-dbus-send /Plugins/softhddevice plugin.SVDRPCommand string:atta
# bzw. mit svdrpsend
svdrpsend plug softhddevice atta

aragorn · 29. April 2013

Jetzt hatte ich wieder so einen undefinierten vdr-Zustand.
Haben eine Aufnahme abgespielt, während laufender Wiedergabe das Frontend detached (die Kinder)
Screensaver Bild (Frontend detached) erscheint.

10min später schaltet der nächste den TV ein - Bild läuft (live TV) , aber kein Ton, keine FB.
Erwartet hätte ich immer noch den Screensaver.

Wenn ich jetzt folgenden Befehl absetze:

Code

root@vdr:~# svdrpsend plug softhddevice deta
220 vdr SVDRP VideoDiskRecorder 2.0.1; Mon Apr 29 19:22:21 2013; UTF-8
900 SoftHdDevice already detached
221 vdr closing connection
root@vdr:~#

denkt der vdr offenbar, dass das frontend noch detached ist - aber das Bild ist ja (wieder) da.

Weitere Reanimations-Versuche:

Code

root@vdr:~# svdrpsend plug softhddevice atta
220 vdr SVDRP VideoDiskRecorder 2.0.1; Mon Apr 29 19:27:23 2013; UTF-8
timeout
root@vdr:~# vdr-dbus-send /Plugins/softhddevice plugin.SVDRPCommand string:atta
Error org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
root@vdr:~# vdr-dbus-send /Plugins/softhddevice plugin.SVDRPCommand string:deta
method return sender=:1.121 -> dest=:1.123 reply_serial=2
   int32 900
   string "SoftHdDevice already detached"
root@vdr:~#

Dachte also, aus der Nummer komme ich ohne vdr restart nicht mehr raus, bin zum PC, habe angefangen diesen Thread zu verlängern.
Nach 2-3min aber TV-Ton im Hintergrund:

Code

Apr 29 19:28:37 vdr vdr: [902] Text2Skin: channelInfo display update thread ended (pid=791, tid=902)
Apr 29 19:28:38 vdr vdr: [874] channel 20 (neo/KiKA) event Mon 29.04.2013 19:25-19:50 (VPS: 29.04. 19:25) 'Die beste Klasse Deutschlands' status 4
Apr 29 19:28:38 vdr vdr: [871] channel 18 (PHOENIX) event Mon 29.04.2013 19:15-20:00 (VPS: 29.04. 19:15) 'Der Fall Borgia' status 4
Apr 29 19:28:38 vdr vdr: [886] EPGSearch: search timer update finished
Apr 29 19:28:38 vdr vdr: [874] channel 2 (ZDF) event Mon 29.04.2013 19:25-20:15 (VPS: 29.04. 19:25) 'WISO' status 4
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Plugins/softhddevice, interface org.freedesktop.DBus.Introspectable, member Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: introspect object /Plugins/softhddevice with Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Remote, interface org.freedesktop.DBus.Introspectable, member Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: introspect object /Remote with Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Shutdown, interface org.freedesktop.DBus.Introspectable, member Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: introspect object /Shutdown with Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Setup, interface org.freedesktop.DBus.Introspectable, member Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: introspect object /Setup with Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Timers, interface org.freedesktop.DBus.Introspectable, member Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: introspect object /Timers with Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Shutdown, interface de.tvdr.vdr.shutdown, member ManualStart
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: starting new message handler 0x7f9a08001be0
Apr 29 19:28:39 vdr vdr: [935] dbus2vdr message handler thread started (pid=791, tid=935, prio=high)
Apr 29 19:28:39 vdr vdr: [935] dbus2vdr: moving message handler 0x7f9a08001be0 from active to finished
Apr 29 19:28:39 vdr vdr: [935] dbus2vdr message handler thread ended (pid=791, tid=935)
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: connection has messages to send, flushing
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: done flushing
Apr 29 19:28:39 vdr vdr-frontend[931]: acip-wakeup.time.old hatte Wert: Thu Apr 18 17:44:00 2013
Apr 29 19:28:39 vdr vdr-frontend[931]: vergleiche mit jetzt: Mon Apr 29 17:28:39 2013
Apr 29 19:28:39 vdr vdr-frontend[931]: assuming manual start
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Plugins, interface org.freedesktop.DBus.Introspectable, member Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: introspect object /Plugins with Introspect
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: can't introspect object /Plugins
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: new message, object /Plugins, interface de.tvdr.vdr.plugin, member List
Apr 29 19:28:39 vdr vdr: [876] dbus2vdr: 1 idle message handler, reusing 0x7f9a08001be0
Apr 29 19:28:39 vdr vdr: [936] dbus2vdr message handler thread started (pid=791, tid=936, prio=high)
Apr 29 19:28:39 vdr rsyslogd-2177: imuxsock begins to drop messages from pid 791 due to rate-limiting
Apr 29 19:28:39 vdr vdr-frontend[931]: started udev monitoring of input devices
Apr 29 19:28:40 vdr vdr-frontend[931]: conntected to Lirc-Socket on /var/run/lirc/lircd
Apr 29 19:28:43 vdr rsyslogd-2177: imuxsock lost 65 messages from pid 791 due to rate-limiting
Apr 29 19:28:43 vdr vdr: audio/alsa: broken driver -5 state 'OPEN'
Apr 29 19:28:48  vdr: last message repeated 51 times
Apr 29 19:28:48 vdr vdr: [899] [softhddev]Clear:
Apr 29 19:28:48 vdr vdr: audio/alsa: using device 'default'
Apr 29 19:28:48 vdr vdr: [899] ERROR: TS packet not accepted in Transfer Mode
Apr 29 19:28:48 vdr vdr: audio/alsa: start delay 336ms
Apr 29 19:28:48 vdr vdr: video: decoder buffer empty, duping frame (1/296) 0 v-buf
Apr 29 19:28:48 vdr vdr: video: --:--:--.---   +0    0   0/\ms   0+5 v-buf
Apr 29 19:28:48 vdr vdr: video: decoder buffer empty, duping frame (19/296) 0 v-buf
Apr 29 19:28:48 vdr vdr: video: slow down video, duping frame
Apr 29 19:28:48 vdr vdr: video: 14:55:19.334 +114  353   0/\ms   3+7 v-buf
Apr 29 19:29:40 vdr vdr: video: slow down video, duping frame
Apr 29 19:29:40 vdr vdr: video: 14:56:10.874  +14  337   0/\ms   3+7 v-buf
Apr 29 19:30:00 vdr vdr: [908] recording thread ended (pid=791, tid=908)
Apr 29 19:30:01 vdr vdr: [910] TS buffer on device 2 thread ended (pid=791, tid=910)
Apr 29 19:30:01 vdr vdr: [909] buffer stats: 81216 (1%) used
Apr 29 19:30:01 vdr vdr: [909] receiver on device 2 thread ended (pid=791, tid=909)
Apr 29 19:30:01 vdr vdr: [791] buffer stats: 1608152 (7%) used
Apr 29 19:30:01 vdr vdr: [791] timer 45 (2 1858-1930 'Nachrichten~heute') stop
Apr 29 19:30:01 vdr vdr: [791] markad: deactivated by user
Apr 29 19:30:01 vdr vdr: [791] executing '/usr/lib/vdr/vdr-recordingaction after "/srv/vdr/video.00/Nachrichten/heute/2013-04-29.18.58.2-0.rec"'
Apr 29 19:30:24 vdr vdr: [871] channel 9 (arte) event Mon 29.04.2013 19:10-19:30 (VPS: 29.04. 19:10) 'ARTE Journal' status 1
Apr 29 19:30:24 vdr vdr: [871] channel 9 (arte) event Mon 29.04.2013 19:30-20:15 (VPS: 29.04. 19:30) 'Geparde - Afrikas elegante Jäger' status 2

Alles anzeigen

Ton und FB sind - nach mehreren Minuten - nun wieder da - alles ok.
Und nun?

Edit: Watchdog übersehen
Der vdr war offenbar schon angeschossen...

Code

Apr 29 19:28:23 vdr vdr: [31269] PANIC: watchdog timer expired - exiting!
Apr 29 19:28:23 vdr vdr: [31366] fatal error, server exiting: Bad file descriptor
Apr 29 19:28:23 vdr vdr: [31366] streamdev server thread ended (pid=31269, tid=31366)
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.channel
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.epg
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.osd
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.plugin
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.recording
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.remote
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.setup
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.shutdown
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.skin
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.timer
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.recording
Apr 29 19:28:23 vdr vdr: [31269] dbus2vdr: deleting message dispatcher for interface de.tvdr.vdr.timer
Apr 29 19:28:26 vdr vdr: [31269] ERROR: dbus2vdr message handler thread 352 won't end (waited 3 seconds) - canceling it...
Apr 29 19:28:29 vdr vdr: [31269] ERROR: dbus2vdr message handler thread 777 won't end (waited 3 seconds) - canceling it...
Apr 29 19:28:29 vdr vdr: [354] osdteletext-receiver thread ended (pid=31269, tid=354)
Apr 29 19:28:29 vdr vdr: [31269] buffer stats: 0 (0%) used
Apr 29 19:28:29 vdr kernel: [911246.909841] init: vdr main process (31269) terminated with status 1
Apr 29 19:28:29 vdr kernel: [911246.913680] init: vdr-frontend main process (31397) killed by TERM signal
Apr 29 19:28:29 vdr vdr-crash: vdr exit with exit status 1 . Restarting
Apr 29 19:28:29 vdr kernel: [911247.105059] init: vdr-exit-other main process (787) terminated with status 1
Apr 29 19:28:30 vdr vdr: [791] VDR version 2.0.1 started

Alles anzeigen

vg, aragorn

seahawk1986 · 29. April 2013

Zitat von aragorn

Apr 29 19:28:39 maxvdr rsyslogd-2177: imuxsock begins to drop messages from pid 791 due to rate-limiting

Das sieht für mich aber so aus als ob da noch einiges passiert ist, was nicht im Log gelandet ist (wohl ein Crash des VDR?)
Kannst du mal die /etc/rsyslog.conf so abändern, damit man in Zukunft sieht was da passiert? http://paste.ubuntu.com/5616646/

Warum der VDR und/oder softhddevice da hängen bleiben weiß ich nicht - evtl. kannst du mal versuchen in der device-Section der /etc/X11/xorg.conf.yavdr die Hotplug Events abzuschalten, um da Probleme durch einen Modus-Wechsel zu vermeiden.

Code

Option         "UseHotplugEvents" "False"

Ach ja - ist das softhddevice-Plugin so eingestellt, dass es die X-Ressourcen freigibt wenn es detached oder suspended wird?

aragorn · 29. April 2013

Zitat von seahawk1986
Warum der VDR und/oder softhddevice da hängen bleiben weiß ich nicht - evtl. kannst du mal versuchen in der device-Section der /etc/X11/xorg.conf.yavdr die Hotplug Events abzuschalten, um da Probleme durch einen Modus-Wechsel zu vermeiden.
Code
Option         "UseHotplugEvents" "False"
Ach ja - ist das softhddevice-Plugin so eingestellt, dass es die X-Ressourcen freigibt wenn es detached oder suspended wird?

Meinst du das hier:
"Unterbrechen schließt Video+Audio: Ja"
"Unterbrechen stoppt X-Server: Nein"

Die Ursache kann ich jetzt übrigens nachvollziehen:

Wenn ich das softhddevice detache bei laufender Wiedergabe einer Aufnahme, geht es kaputt wie oben beschrieben.
Um dieses Verhalten zu umgehen, müsste man die Wiedergabe einen Schritt vor dem Detach stoppen - entweder im Detach-Script oder im Plugin selbst?

Detache ich während live TV, funktioniert's nämlich zuverlässig.

vg, aragon

seahawk1986 · 29. April 2013

Ok, die Konstellation sollte IMHO besser das Plugin abfangen - mit der aktuellen Version unter Arch Linux beendet sich die Wiedergabe, wenn ich das Frontend detache und es lässt sich wieder attachen. Am yaVDR kann ich es gerade nicht testen.
Als Workaround könntest du hier https://github.com/yavdr/yavdr…ddevice-02-script.py#L129
das einfügen:

Code

remote.sendkey("STOP")

(Mit so vielen Leerzeichen am Anfang der Zeile, dass es bündig ist)

aragorn · 29. April 2013

Zitat von seahawk1986
Code
remote.sendkey("STOP")

das scheint so nicht zu funktionieren - ich vermute es ist ein Timing-Problem ("STOP" nicht schnell genug).
danke, ich schaue mal weiter...

vg, aragorn

seahawk1986 · 29. April 2013

Magst du das mal mit einer aktuellen softhddevice-Version probieren?
Für stable:
https://launchpad.net/~seahawk…15/+listing-archive-extra
für testing:
https://launchpad.net/~seahawk…16/+listing-archive-extra

aragorn · 30. April 2013

hab ich gemacht - mit 0.6. ändert sich erstmal nichts - vdr crasht oder FB/Ton kommt nicht wieder:

Code

Apr 29 23:13:55 vdr vdr: [7441] dbus2vdr: invoking softhddevice.SVDRPCommand("DETA", "None")
Apr 29 23:13:55 vdr vdr: [7441] [softhddev]SetPlayMode: 0
Apr 29 23:13:55 vdr vdr: [7441] [softhddev]SetVideoDisplayFormat: 1
Apr 29 23:13:55 vdr vdr: [7441] [softhddev]GetSpuDecoder:
Apr 29 23:13:55 vdr vdr: [7441] [softhddev]SetPlayMode: 1
Apr 29 23:13:55 vdr vdr: video/vdpau: can't block queue: An invalid handle value was provided.
Apr 29 23:13:55 vdr vdr: video/vdpau: can't render output surface: An invalid handle value was provided.
Apr 29 23:13:55 vdr vdr: video/vdpau: can't queue display: An invalid handle value was provided.
Apr 29 23:13:55 vdr kernel: [48018.179702] Text2Skin: menu[7442]: segfault at 0 ip 00007f74af6525b6 sp 00007f744c98cc40 error 4 in libxcb.so.1.1.0[7f74af648000+1d000]
Apr 29 23:13:55 vdr kernel: [48018.284295] init: vdr main process (6595) killed by SEGV signal
Apr 29 23:13:55 vdr kernel: [48018.285297] init: vdr-frontend main process (6724) killed by TERM signal
Apr 29 23:13:55 vdr vdr-crash: vdr exit with signal SEGV . Restarting
Apr 29 23:13:55 vdr kernel: [48018.383440] init: vdr-exit-other main process (7452) terminated with status 1
Apr 29 23:13:55 vdr vdr: [7456] VDR version 2.0.1 started
Apr 29 23:13:55 vdr vdr: [7456] switched to user 'vdr'
Apr 29 23:13:55 vdr vdr: [7456] codeset is 'UTF-8' - known

Alles anzeigen

oder auch:

Code

Apr 30 00:37:54 vdr vdr: [5318] replay /srv/vdr/video.00/ttt_-_titel_thesen_temperamente/Kulturmagazin/2013-04-28.23.03.1-0.rec
Apr 30 00:37:54 vdr vdr: [5318] playing '/srv/vdr/video.00/ttt_-_titel_thesen_temperamente/Kulturmagazin/2013-04-28.23.03.1-0.rec/00001.ts'
Apr 30 00:37:54 vdr vdr: [5318] [softhddev]SetPlayMode: 1
Apr 30 00:37:54 vdr vdr: [5725] dvbplayer thread started (pid=5318, tid=5725, prio=high)
Apr 30 00:37:54 vdr vdr: [5725] resuming replay at index 15783 (0:10:31.09)
Apr 30 00:37:54 vdr vdr: [5726] non blocking file reader thread started (pid=5318, tid=5726, prio=high)
Apr 30 00:37:54 vdr vdr: audio/alsa: using device 'default'
Apr 30 00:37:54 vdr vdr: audio/alsa: start delay 336ms
Apr 30 00:37:54 vdr vdr: codec: buggy libav, use ffmpeg
Apr 30 00:37:56 vdr vdr: [softhddev] empty video packet 115 bytes
Apr 30 00:38:03 vdr vdr: [5406] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 30 00:38:03 vdr vdr: [5406] dbus2vdr: 1 idle message handler, reusing 0x7fa318001c60
Apr 30 00:38:03 vdr vdr: [5727] dbus2vdr message handler thread started (pid=5318, tid=5727, prio=high)
Apr 30 00:38:03 vdr vdr: [5727] dbus2vdr: invoking softhddevice.SVDRPCommand("STAT", "None")
Apr 30 00:38:03 vdr vdr: [5727] dbus2vdr: moving message handler 0x7fa318001c60 from active to finished
Apr 30 00:38:03 vdr vdr: [5727] dbus2vdr message handler thread ended (pid=5318, tid=5727)
Apr 30 00:38:03 vdr vdr: [5406] dbus2vdr: connection has messages to send, flushing
Apr 30 00:38:03 vdr vdr: [5406] dbus2vdr: done flushing
Apr 30 00:38:03 vdr vdr: [5729] Text2Skin: menu display update thread started (pid=5318, tid=5729, prio=high)
Apr 30 00:38:04 vdr vdr: [5406] dbus2vdr: new message, object /Remote, interface de.tvdr.vdr.remote, member HitKey
Apr 30 00:38:04 vdr vdr: [5406] dbus2vdr: 1 idle message handler, reusing 0x7fa318001c60
Apr 30 00:38:04 vdr vdr: [5731] dbus2vdr message handler thread started (pid=5318, tid=5731, prio=high)
Apr 30 00:38:04 vdr vdr: [5731] dbus2vdr: de.tvdr.vdr.remote.HitKey: get key 'STOP'
Apr 30 00:38:04 vdr vdr: [5731] dbus2vdr: moving message handler 0x7fa318001c60 from active to finished
Apr 30 00:38:04 vdr vdr: [5731] dbus2vdr message handler thread ended (pid=5318, tid=5731)
Apr 30 00:38:04 vdr vdr: [5406] dbus2vdr: connection has messages to send, flushing
Apr 30 00:38:04 vdr vdr: [5406] dbus2vdr: done flushing
Apr 30 00:38:04 vdr vdr: [5406] dbus2vdr: new message, object /Plugins/softhddevice, interface de.tvdr.vdr.plugin, member SVDRPCommand
Apr 30 00:38:04 vdr vdr: [5406] dbus2vdr: 1 idle message handler, reusing 0x7fa318001c60
Apr 30 00:38:04 vdr vdr: [5732] dbus2vdr message handler thread started (pid=5318, tid=5732, prio=high)
Apr 30 00:38:04 vdr vdr: [5732] dbus2vdr: invoking softhddevice.SVDRPCommand("DETA", "None")
Apr 30 00:38:04 vdr vdr: [5732] [softhddev]SetPlayMode: 0
Apr 30 00:38:04 vdr vdr: [5732] [softhddev]SetVideoDisplayFormat: 1
Apr 30 00:38:04 vdr vdr: [5732] [softhddev]GetSpuDecoder:
Apr 30 00:38:04 vdr vdr: [5414] XVDR: Recordings state changed (550)
Apr 30 00:38:04 vdr vdr: [5414] XVDR: Requesting clients to reload recordings list
Apr 30 00:38:04 vdr kernel: [42275.725707] init: vdr main process (5318) killed by ABRT signal
Apr 30 00:38:04 vdr kernel: [42275.727390] init: vdr-frontend main process (5454) killed by TERM signal
Apr 30 00:38:04 vdr vdr-crash: vdr exit with signal ABRT . Restarting
Apr 30 00:38:04 vdr kernel: [42276.021378] init: vdr-exit-other main process (5742) terminated with status 1
Apr 30 00:38:05 vdr vdr: [5746] VDR version 2.0.1 started

Alles anzeigen

vg,
aragorn

seahawk1986 · 30. April 2013

Komisch, ich hab es hier gerade ausprobiert, da klappt es...
Siehst du irgendwelche HDMI-Events im Syslog, wenn der TV aus- oder eingeschaltet wird?

aragorn · 30. April 2013

nein - sehe keine HDMI events bei Ein- oder Ausschalten des TV.

wenn die FB und der Ton nicht zurückkommen - kann man im syslog daran erkennen, dass folgende Zeilen (nach den VDPAU messages) ganz fehlen.
Ich habe die Log-Einträge mal per Leerzeilen abgesetzt:

Code

Apr 30 11:58:26 vdr vdr: [8830] dbus2vdr: invoking softhddevice.SVDRPCommand("ATTA", "-d :1.0")
Apr 30 11:58:26 vdr vdr: [8830] [softhddev]SetPlayMode: 0
Apr 30 11:58:26 vdr vdr: [8830] [softhddev]SetVideoDisplayFormat: 1
Apr 30 11:58:26 vdr vdr: [8830] [softhddev]GetSpuDecoder:
Apr 30 11:58:26 vdr vdr: [8830] [softhddev]~cSoftHdControl: dummy player stopped
Apr 30 11:58:26 vdr vdr: video/vdpau: VDPAU API version: 1
Apr 30 11:58:26 vdr vdr: video/vdpau: VDPAU information: NVIDIA VDPAU Driver Shared Library  304.88  Wed Mar 27 14:49:27 PDT 2013
Apr 30 11:58:26 vdr vdr: video/vdpau: highest supported high quality scaling 1
Apr 30 11:58:26 vdr vdr: video/vdpau: feature deinterlace temporal supported
Apr 30 11:58:26 vdr vdr: video/vdpau: feature deinterlace temporal spatial supported
Apr 30 11:58:26 vdr vdr: video/vdpau: attribute skip chroma deinterlace supported
Apr 30 11:58:26 vdr vdr: video/vdpau: 4:2:0 chroma format with 4096x4096 supported
Apr 30 11:58:26 vdr vdr: video/vdpau: 4:2:2 chroma format with 4096x4096 supported
Apr 30 11:58:26 vdr vdr: video/vdpau: 8bit BGRA format with 16384x16384 supported
Apr 30 11:58:26 vdr vdr: video/vdpau: 10bit RGBA format with 16384x16384 supported
Apr 30 11:58:26 vdr vdr: audio: 'alsa' output module used


Apr 30 11:58:26 vdr vdr: audio/alsa: supports pause: no
Apr 30 11:58:27 vdr vdr: audio:  44100Hz supports 1 2 3 4 5 6 7 8 channels
Apr 30 11:58:27 vdr vdr: audio:  48000Hz supports 1 2 3 4 5 6 7 8 channels
Apr 30 11:58:27 vdr vdr: audio: 192000Hz supports 0 0 0 0 0 0 0 0 channels
Apr 30 11:58:27 vdr vdr: [8830] dbus2vdr: moving message handler 0x7ffb00001be0 from active to finished
Apr 30 11:58:27 vdr vdr: [8830] dbus2vdr message handler thread ended (pid=8469, tid=8830)
Apr 30 11:58:27 vdr vdr: [8557] dbus2vdr: connection has messages to send, flushing
Apr 30 11:58:27 vdr vdr: [8557] dbus2vdr: done flushing
Apr 30 11:58:27 vdr vdr: [8557] dbus2vdr: new message, object /Remote, interface de.tvdr.vdr.remote, member Enable
Apr 30 11:58:27 vdr vdr: [8557] dbus2vdr: 1 idle message handler, reusing 0x7ffb00001be0
Apr 30 11:58:27 vdr vdr: [8833] dbus2vdr message handler thread started (pid=8469, tid=8833, prio=high)
Apr 30 11:58:27 vdr vdr: [8833] dbus2vdr: moving message handler 0x7ffb00001be0 from active to finished
Apr 30 11:58:27 vdr vdr: [8833] dbus2vdr message handler thread ended (pid=8469, tid=8833)
Apr 30 11:58:27 vdr vdr: [8557] dbus2vdr: connection has messages to send, flushing
Apr 30 11:58:27 vdr vdr: [8557] dbus2vdr: done flushing


Apr 30 11:58:27 vdr vdr: [8469] switching to channel 2

Alles anzeigen

wenn Ton und FB fehlen, dann fehlt auch der entsprechende Teil im syslog:

Code

Apr 30 11:59:58 vdr vdr: video/vdpau: 10bit RGBA format with 16384x16384 supported
Apr 30 11:59:58 vdr vdr: audio: 'alsa' output module used


Apr 30 11:59:58 vdr vdr: [8469] switching to channel 1

kein Ton, wenn er durch den alsa Teil nicht durchkommt.
und dann "vergisst" er im nächsten Schritt, die FB einzuschalten - vermutlich, weil er an der Stelle hängt?

SoS · 27. Januar 2014

Hallo,

auch wenn der Fred schon etwas älter ist ... hat jemand dazu nun eine Lösung gefunden?

Ich habe das Problem auch schon länger und wollte das jetzt mal angehen, da Frau und
Kinder langsam genervt sind

Danke!

SoS

johns · 27. Januar 2014

In yaVDR ist mein Patch mit dem Fix für Audio drin.
Vielleicht hilft der auch bei diesem Problem.

Mal softhddevice aus einem anderen Reposit testen,
ich vermute mal, daß der Patch nur in testing drin ist.

Ansonsten Plugin aus GIT + Patch selber bauen.

Johns

utiltiy · 27. Januar 2014

Zitat von johns

In yaVDR ist mein Patch mit dem Fix für Audio drin.
...
ich vermute mal, daß der Patch nur in testing drin ist.

Man kann auch, falls dies zutrifft, das Paket händisch herunterladen und manuell am betroffenen System installieren. Man spart sich dann den Paketbau.

SoS · 27. Januar 2014

... dabei bin ich erst vor ein paar Monaten auf stable zurückgegangen, nachdem es ein paar Mal Stress nach Updates gab ..

Weiß jemand, ob und wann der Patch in stable kommt?

Danke.

mini73 · 27. Januar 2014

Man spart sich nie den Paketbau, wenn man ein Plugin aus einem anderem PPA holt.
Der vdr in stable hat eine andere ABI als der vdr in testing.

Das geht so schnell mit dget...

Lars

yaVDR 0.5 Frontend detached im Play Mode -> kein Ton / keine Reaktion mehr auf FB

Jetzt mitmachen!

Teilen

Tags