Tanja wrote: Moved from users:
> Hi Duncan, > >> However, I'm having big problems with recording, after the first call to >> the subprocess Popen when called from the recordserver (should not >> affect the ivtv_record) it does not work any more. So can you let me >> know if you are having problems. It could be that each call with kaa.rpc >> is creating a new connection which is not being closed. >> > > I am also having some strange problems with recording (generic_record.py > with DVB). > > If I schedule something in the near future and my freevo box stays > running until the recording starts, then the recording seems to work as > expected. But when I shutdown the system before the > recordings should start, then it is not working. > The system is booting at the correct time and the recordserver noticing > the scheduled recording, > the RECORD_START event is emitted, the lockfile is written, the fxd file > is written and ChildApp > is initialized with the right command string to call mplayer for the > recording. > But for some reason mplayer is never called. There is not file created > by mplayer --dumpfile and > there are no messages in mplayer-stderr.log and mplayer-stdout.log, > although this files are newly > generated. > > Here you see a part of my logs (from recordserver.log): > > 2008-02-28 20:12:45,013 DEBUG recordserver.py (158): in findOverlaps > 2008-02-28 20:12:45,015 DEBUG recordserver.py (294): saving cached > file (/var/cache/freevo/record_schedule.xml) with 5 items > 2008-02-28 20:12:45,103 INFO recordserver.py (943): start recording: > Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abe > nteuer > 2008-02-28 20:12:45,105 DEBUG channels.py (155): > tunerSetFreq(chan='NDR', isplayer=False, app='record plugin', app_cmd=None > 2008-02-28 20:12:45,106 DEBUG generic_record.py (104): > Recorder::Record: /usr/bin/mplayer -dumpstream -dumpfile /media/Tv/L_nder_ > -_Menschen_-_Abenteuer_-_Irlands_rauer_Westen_-_Connemara_28-02_2015.ts > dvb://NDR > 2008-02-28 20:12:45,608 DEBUG generic_record.py (154): > Record_Thread::run: mode=record > 2008-02-28 20:12:45,610 DEBUG rc.py (450): > EventHandler.__init__(use_pylirc=1, use_netremote=1, is_plugin=1) > 2008-02-28 20:12:45,613 DEBUG rc.py (177): PyLirc resumed! > 2008-02-28 20:12:45,615 DEBUG generic_record.py (161): > Record_Thread::run: cmd=/usr/bin/mplayer -dumpstream -dumpfile > /media/Tv/L_nder_-_Menschen_-_Abenteuer_-_Irlands_rauer_Westen_-_Connemara_28-02_2015.ts > > dvb://NDR > 2008-02-28 20:12:45,616 INFO generic_record.py (128): Record logging > to "/var/log/freevo/recorder_stdout.log" and > "/var/log/freevo/recorder_stderr.log" > 2008-02-28 20:12:45,618 DEBUG childapp.py (58): > ChildApp.__init__(app=u'/usr/bin/mplayer -dumpstream -dumpfile > /media/Tv/L_nder_-_Menschen_-_Abenteuer_-_Irlands_rauer_Westen_-_Connemara_28-02_2015.ts > > dvb://NDR', debugname=None, doeslogging=0) > 2008-02-28 20:12:45,618 DEBUG childapp.py (64): u'/usr/bin/mplayer > -dumpstream -dumpfile > /media/Tv/L_nder_-_Menschen_-_Abenteuer_-_Irlands_rauer_Westen_-_Connemara_28-02_2015.ts > > dvb://NDR' is a unicode string > 2008-02-28 20:12:45,623 DEBUG recordserver.py (1312): > event=RECORD_START arg=<tv.epg_types.TvProgram instance at 0x87daf4c> > 2008-02-28 20:12:45,624 INFO recordserver.py (1380): RECORD_START Do > Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > 2008-02-28 20:12:45,790 DEBUG fxdimdb.py (907): fetch_image=[] > > > From the cases, that work I see, that the next message is supposed to be: > > 2008-02-28 19:30:51,468 DEBUG childapp.py (147): Running (str) > "/usr/bin/mplayer -dumpstream -dumpfile /media/Tv/Lokalzeit_aus_K_ > ln_-_28-02_1930.ts dvb://WDR" in shell with pid 1497 priority 0 > 2008-02-28 19:30:51,469 DEBUG childapp.py (411): > Read_Thread.__init__(name='stdout', fh=<open file '<fdopen>', mode 'rU' > at 0x8e8 > e9f8>, callback=<bound method RecordApp.stdout_cb of > <tv.plugins.generic_record.RecordApp instance at 0x8e580ac>>, > logger='mplayer', > doeslogging=1 > 2008-02-28 19:30:51,470 DEBUG childapp.py (425): logging stdout child > to "/var/log/freevo/mplayer-stdout-1001.log" > 2008-02-28 19:30:51,471 DEBUG childapp.py (411): > Read_Thread.__init__(name='stderr', fh=<open file '<fdopen>', mode 'rU' > at 0x8e8 > ea40>, callback=<bound method RecordApp.stderr_cb of > <tv.plugins.generic_record.RecordApp instance at 0x8e580ac>>, > logger='mplayer', > doeslogging=1 > 2008-02-28 19:30:51,472 DEBUG childapp.py (425): logging stderr child > to "/var/log/freevo/mplayer-stderr-1001.log" > 2008-02-28 19:30:51,524 DEBUG generic_record.py (164): app child pid: > 1497 > > The recording process (mplayer) is definitly not running, but the lock > file is there, thus I can not use the tuner for watching life TV. And if > I try to unschedule the ghost recording, to get rid of that lock file > and maybe to schedule it again, nothing happens: > > > 2008-02-28 20:15:07,838 DEBUG recordserver.py (727): > removeScheduledRecording(prog=<tv.epg_types.TvProgram instance at > 0x891482c> > ) > 2008-02-28 20:15:07,838 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 20:15:07,839 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 20:15:07,840 DEBUG recordserver.py (240): Return cached data > 2008-02-28 20:15:07,842 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 20:15:07,843 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 20:15:07,844 DEBUG recordserver.py (240): Return cached data > 2008-02-28 20:15:07,846 DEBUG record_types.py (77): removed > "130:1204226100" Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - > Abenteuer " > 2008-02-28 20:15:07,847 DEBUG recordserver.py (286): > saveScheduledRecordings(scheduledRecordings=<tv.record_types.ScheduledRecordings > > instance at 0x87dab8c>) > 2008-02-28 20:15:07,847 DEBUG recordserver.py (158): in findOverlaps > 2008-02-28 20:15:07,848 DEBUG recordserver.py (294): saving cached > file (/var/cache/freevo/record_schedule.xml) with 4 items > 2008-02-28 20:15:07,913 INFO recordserver.py (752): stopping current > recording Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > > The programm is removed from schedule, but there is no try to stop the > (not running) recording > and the lock file is not removed. > > If I try to reschedule the program afterwards, I get this: > > 2008-02-28 20:15:42,380 DEBUG recordserver.py (673): > scheduleRecording(prog=<tv.epg_types.TvProgram instance at 0x894376c>) > 2008-02-28 20:15:42,382 DEBUG epg_xmltv.py (89): XMLTV, reading > cached file (/var/cache/freevo/TV.xml.pickled) > 2008-02-28 20:15:42,780 DEBUG epg_xmltv.py (117): XMLTV, got cached > guide (version 6). > 2008-02-28 20:15:42,782 DEBUG recordserver.py (1127): > isProgAFavorite(prog=<tv.epg_types.TvProgram instance at 0x894376c>) > 2008-02-28 20:15:42,782 DEBUG recordserver.py (1044): getFavorites() > 2008-02-28 20:15:42,783 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 20:15:42,784 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 20:15:42,785 DEBUG recordserver.py (240): Return cached data > 2008-02-28 20:15:42,786 DEBUG recordserver.py (700): Conflict > resolution: 1 reason Conflict resolution disabled > 2008-02-28 20:15:42,787 DEBUG recordserver.py (667): Do Feb 28 > 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer tuner: NDR > 2008-02-28 20:15:42,789 DEBUG recordserver.py (709): adding Länder - > Menschen - Abenteuer to schedule > 2008-02-28 20:15:42,790 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 20:15:42,791 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 20:15:42,792 DEBUG recordserver.py (240): Return cached data > 2008-02-28 20:15:42,793 DEBUG record_types.py (64): added > "130:1204226100" Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - > Abenteuer " > > and a little later this: > > 2008-02-28 20:15:42,874 INFO recordserver.py (925): going to record: > Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > 2008-02-28 20:15:42,879 DEBUG recordserver.py (286): > saveScheduledRecordings(scheduledRecordings=<tv.record_types.ScheduledRecord > > ings instance at 0x87dab8c>) > 2008-02-28 20:15:42,880 DEBUG recordserver.py (158): in findOverlaps > 2008-02-28 20:15:42,881 DEBUG recordserver.py (294): saving cached > file (/var/cache/freevo/record_schedule.xml) with 5 items > 2008-02-28 20:15:42,955 INFO recordserver.py (943): start recording: > Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > 2008-02-28 20:15:42,956 DEBUG channels.py (155): > tunerSetFreq(chan='NDR', isplayer=False, app='record plugin', app_cmd=None > 2008-02-28 20:15:42,959 DEBUG generic_record.py (104): > Recorder::Record: /usr/bin/mplayer -dumpstream -dumpfile /media/Tv/L_nder_ > -_Menschen_-_Abenteuer_-_Irlands_rauer_Westen_-_Connemara_28-02_2015.ts > dvb://NDR > > and that's it, no further sign of processing the record request... > > > More over I noticed that, if two consecutive recordings are scheduled, > the second one fails completly (never mind, if the first one has been > successful or not): > > 2008-02-28 20:58:45,009 INFO recordserver.py (890): overlap_duration=0 > 2008-02-28 20:58:45,010 WARNING recordserver.py (923): delaying: Do Feb > 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 20:58:45,011 DEBUG recordserver.py (868): progloop=Fr Feb > 29 22:00->22:45 (22:00) 16418 Men in Trees > 2008-02-28 20:59:45,001 DEBUG recordserver.py (1436): DJW:time=20:59:45 > 2008-02-28 20:59:45,002 DEBUG recordserver.py (848): checkToRecord > 20:59:45 > 2008-02-28 20:59:45,003 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 20:59:45,004 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 20:59:45,004 DEBUG recordserver.py (240): Return cached data > 2008-02-28 20:59:45,006 DEBUG recordserver.py (868): progloop=Do Feb > 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > 2008-02-28 20:59:45,008 DEBUG recordserver.py (868): progloop=Do Feb > 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 20:59:45,009 INFO recordserver.py (890): overlap_duration=0 > 2008-02-28 20:59:45,010 WARNING recordserver.py (923): delaying: Do Feb > 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 20:59:45,011 DEBUG recordserver.py (868): progloop=Fr Feb > 29 22:00->22:45 (22:00) 16418 Men in Trees > 2008-02-28 21:00:45,001 DEBUG recordserver.py (1436): DJW:time=21:00:45 > 2008-02-28 21:00:45,002 DEBUG recordserver.py (848): checkToRecord > 21:00:45 > 2008-02-28 21:00:45,003 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 21:00:45,004 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 21:00:45,004 DEBUG recordserver.py (240): Return cached data > 2008-02-28 21:00:45,006 DEBUG recordserver.py (868): progloop=Do Feb > 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > 2008-02-28 21:00:45,008 DEBUG recordserver.py (868): progloop=Do Feb > 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 21:00:45,009 INFO recordserver.py (890): overlap_duration=0 > 2008-02-28 21:00:45,010 DEBUG recordserver.py (1127): > isProgAFavorite(prog=<tv.epg_types.TvProgram instance at 0x87d4d6c>) > 2008-02-28 21:00:45,011 DEBUG recordserver.py (1044): getFavorites() > 2008-02-28 21:00:45,012 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 21:00:45,013 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 21:00:45,014 DEBUG recordserver.py (240): Return cached data > 2008-02-28 21:00:45,015 DEBUG record_types.py (77): removed > "130:1204226100" Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - > Abenteuer " > 2008-02-28 21:00:45,016 INFO recordserver.py (904): CALLED RECORD > STOP 1: Do Feb 28 20:15->21:00 (20:15) 130 Länder - Menschen - Abenteuer > 2008-02-28 21:00:45,017 WARNING recordserver.py (923): delaying: Do Feb > 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 21:00:45,018 DEBUG recordserver.py (868): progloop=Fr Feb > 29 22:00->22:45 (22:00) 16418 Men in Trees > 2008-02-28 21:01:45,001 DEBUG recordserver.py (1436): DJW:time=21:01:45 > 2008-02-28 21:01:45,002 DEBUG recordserver.py (848): checkToRecord > 21:01:45 > 2008-02-28 21:01:45,003 DEBUG recordserver.py (230): > getScheduledRecordings() > 2008-02-28 21:01:45,004 DEBUG recordserver.py (235): reading cached > file (/var/cache/freevo/record_schedule.xml) > 2008-02-28 21:01:45,005 DEBUG recordserver.py (240): Return cached data > 2008-02-28 21:01:45,008 DEBUG recordserver.py (868): progloop=Do Feb > 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 21:01:45,009 INFO recordserver.py (925): going to record: > Do Feb 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 21:01:45,010 DEBUG recordserver.py (868): progloop=Fr Feb > 29 22:00->22:45 (22:00) 16418 Men in Trees > 2008-02-28 21:01:45,011 DEBUG recordserver.py (286): > saveScheduledRecordings(scheduledRecordings=<tv.record_types.ScheduledRecordings > > instance at 0x87dab8c>) > 2008-02-28 21:01:45,012 DEBUG recordserver.py (158): in findOverlaps > 2008-02-28 21:01:45,013 DEBUG recordserver.py (294): saving cached > file (/var/cache/freevo/record_schedule.xml) with 4 items > 2008-02-28 21:01:45,072 INFO recordserver.py (943): start recording: > Do Feb 28 21:00->21:45 (21:00) 130 Kühn und Kollegen > 2008-02-28 21:01:45,074 DEBUG channels.py (155): > tunerSetFreq(chan='NDR', isplayer=False, app='record plugin', app_cmd=None > 2008-02-28 21:01:45,075 DEBUG generic_record.py (104): > Recorder::Record: /usr/bin/mplayer -dumpstream -dumpfile > /media/Tv/K_hn_und_Kollegen_-_Das_NDR_Team_k_mpft_f_r_Sie_28-02_2100.ts > dvb://NDR > > and again, that's it, no further processing. The lock file is still > there by the way... > > Hope this gives you a clue. But probably you see the same in your log > files... > > Is there anything, I can do to help debugging this? I do not have much > time at the moment, but on the other hand this is a very annoying bug > and leaves freevo almost unusable for us at the moment. What I did is to add two prints before and after the Popen in childapp.py and noticed that the first one was printed but not the second one nor any other message after. So it looks like somehow the latest kaa.svn is breaks the Popen call. Just using the last release of kaa.base 0.3.0 and removing the coroutine call in record_client.py and it works just find. The recordserver does not shut down, needs a kill -9. I have quite a few uncommitted changes to recordserver since 1.8.0rc2, while I'm splitting up the record schedule xml into schedule which will be a schedule built from favorites, manual and deleted stored as pickle files rather than xml. Should be much faster and the building of the schedule can be done in the background. So if you would like to install kaa-base-0.3.0 and replace the new kaa names with those from 1.8.0rc2 to see if one of the calls fixes the exit problem then this would help a lot. Duncan ------------------------------------------------------------------------- This SF.net email is sponsored by: Microsoft Defy all challenges. Microsoft(R) Visual Studio 2008. http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/ _______________________________________________ Freevo-devel mailing list Freevo-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/freevo-devel
