vdr-bounces@linuxtv.org schrieb am 19.07.2006 18:04:16:

> On Wed, 19 Jul 2006 15:43:22 +0200, Peter Dittmann wrote
> > Could this be the cause of the watchdog exit I get more or less
> > regularly when my infosat/tvm2vdr.pl scripts are sending  status
> > updates via SVDRP ? Afaik could this cause the watchdog to fire when
> > another SVDRP command comes in ?
> >
> > The script does a little more status messages than the original
> > scripts. SVDRP messages are send around each ~30sec.
> >
> > However I may give your suggestion a try.
> > I would happily live again with a broken pipe instead of the exit ;-)
>
> Hi Peter,
>
> I doubt it will change anything for you, but you never know... To find out if
> really SVDRP itself is responsible, I'd suggest to add some syslog calls to
> cSVDRP::Process. Check how much time it spends in there.
>
The log already shows it's triggered by SVDRP.
SVDRP command is send but not received correctly.
VDR did not log here that he received the MESG command but the log tells the SVDRP connection was opened.
30sec later (at a watchdog timout of 30) I get the emergency exit.

Here a small log:

Jul 13 04:00:01 vdr /USR/SBIN/CRON[4117]: (root) CMD (   /usr/bin/infosat.sh)
Jul 13 04:00:01 vdr vdr[1401]: connect from 127.0.0.1, port 32770 - accepted
Jul 13 04:00:01 vdr vdr[1401]: SVDRP message: 'EPG Update started'
Jul 13 04:00:01 vdr vdr[1401]: info: EPG Update started
Jul 13 04:00:01 vdr vdr[1401]: closing SVDRP connection
Jul 13 04:00:01 vdr vdr[1401]: connect from 127.0.0.1, port 32771 - accepted
Jul 13 04:00:01 vdr vdr[1401]: switching to channel 5633
Jul 13 04:00:01 vdr vdr[2419]: TS buffer on device 1 thread ended (pid=2419, tid=213006)
Jul 13 04:00:01 vdr vdr[2418]: buffer stats: 11092 (0%) used
Jul 13 04:00:01 vdr vdr[2418]: receiver on device 1 thread ended (pid=2418, tid=196621)
Jul 13 04:00:01 vdr vdr[1401]: buffer stats: 0 (0%) used
Jul 13 04:00:02 vdr vdr[1401]: closing SVDRP connection
Jul 13 04:00:07 vdr vdr[1401]: ERROR: can't open XPM file '/var/lib/vdrdevel/plugins/skinelchi/logos/RADIOROPA-BERLIN.xpm'
Jul 13 04:00:08 vdr vdr[1411]: changing portal name of channel 511 from '' to 'Info Tafel'
Jul 13 04:00:08 vdr vdr[1411]: linking channel 511 from none to 5001 5634 5162 5163 5758
Jul 13 04:00:08 vdr vdr[1411]: changing portal name of channel 509 from '' to 'Direkt Portal'
Jul 13 04:00:08 vdr vdr[1411]: changing name of channel 5005 from 'D 1 - 20:30,;' to 'D 1 - 02:30,;'
Jul 13 04:00:08 vdr vdr[1411]: changing name of channel 5616 from 'D 1 - 21:00,;' to 'D 1 - 03:00,;'
Jul 13 04:00:08 vdr vdr[1411]: changing name of channel 5635 from 'D 2 - 20:30,;' to 'D 2 - 03:15,;'
Jul 13 04:00:08 vdr vdr[1411]: changing name of channel 5008 from 'D 3 - 20:30,;' to 'D 3 - 03:15,;'
Jul 13 04:00:08 vdr vdr[1411]: changing name of channel 5010 from 'D 4 - 20:30,;' to 'D 4 - 03:15,;'
Jul 13 04:00:08 vdr vdr[1411]: linking channel 509 from none to 5005 5616 5635 5008 5010
Jul 13 04:01:02 vdr vdr[1401]: connect from 127.0.0.1, port 32772 - accepted
Jul 13 04:01:02 vdr vdr[1401]: SVDRP message: 'Infosat:Received    0 of 1500 data blocks [  0.00%]'

>> this is normal flow, connect and report SVDRP message

Jul 13 04:01:02 vdr vdr[1401]: info: Infosat:Received    0 of 1500 data blocks [  0.00%]
Jul 13 04:01:02 vdr vdr[1401]: closing SVDRP connection
Jul 13 04:01:02 vdr vdr[1401]: connect from 127.0.0.1, port 32773 - accepted

