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. Regards Tanja ------------------------------------------------------------------------- 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-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/freevo-users
