SVDRP ignores EOF (clientside close)

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



vdr-bounces@xxxxxxxxxxx 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.linuxtv.org/pipermail/vdr/attachments/20060720/1f7b655e/attachment.htm

[Index of Archives]     [Linux Media]     [Asterisk]     [DCCP]     [Netdev]     [Xorg]     [Util Linux NG]     [Xfree86]     [Big List of Linux Books]     [Fedora Users]     [Fedora Women]     [ALSA Devel]     [Linux USB]

  Powered by Linux