>> This should be an SVDRP CHAN 1

Jul 13 04:01:02 vdr vdr[1401]: switching to channel 1
Jul 13 04:01:02 vdr vdr[1401]: graphlcd plugin: logo /var/lib/vdrdevel/plugins/graphlcd/logos/DAS ERSTE_l.glcd loaded. delay 2
Jul 13 04:01:02 vdr vdr[1401]: creating directory /var/cache/vdr/vtx/S19.2E-1-1101-28106
Jul 13 04:01:02 vdr vdr[4460]: receiver on device 1 thread started (pid=4460, tid=245773)
Jul 13 04:01:02 vdr vdr[4461]: TS buffer on device 1 thread started (pid=4461, tid=262158)
Jul 13 04:01:02 vdr vdr[1401]: closing SVDRP connection

>> I'm personally missing here a second SVDRP HITK POWER

Jul 13 04:01:57 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:02:20 vdr vdr[1411]: changing name of channel 1041 from 'NDR 90,3;ARD NDR' to 'NDR 90,3,;ARD NDR'
Jul 13 04:02:20 vdr vdr[1411]: changing name of channel 1053 from 'radioBERLIN 88,8;ARD rbb' to 'radioBERLIN 88,8,;ARD rbb'
Jul 13 04:02:56 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:03:57 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:04:56 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:05:01 vdr /USR/SBIN/CRON[5629]: (root) CMD (   run-parts --report /etc/cron.hourly)
Jul 13 04:05:58 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:06:56 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:07:58 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:08:57 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:09:46 vdr vdr[1401]: connect from 127.0.0.1, port 32774 - accepted

>> this is possibly VDRADMIN

Jul 13 04:09:57 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:10:01 vdr /USR/SBIN/CRON[7221]: (root) CMD (test -x /usr/sbin/anacron || run-parts --report /etc/cron.daily)
Jul 13 04:10:05 vdr vdr[1401]: max. latency time 19 seconds
Jul 13 04:10:27 vdr vdr[1401]: closing SVDRP connection
Jul 13 04:10:55 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:11:57 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:12:07 vdr vdr[1411]: changing pids of channel 5015 from 160+160:80=fra:0 to 160+160:80=fra,81=eng:32
Jul 13 04:12:07 vdr vdr[1411]: changing caids of channel 5015 from 500,100 to 100
Jul 13 04:12:56 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:13:58 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:14:43 vdr vdr[1411]: changing caids of channel 531 from 100 to 0
Jul 13 04:14:56 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:15:56 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:16:58 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:17:56 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:18:55 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204
Jul 13 04:19:58 vdr vdr[1408]: changing pids of channel 5013 from 901+901:902:204 to 701+701:702:204
Jul 13 04:20:29 vdr vdr[1401]: connect from 127.0.0.1, port 32775 - accepted

>> next connect

Jul 13 04:20:58 vdr vdr[1408]: changing pids of channel 5013 from 701+701:702:204 to 901+901:902:204

>> 60sec later we get the PANIC

Jul 13 04:21:31 vdr vdr[1401]: PANIC: watchdog timer expired - exiting!
Jul 13 04:21:31 vdr lircd 0.7.1pre2[840]: removed client
Jul 13 04:21:31 vdr vdr[2416]: KBD remote control thread ended (pid=2416, tid=163851)
Jul 13 04:21:32 vdr vdr[2405]: graphlcd plugin: Display update thread ended (pid=2405)
Jul 13 04:21:32 vdr vdr[4461]: TS buffer on device 1 thread ended (pid=4461, tid=262158)
Jul 13 04:21:32 vdr vdr[4460]: buffer stats: 10152 (0%) used
Jul 13 04:21:32 vdr vdr[4460]: receiver on device 1 thread ended (pid=4460, tid=245773)
Jul 13 04:21:32 vdr vdr[1401]: buffer stats: 0 (0%) used
Jul 13 04:21:32 vdr runvdrdevel: restarting VDR
Jul 13 04:21:37 vdr kernel: saa7146: unregister extension 'dvb'.

I't not realy clear what kills VDR.
But it seems to be triggered by SVDRP.

P.S. It's a vdr 1.3.24, the scripts are placing a high stress as they never exit SVDRP correctly.
Besides I still see a lot of broken pipes for SVDRP too, mainly comming from VDRAdmin.

kind regards   Peter