Mon 7/30 22:20:51.126 Changed default timezone to:Argentine Time Mon 7/30 22:20:51.455 user.dir2=/opt/sagetv/server Mon 7/30 22:20:51.456 classpath=Sage.jar:.:/:JARs/commons-jxpath-1.1.jar:JARs/commons-logging-api.jar:JARs/commons-logging.jar:JARs/jcifs-1.1.6.jar:JARs/mx4j-impl.jar:JARs/mx4j-jmx.jar:JARs/mx4j-remote.jar:JARs/mx4j-tools.jar:JARs/sbbi-jmx-1.0.jar:JARs/sbbi-upnplib-1.0.3.jar Mon 7/30 22:20:51.456 JVM version=1.5.0_06 Mon 7/30 22:20:51.458 OS=Linux 2.6.17.6 Mon 7/30 22:20:51.511 SageTV V6.1.9.1 Mon 7/30 22:20:52.181 ERROR resolving hostname:java.net.UnknownHostException: STVMC-540: STVMC-540 Mon 7/30 22:20:52.182 hostname=localhost Mon 7/30 22:20:56.940 Wizard starting to load database info... Mon 7/30 22:20:57.007 DBFile at version 65 FileSize=273113 Mon 7/30 22:20:57.008 Wizard allocating table for Year of size 0 Mon 7/30 22:20:57.061 Wizard allocating table for Network of size 0 Mon 7/30 22:20:57.062 Wizard allocating table for Title of size 1 Mon 7/30 22:20:57.063 Wizard loading main index for Title Mon 7/30 22:20:57.064 Wizard building alt. index 0 for Title Mon 7/30 22:20:57.066 Wizard allocating table for Channel of size 158 Mon 7/30 22:20:57.066 Wizard loading main index for Channel Mon 7/30 22:20:57.092 Wizard allocating table for People of size 1 Mon 7/30 22:20:57.092 Wizard loading main index for People Mon 7/30 22:20:57.093 Wizard building alt. index 0 for People Mon 7/30 22:20:57.093 Wizard allocating table for SubCategory of size 0 Mon 7/30 22:20:57.094 Wizard allocating table for Rated of size 0 Mon 7/30 22:20:57.094 Wizard allocating table for ParentalRating of size 0 Mon 7/30 22:20:57.095 Wizard allocating table for ExtendedRating of size 0 Mon 7/30 22:20:57.095 Wizard allocating table for Category of size 0 Mon 7/30 22:20:57.096 Wizard allocating table for PrimeTitle of size 0 Mon 7/30 22:20:57.096 Wizard allocating table for Bonus of size 0 Mon 7/30 22:20:57.097 Wizard allocating table for Show of size 1 Mon 7/30 22:20:57.097 Wizard loading main index for Show Mon 7/30 22:20:57.099 Wizard building alt. index 0 for Show Mon 7/30 22:20:57.111 Wizard allocating table for Airing of size 7904 Mon 7/30 22:20:57.112 Wizard loading main index for Airing Mon 7/30 22:20:57.172 Sage waiting for GC to free up some memory usage%=0.96596485 Mon 7/30 22:20:57.448 Sage done waiting for GC to free up some memory usage%=0.52673036 Mon 7/30 22:20:57.468 Wizard building alt. index 0 for Airing Mon 7/30 22:20:57.488 Wizard building alt. index 1 for Airing Mon 7/30 22:20:57.517 Wizard allocating table for ManualRecord of size 0 Mon 7/30 22:20:57.518 Wizard allocating table for MediaFile of size 7 Mon 7/30 22:20:57.519 Wizard loading main index for MediaFile Mon 7/30 22:20:57.681 Wizard building alt. index 0 for MediaFile Mon 7/30 22:20:57.681 Wizard building alt. index 1 for MediaFile Mon 7/30 22:20:57.682 Wizard allocating table for Watched of size 0 Mon 7/30 22:20:57.683 Wizard allocating table for Agent of size 0 Mon 7/30 22:20:57.684 Wizard allocating table for Wasted of size 0 Mon 7/30 22:20:57.684 Wizard allocating table for Playlist of size 0 Mon 7/30 22:20:57.685 Wizard allocating table for TVEditorial of size 0 Mon 7/30 22:20:57.685 Wizard allocating table for SeriesInfo of size 0 Mon 7/30 22:20:57.687 Wizard processing transactional records... Mon 7/30 22:20:57.705 Wizard performing validation on database objects... Mon 7/30 22:20:57.765 Wizard DONE loading database info. loadTime=0.825 sec Mon 7/30 22:20:58.668 MMC calling detectCaptureDevices on sage.b9@55e55f Mon 7/30 22:20:58.671 devices detected=[] Mon 7/30 22:20:58.671 EncoderMap={} Mon 7/30 22:20:58.672 MMC calling detectCaptureDevices on sage.ab@64883c Mon 7/30 22:20:58.679 videoDevices=[video0] Mon 7/30 22:20:58.681 Checking encoder key:-816678123 Mon 7/30 22:20:58.718 Created IVTVCaptureDevice object for:video0 Mon 7/30 22:20:58.719 EncoderMap1={video0=video0} Mon 7/30 22:20:58.721 Saving properties file to Sage.properties Mon 7/30 22:20:58.806 Processing new system dev:video0 Mon 7/30 22:20:58.807 Device already has been processed Mon 7/30 22:20:58.807 devices detected=[video0] Mon 7/30 22:20:58.808 EncoderMap={video0=video0} Mon 7/30 22:20:58.808 MMC calling detectCaptureDevices on sage.a9@15bdc50 Mon 7/30 22:20:58.809 WARNING - MissingResource: "Linux_DVB_Capture_Manager" Mon 7/30 22:20:58.810 videoDevices=[] Mon 7/30 22:20:58.810 detect 3 Mon 7/30 22:20:58.811 Checking encoder key:-816678123 Mon 7/30 22:20:58.812 Device is already accounted for. Mon 7/30 22:20:58.812 EncoderMap1={} Mon 7/30 22:20:58.813 devices detected=[] Mon 7/30 22:20:58.813 EncoderMap={video0=video0} Mon 7/30 22:20:58.936 Checking video directories for new files Mon 7/30 22:20:59.141 CARNY Processing 0 Agents & 1896 Airs Mon 7/30 22:20:59.142 CARNY Negative Energy Size: 0 Mon 7/30 22:20:59.143 CARNY Traitors:[] Mon 7/30 22:20:59.148 Verifying existence of all TV media files in database fixDurs=true avoidArchive=false Mon 7/30 22:20:59.382 Carny waiting for awhile... Mon 7/30 22:20:59.792 Trying to find lan network interface Mon 7/30 22:20:59.809 addr: /10.1.1.69 Mon 7/30 22:20:59.813 Miniserver running on 10.1.1.69 Mon 7/30 22:20:59.814 Parsed 0 clients Mon 7/30 22:20:59.817 SageTVServer was instantiated. Mon 7/30 22:20:59.820 SageTVMiniDiscoveryServer was instantiated. Mon 7/30 22:20:59.857 Wizard removing 2207 old airings of 7904 total... Mon 7/30 22:20:59.935 0.0.0.0/0.0.0.0 16867 Mon 7/30 22:21:00.005 Loading locator keys from filesystem since they already exist. Mon 7/30 22:21:00.007 0.0.0.0/0.0.0.0 16881 Mon 7/30 22:21:00.016 SageTVDiscoveryServer was instantiated. Mon 7/30 22:21:00.017 0.0.0.0/0.0.0.0 16869 Mon 7/30 22:21:00.054 Starting UPnP NAT Manager... Mon 7/30 22:21:00.106 Loading IVTV capture device Mon 7/30 22:21:00.107 createEncoder /dev/video0 Mon 7/30 22:21:00.108 verifying interface compatibility Mon 7/30 22:21:00.108 Opened /dev/video0 with interface 0 Mon 7/30 22:21:00.248 Loaded Mon 7/30 22:21:00.283 IVTV: video0 PVR card type is Hauppauge WinTV PVR-350 Mon 7/30 22:21:00.285 setInput0 0 0 54 8 Mon 7/30 22:21:00.345 updateColors0 b=128 c=128 h=128 s=128 Mon 7/30 22:21:00.472 Scheduler.updateSchedule() called time=Mon 7/30 22:21:00.471 manual=[] schedules={video0=[Sched=[] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:21:00.478 # Airs=0 Mon 7/30 22:21:00.553 MUST SEE FINAL-video0-[] Mon 7/30 22:21:00.571 Evaluating Potentials Mon 7/30 22:21:00.571 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:21:00.572 [] Mon 7/30 22:21:02.731 Checking video directories for new files Mon 7/30 22:21:02.732 Diskspace checking is running Mon 7/30 22:21:02.733 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:21:02.736 Enforcing keep at most limits for the files... Mon 7/30 22:21:02.736 Seeker clearing unwanted and partial files... Mon 7/30 22:21:02.750 Seeker waiting for 153722847516831 mins. Mon 7/30 22:21:02.758 Seeker awoken Mon 7/30 22:21:02.759 Seeker adding new Encoder: video0 Mon 7/30 22:21:02.765 MARK 1 currRecord=null enc=video0 clients=[] ir=false Mon 7/30 22:21:02.766 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:21:02.766 newRecord=null Mon 7/30 22:21:02.766 NOTHING TO RECORD FOR NOW... Mon 7/30 22:21:02.782 Seeker waiting for -19764081 mins. Mon 7/30 22:21:02.790 Seeker awoken Mon 7/30 22:21:02.791 MARK 1 currRecord=null enc=video0 clients=[] ir=false Mon 7/30 22:21:02.791 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:21:02.793 newRecord=null Mon 7/30 22:21:02.793 NOTHING TO RECORD FOR NOW... Mon 7/30 22:21:02.873 Checking video directories for new files Mon 7/30 22:21:02.874 Diskspace checking is running Mon 7/30 22:21:02.875 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:21:02.875 Enforcing keep at most limits for the files... Mon 7/30 22:21:02.875 Seeker clearing unwanted and partial files... Mon 7/30 22:21:02.876 Seeker waiting for 153722847516831 mins. Mon 7/30 22:21:02.979 StorageDeviceDetector started... Mon 7/30 22:21:03.238 Seeker is starting the library import scan... Mon 7/30 22:21:03.347 Seeker has finished the library import scan. Mon 7/30 22:21:04.190 Ministry is starting Mon 7/30 22:21:04.192 Ministry is waiting for 180 sec Mon 7/30 22:21:06.423 Wizard locating time holes in airing table... Mon 7/30 22:21:06.604 Wizard plugging the 158 time holes in the airing table... Mon 7/30 22:21:07.114 Wizard fixing duration for 316 noshow airings... Mon 7/30 22:21:07.126 Unable to setup UPnP mappings because we can't get a local IP address! Mon 7/30 22:21:09.675 Unable to setup UPnP mappings because we can't get a local IP address! Mon 7/30 22:21:13.088 Wizard removing 0 expired Channels of 158 total... Mon 7/30 22:21:13.208 Wizard removing 0 expired Shows of 1 total... Mon 7/30 22:21:13.544 Retaining 1 total title & people & category & bonus ids. Mon 7/30 22:21:13.547 Clearing out 0 titles of 1 total. Mon 7/30 22:21:13.604 Clearing out 0 prime titles of 0 total. Mon 7/30 22:21:13.662 Clearing out 0 people of 1 total. Mon 7/30 22:21:13.720 Clearing out 0 categories of 0 total. Mon 7/30 22:21:13.776 Clearing out 0 subcategories of 0 total. Mon 7/30 22:21:13.832 Clearing out 0 bonuses of 0 total. Mon 7/30 22:21:13.887 Wizard is fixing the media mask on the Show objects... Mon 7/30 22:21:13.943 Wizard is fixing the media mask on the Titles... Mon 7/30 22:21:13.999 Wizard is fixing the media mask on the Years... Mon 7/30 22:21:14.055 Wizard is fixing the media mask on the Peoples... Mon 7/30 22:21:14.111 Wizard is fixing the media mask on the Categories... Mon 7/30 22:21:14.167 Wizard is fixing the media mask on the SubCategories... Mon 7/30 22:21:14.223 Wizard is fixing the media mask on the Rated... Mon 7/30 22:21:14.279 Wizard is fixing the media mask on the PR... Mon 7/30 22:21:14.335 Wizard is fixing the media mask on the ERs... Mon 7/30 22:21:14.391 Wizard is fixing the media mask on the Bonus... Mon 7/30 22:21:14.503 Wizard backing up database file... Mon 7/30 22:21:14.508 Wizard compressing new file... Mon 7/30 22:21:14.513 Wizard writing out table info for Year Mon 7/30 22:21:14.516 Wizard writing out table info for Network Mon 7/30 22:21:14.518 Wizard writing out table info for Title Mon 7/30 22:21:14.523 Wizard writing out table info for Channel Mon 7/30 22:21:14.536 Wizard writing out table info for People Mon 7/30 22:21:14.540 Wizard writing out table info for SubCategory Mon 7/30 22:21:14.542 Wizard writing out table info for Rated Mon 7/30 22:21:14.544 Wizard writing out table info for ParentalRating Mon 7/30 22:21:14.547 Wizard writing out table info for ExtendedRating Mon 7/30 22:21:14.549 Wizard writing out table info for Category Mon 7/30 22:21:14.551 Wizard writing out table info for PrimeTitle Mon 7/30 22:21:14.553 Wizard writing out table info for Bonus Mon 7/30 22:21:14.555 Wizard writing out table info for Show Mon 7/30 22:21:14.559 Wizard writing out table info for Airing Mon 7/30 22:21:14.606 Wizard writing out table info for ManualRecord Mon 7/30 22:21:14.609 Wizard writing out table info for MediaFile Mon 7/30 22:21:14.615 Wizard writing out table info for Watched Mon 7/30 22:21:14.617 Wizard writing out table info for Agent Mon 7/30 22:21:14.619 Wizard writing out table info for Wasted Mon 7/30 22:21:14.621 Wizard writing out table info for Playlist Mon 7/30 22:21:14.623 Wizard writing out table info for TVEditorial Mon 7/30 22:21:14.625 Wizard writing out table info for SeriesInfo Mon 7/30 22:21:14.644 Wizard DONE saving database info. Mon 7/30 22:21:14.647 sage.a5@1ea7821 needs an update in 0:00:00 Mon 7/30 22:21:14.648 EPG needs an update in 0 minutes Mon 7/30 22:21:14.648 EPG attempting to expand video0 TV Tuner Mon 7/30 22:21:14.649 expand called on video0 TV Tuner at Mon 7/30 22:21:14.649 expandedUntil=Mon 7/30 20:59:54.724 scannedUntil=Sun 8/17 4:12:55.807 Mon 7/30 22:21:14.650 EPG Expanding video0 TV Tuner at Mon 7/30 22:21:14.650 Mon 7/30 22:21:14.651 Carny got a Std job of null Mon 7/30 22:21:14.766 Saving properties file to Sage.properties Mon 7/30 22:21:14.807 Scheduler awoken Mon 7/30 22:21:14.809 Scheduler.updateSchedule() called time=Mon 7/30 22:21:14.808 manual=[] schedules={video0=[Sched=[] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:21:14.809 # Airs=0 Mon 7/30 22:21:14.810 MUST SEE FINAL-video0-[] Mon 7/30 22:21:14.810 Evaluating Potentials Mon 7/30 22:21:14.810 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:21:14.811 [] Mon 7/30 22:21:14.819 Seeker awoken Mon 7/30 22:21:14.820 MARK 1 currRecord=null enc=video0 clients=[] ir=false Mon 7/30 22:21:14.820 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:21:14.821 newRecord=null Mon 7/30 22:21:14.821 NOTHING TO RECORD FOR NOW... Mon 7/30 22:21:15.119 Checking video directories for new files Mon 7/30 22:21:15.120 Diskspace checking is running Mon 7/30 22:21:15.121 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:21:15.124 Enforcing keep at most limits for the files... Mon 7/30 22:21:15.124 Seeker clearing unwanted and partial files... Mon 7/30 22:21:15.125 Seeker waiting for 153722847516831 mins. Mon 7/30 22:21:15.175 CARNY Processing 0 Agents & 3950 Airs Mon 7/30 22:21:15.177 CARNY Negative Energy Size: 0 Mon 7/30 22:21:15.178 CARNY Traitors:[] Mon 7/30 22:21:15.179 Scheduler awoken Mon 7/30 22:21:15.180 Scheduler.updateSchedule() called time=Mon 7/30 22:21:15.180 manual=[] schedules={video0=[Sched=[] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:21:15.180 # Airs=0 Mon 7/30 22:21:15.181 MUST SEE FINAL-video0-[] Mon 7/30 22:21:15.181 Evaluating Potentials Mon 7/30 22:21:15.181 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:21:15.182 [] Mon 7/30 22:21:15.182 Seeker awoken Mon 7/30 22:21:15.183 MARK 1 currRecord=null enc=video0 clients=[] ir=false Mon 7/30 22:21:15.183 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:21:15.184 newRecord=null Mon 7/30 22:21:15.184 NOTHING TO RECORD FOR NOW... Mon 7/30 22:21:15.185 Carny got a Req job of null Mon 7/30 22:21:15.191 Checking video directories for new files Mon 7/30 22:21:15.192 Diskspace checking is running Mon 7/30 22:21:15.192 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:21:15.193 Enforcing keep at most limits for the files... Mon 7/30 22:21:15.193 Seeker clearing unwanted and partial files... Mon 7/30 22:21:15.193 Seeker waiting for 153722847516831 mins. Mon 7/30 22:21:15.246 CARNY Processing 0 Agents & 3950 Airs Mon 7/30 22:21:15.247 CARNY Negative Energy Size: 0 Mon 7/30 22:21:15.247 CARNY Traitors:[] Mon 7/30 22:21:15.247 Scheduler awoken Mon 7/30 22:21:15.249 Scheduler.updateSchedule() called time=Mon 7/30 22:21:15.248 manual=[] schedules={video0=[Sched=[] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:21:15.249 # Airs=0 Mon 7/30 22:21:15.249 MUST SEE FINAL-video0-[] Mon 7/30 22:21:15.250 Evaluating Potentials Mon 7/30 22:21:15.250 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:21:15.250 [] Mon 7/30 22:21:15.251 Seeker awoken Mon 7/30 22:21:15.258 MARK 1 currRecord=null enc=video0 clients=[] ir=false Mon 7/30 22:21:15.259 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:21:15.259 newRecord=null Mon 7/30 22:21:15.259 NOTHING TO RECORD FOR NOW... Mon 7/30 22:21:15.260 Carny waiting for awhile... Mon 7/30 22:21:15.261 Checking video directories for new files Mon 7/30 22:21:15.262 Diskspace checking is running Mon 7/30 22:21:15.262 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:21:15.262 Enforcing keep at most limits for the files... Mon 7/30 22:21:15.263 Seeker clearing unwanted and partial files... Mon 7/30 22:21:15.263 Seeker waiting for 153722847516831 mins. Mon 7/30 22:21:15.580 Wizard removing 2 old airings of 7909 total... Mon 7/30 22:21:15.641 Wizard locating time holes in airing table... Mon 7/30 22:21:15.811 Wizard plugging the 1 time holes in the airing table... Mon 7/30 22:21:15.927 Wizard fixing duration for 1 noshow airings... Mon 7/30 22:21:16.096 Wizard removing 0 expired Channels of 158 total... Mon 7/30 22:21:16.216 Wizard removing 0 expired Shows of 1 total... Mon 7/30 22:21:16.552 Retaining 1 total title & people & category & bonus ids. Mon 7/30 22:21:16.555 Clearing out 0 titles of 1 total. Mon 7/30 22:21:16.613 Clearing out 0 prime titles of 0 total. Mon 7/30 22:21:16.675 Clearing out 0 people of 1 total. Mon 7/30 22:21:16.733 Clearing out 0 categories of 0 total. Mon 7/30 22:21:16.789 Clearing out 0 subcategories of 0 total. Mon 7/30 22:21:16.846 Clearing out 0 bonuses of 0 total. Mon 7/30 22:21:16.904 Wizard is fixing the media mask on the Show objects... Mon 7/30 22:21:16.963 Wizard is fixing the media mask on the Titles... Mon 7/30 22:21:17.019 Wizard is fixing the media mask on the Years... Mon 7/30 22:21:17.075 Wizard is fixing the media mask on the Peoples... Mon 7/30 22:21:17.131 Wizard is fixing the media mask on the Categories... Mon 7/30 22:21:17.133 MiniUI got connection from Socket[addr=/127.0.0.1,port=36291,localport=31099] Mon 7/30 22:21:17.157 MiniPlayer is adding to its map:0050040db957 Mon 7/30 22:21:17.160 MiniUI got connection from Socket[addr=/127.0.0.1,port=36292,localport=31099] Mon 7/30 22:21:17.180 MiniUI is adding to its map:0050040db957 Mon 7/30 22:21:17.181 Creating new UI for client:0050040db957 Mon 7/30 22:21:17.187 Wizard is fixing the media mask on the SubCategories... Mon 7/30 22:21:17.203 Creating-2 new UI for client:0050040db957 UIManager:localhost@@0050040db957-e2a37b Mon 7/30 22:21:17.243 Wizard is fixing the media mask on the Rated... Mon 7/30 22:21:17.299 Wizard is fixing the media mask on the PR... Mon 7/30 22:21:17.344 MiniUI established for 0050040db957 Mon 7/30 22:21:17.355 Wizard is fixing the media mask on the ERs... Mon 7/30 22:21:17.406 Error in MediaServerConnection of :java.io.EOFException java.io.EOFException Mon 7/30 22:21:17.407 at sage.MediaServer$a.a(Unknown Source) Mon 7/30 22:21:17.408 at sage.MediaServer$a.run(Unknown Source) Mon 7/30 22:21:17.408 at java.lang.Thread.run(Unknown Source) Mon 7/30 22:21:17.411 Wizard is fixing the media mask on the Bonus... Mon 7/30 22:21:17.560 Wizard backing up database file... Mon 7/30 22:21:17.562 Wizard compressing new file... Mon 7/30 22:21:17.673 Wizard writing out table info for Year Mon 7/30 22:21:17.728 Wizard writing out table info for Network Mon 7/30 22:21:17.871 Wizard writing out table info for Title Mon 7/30 22:21:17.935 Wizard writing out table info for Channel Mon 7/30 22:21:17.971 Wizard writing out table info for People Mon 7/30 22:21:18.003 Wizard writing out table info for SubCategory Mon 7/30 22:21:18.019 Wizard writing out table info for Rated Mon 7/30 22:21:18.023 Wizard writing out table info for ParentalRating Mon 7/30 22:21:18.027 Wizard writing out table info for ExtendedRating Mon 7/30 22:21:18.030 Wizard writing out table info for Category Mon 7/30 22:21:18.032 Wizard writing out table info for PrimeTitle Mon 7/30 22:21:18.128 Wizard writing out table info for Bonus Mon 7/30 22:21:18.158 Wizard writing out table info for Show Mon 7/30 22:21:18.162 Wizard writing out table info for Airing Mon 7/30 22:21:18.242 Wizard writing out table info for ManualRecord Mon 7/30 22:21:18.248 Wizard writing out table info for MediaFile Mon 7/30 22:21:18.254 Wizard writing out table info for Watched Mon 7/30 22:21:18.256 Wizard writing out table info for Agent Mon 7/30 22:21:18.258 Wizard writing out table info for Wasted Mon 7/30 22:21:18.261 Wizard writing out table info for Playlist Mon 7/30 22:21:18.263 Wizard writing out table info for TVEditorial Mon 7/30 22:21:18.266 Wizard writing out table info for SeriesInfo Mon 7/30 22:21:18.271 Wizard DONE saving database info. Mon 7/30 22:21:18.274 sage.a5@1ea7821 needs an update in 23:59:56 Mon 7/30 22:21:18.274 EPG needs an update in 1439 minutes Mon 7/30 22:21:18.274 EPG's works is done. Waiting... Mon 7/30 22:21:18.275 Carny got a Std job of null Mon 7/30 22:21:18.356 CARNY Processing 0 Agents & 3950 Airs Mon 7/30 22:21:18.356 CARNY Negative Energy Size: 0 Mon 7/30 22:21:18.357 CARNY Traitors:[] Mon 7/30 22:21:18.357 Carny waiting for awhile... Mon 7/30 22:21:18.357 Scheduler awoken Mon 7/30 22:21:18.358 Scheduler.updateSchedule() called time=Mon 7/30 22:21:18.358 manual=[] schedules={video0=[Sched=[] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:21:18.359 # Airs=0 Mon 7/30 22:21:18.359 MUST SEE FINAL-video0-[] Mon 7/30 22:21:18.360 Evaluating Potentials Mon 7/30 22:21:18.360 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:21:18.360 [] Mon 7/30 22:21:18.361 Seeker awoken Mon 7/30 22:21:18.361 MARK 1 currRecord=null enc=video0 clients=[] ir=false Mon 7/30 22:21:18.362 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:21:18.362 newRecord=null Mon 7/30 22:21:18.362 NOTHING TO RECORD FOR NOW... Mon 7/30 22:21:18.378 Saving properties file to Sage.properties Mon 7/30 22:21:18.408 Checking video directories for new files Mon 7/30 22:21:18.409 Diskspace checking is running Mon 7/30 22:21:18.410 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:21:18.410 Enforcing keep at most limits for the files... Mon 7/30 22:21:18.410 Seeker clearing unwanted and partial files... Mon 7/30 22:21:18.411 Seeker waiting for 153722847516831 mins. Mon 7/30 22:21:20.611 MiniClient GFX_TEXTMODE=REMOTEFONTS Mon 7/30 22:21:20.614 MiniClient GFX_BLENDMODE=POSTMULTIPLY Mon 7/30 22:21:20.616 MiniClient GFX_DRAWMODE=null Mon 7/30 22:21:20.618 MiniClient GFX_BITMAP_FORMAT=null Mon 7/30 22:21:20.627 MiniClient GFX_SCALING=SOFTWARE Mon 7/30 22:21:20.630 MiniClient GFX_OFFLINE_IMAGE_CACHE=TRUE Mon 7/30 22:21:20.632 MiniClient GFX_SUPPORTED_ASPECTS=null Mon 7/30 22:21:20.634 MiniClient GFX_ASPECT=null Mon 7/30 22:21:20.636 MiniClient GFX_SUPPORTED_RESOLUTIONS=720x480;windowed Mon 7/30 22:21:20.639 MiniClient GFX_RESOLUTION=720x480 Mon 7/30 22:21:20.641 MiniClient GFX_COMPOSITE=COLORKEY Mon 7/30 22:21:20.643 MiniClient GFX_COLORKEY=080010 Mon 7/30 22:21:20.691 MiniClient INPUT_DEVICES=IR,KEYBOARD,MOUSE Mon 7/30 22:21:20.694 MiniClient DISPLAY_OVERSCAN=0;0;1.0;1.0 Mon 7/30 22:21:20.697 MiniClient VIDEO_CODECS=FlashVideo,H.264,MPEG1-Video,MPEG2-Video,MPEG4-Video,WMV7,WMV8 Mon 7/30 22:21:20.699 MiniClient AUDIO_CODECS=AAC,FLAC,MP2,MP3,WAV,Vorbis,WMA7,WMA8,AC3 Mon 7/30 22:21:20.701 MiniClient PULL_AV_CONTAINERS=MPEG2-PS,AAC,MPEG2-TS,ASF,AVI,FLAC,FlashVideo,MP2,MP3,MPEG1,Ogg,Quicktime,Vorbis,WAV Mon 7/30 22:21:20.703 MiniClient PUSH_AV_CONTAINERS=MPEG2-PS Mon 7/30 22:21:20.705 MiniClient FIXED_PUSH_MEDIA_FORMAT=null Mon 7/30 22:21:20.707 MiniClient DETAILED_BUFFER_STATS=TRUE Mon 7/30 22:21:20.709 MiniClient PUSH_BUFFER_SEEKING=TRUE Mon 7/30 22:21:20.711 MiniClient MEDIA_PLAYER_BUFFER_DELAY=2000 Mon 7/30 22:21:20.713 MiniClient IR_PROTOCOL=null Mon 7/30 22:21:20.715 MiniClient CRYPTO_ALGORITHMS=RSA,Blowfish,DH,DES Mon 7/30 22:21:20.796 Creating-3 new UI for client:0050040db957 UIManager:localhost@@0050040db957-e2a37b Mon 7/30 22:21:20.828 UIMgr loading UI from: /opt/sagetv/server/STVs/SageTV3/SageTV3.xml Mon 7/30 22:21:20.963 VF thread is now running... Mon 7/30 22:21:20.964 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:21:27.347 locale = en Mon 7/30 22:21:28.278 UIMgr done loading UI from: /opt/sagetv/server/STVs/SageTV3/SageTV3.xml Mon 7/30 22:21:28.637 EVPoolSize=1 Mon 7/30 22:21:28.747 Hidden Extras are DISABLED Mon 7/30 22:21:32.049 DatePat=EEE, MMM d orgPat=EEEE, MMMM d, yyyy Mon 7/30 22:21:32.109 setUI(sage.b2@1eef3b0[Main Menu]) histIdx=0 uiHistory=[sage.b2@1eef3b0[Main Menu]] Mon 7/30 22:21:32.376 Creating-4 new UI for client:0050040db957 UIManager:localhost@@0050040db957-e2a37b Mon 7/30 22:21:32.989 Loading 720x480 image from file /opt/sagetv/server/STVs/SageTV3/Background.jpg Mon 7/30 22:21:34.483 Loading 169x59 image from file /opt/sagetv/server/STVs/SageTV3/SageLogo256small.png Mon 7/30 22:21:34.741 Loading 118x103 image from file /opt/sagetv/server/STVs/SageTV3/GoFullscreen.png Mon 7/30 22:21:34.952 Loading 97x121 image from file /opt/sagetv/server/STVs/SageTV3/GoSleep.png Mon 7/30 22:21:35.057 Loading 586x47 image from file /opt/sagetv/server/STVs/SageTV3/MenuBarLong.png Mon 7/30 22:22:06.047 VF.submitJob(VFJob[CloseMF r=0.0 t=0 file=null ifn=null]) Mon 7/30 22:22:06.048 VF processing job VFJob[CloseMF r=0.0 t=0 file=null ifn=null] nPlayin=false Mon 7/30 22:22:06.049 VF processing on UI Thread VFJob[CloseMF r=0.0 t=0 file=null ifn=null] Mon 7/30 22:22:06.049 VF processing job null nPlayin=false Mon 7/30 22:22:06.050 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:06.053 Seeker.finishWatch(UIManager:localhost@@0050040db957-e2a37b) Mon 7/30 22:22:06.354 setUI(sage.b2@1d1011a[MediaPlayer OSD]) histIdx=1 uiHistory=[sage.b2@1eef3b0[Main Menu], sage.b2@1d1011a[MediaPlayer OSD]] Mon 7/30 22:22:06.628 Loading 380x380 image from file /opt/sagetv/server/STVs/SageTV3/VideoArt.png Mon 7/30 22:22:06.650 VideoFrame.watch(A[12231,1,"No Data",-392251032@0730.21:00,120]) Mon 7/30 22:22:06.653 watchThisFile=null Mon 7/30 22:22:06.654 Called Seeker.requestWatch(A[12231,1,"No Data",-392251032@0730.21:00,120]) hostname=UIManager:localhost@@0050040db957-e2a37b Mon 7/30 22:22:06.654 findBestEncoderForNow(A[12231,1,"No Data",-392251032@0730.21:00,120] record=false host=UIManager:localhost@@0050040db957-e2a37b) Mon 7/30 22:22:06.655 foundBestEncoder3=sage.ca$c@1089de1[video0] Mon 7/30 22:22:06.656 MARK 1 currRecord=null enc=video0 clients=[UIManager:localhost@@0050040db957-e2a37b] ir=false Mon 7/30 22:22:06.656 defaultRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:06.657 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:06.658 FORCE WATCH executing clients=[UIManager:localhost@@0050040db957-e2a37b] Mon 7/30 22:22:06.658 newRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:06.659 Change in record to another show. Entering device record mode. - LATER Mon 7/30 22:22:06.659 Change in record to another show. Entering device record mode. - NOW Mon 7/30 22:22:06.659 Seeker.startRecord(video0 A[12231,1,"No Data",-392251032@0730.21:00,120], currTime=Mon 7/30 22:22:06.655) currRecord=null switch=false Mon 7/30 22:22:06.660 Setting up MMC video for recording new show & tuning channel conn=video0 TV Tuner Mon 7/30 22:22:06.719 Using quality setting "Great" for recording Mon 7/30 22:22:06.719 VideoStorage for new file: /var/media/tv - Use All Mon 7/30 22:22:06.729 MediaFile created subfile:/var/media/tv/392251032_1_0730_2222-0.mpg MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]]] Mon 7/30 22:22:06.809 Added:MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] Mon 7/30 22:22:07.379 Seeker channel string=1 Mon 7/30 22:22:07.379 startEncoding for IVTV capture device file=/var/media/tv/392251032_1_0730_2222-0.mpg chan=1 Mon 7/30 22:22:07.380 IVTV: video0 PVR card type is Hauppauge WinTV PVR-350 Mon 7/30 22:22:07.380 setInput0 0 0 54 8 Mon 7/30 22:22:07.380 updateColors0 b=128 c=128 h=128 s=128 Mon 7/30 22:22:07.388 setEncodingProperties0 Great Mon 7/30 22:22:07.388 Set encoding property audiooutputmode to 0 Mon 7/30 22:22:07.388 Set encoding property audiocrc to 0 Mon 7/30 22:22:07.389 Set encoding property gopsize to 15 Mon 7/30 22:22:07.389 Set encoding property videobitrate to 3800000 Mon 7/30 22:22:07.389 Set encoding property inversetelecine to 0 Mon 7/30 22:22:07.389 Set encoding property closedgop to 0 Mon 7/30 22:22:07.389 Set encoding property vbr to 0 Mon 7/30 22:22:07.389 Set encoding property outputstreamtype to 10 Mon 7/30 22:22:07.389 Set encoding property width to 720 Mon 7/30 22:22:07.390 Set encoding property height to 576 Mon 7/30 22:22:07.390 Set encoding property audiobitrate to 384 Mon 7/30 22:22:07.390 Set encoding property audiosampling to 48000 Mon 7/30 22:22:07.390 Set encoding property disablefilter to 1 Mon 7/30 22:22:07.390 Set encoding property medianfilter to 3 Mon 7/30 22:22:07.390 Set encoding property fps to 25 Mon 7/30 22:22:07.391 Set encoding property ipb to 0 Mon 7/30 22:22:07.391 Set encoding property deinterlace to 0 Mon 7/30 22:22:07.391 Set encoding property aspectratio to 1 Mon 7/30 22:22:07.391 Default DNR mode=0 spatial=0 temporal=8 type=0 Mon 7/30 22:22:07.408 setup encoding /var/media/tv/392251032_1_0730_2222-0.mpg Mon 7/30 22:22:07.410 Starting IVTV capture thread Mon 7/30 22:22:07.412 VF.submitJob(VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null]) Mon 7/30 22:22:07.413 VF processing job VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:07.414 VF processing on UI Thread VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] Mon 7/30 22:22:07.415 VideoFrame creating new media player for file:MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] Mon 7/30 22:22:07.440 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:07.440 VF network encoder playback detected: false Mon 7/30 22:22:07.452 VF waiting for data to appear in new file...liveWait=1268 Mon 7/30 22:22:07.452 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:07.469 EVPoolSize=2 Mon 7/30 22:22:07.473 EVPoolSize=3 Mon 7/30 22:22:07.654 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:07.655 VF network encoder playback detected: false Mon 7/30 22:22:07.655 VF waiting for data to appear in new file...liveWait=1065 Mon 7/30 22:22:07.656 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:07.685 VF.submitJob(VFJob[Play r=0.0 t=0 file=null ifn=null]) Mon 7/30 22:22:07.686 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:07.686 VF network encoder playback detected: false Mon 7/30 22:22:07.686 VF waiting for data to appear in new file...liveWait=1034 Mon 7/30 22:22:07.687 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:07.688 VF.submitJob(VFJob[TimeSet r=0.0 t=1185844927688 file=null ifn=null]) Mon 7/30 22:22:07.689 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:07.689 VF network encoder playback detected: false Mon 7/30 22:22:07.690 VF waiting for data to appear in new file...liveWait=1030 Mon 7/30 22:22:07.690 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:07.820 Loading 29x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDChUp.png Mon 7/30 22:22:07.898 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:07.899 VF network encoder playback detected: false Mon 7/30 22:22:07.899 VF waiting for data to appear in new file...liveWait=821 Mon 7/30 22:22:07.900 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:07.917 Loading 35x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDChDisplay.png Mon 7/30 22:22:07.930 Loading 29x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDChDown.png Mon 7/30 22:22:07.944 ImageUtils loading file /opt/sagetv/server/STVs/SageTV3/OSDStatusPause.png Mon 7/30 22:22:07.955 ImageUtils creating BI copy BufferedImage@18c0dc2: type = 0 ColorModel: #pixelBits = 32 numComponents = 4 color space = java.awt.color.ICC_ColorSpace@1db3f6c transparency = 3 has alpha = true isAlphaPre = false ByteInterleavedRaster: width = 6 height = 8 #numDataElements 4 dataOff[0] = 0 w=6 h=8 freeMem=840200 totalMem=34516992 Mon 7/30 22:22:08.990 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:08.991 VF network encoder playback detected: false Mon 7/30 22:22:08.991 VF waiting for data to appear in new file...liveWait=-271 Mon 7/30 22:22:08.992 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:09.110 Loading 16x13 image from file /opt/sagetv/server/STVs/SageTV3/OSDVolOn.png Mon 7/30 22:22:09.140 ImageUtils loading file /opt/sagetv/server/STVs/SageTV3/OSDVolBar.png Mon 7/30 22:22:09.146 ImageUtils creating BI copy BufferedImage@1db0c7e: type = 0 ColorModel: #pixelBits = 32 numComponents = 4 color space = java.awt.color.ICC_ColorSpace@1db3f6c transparency = 3 has alpha = true isAlphaPre = false ByteInterleavedRaster: width = 64 height = 4 #numDataElements 4 dataOff[0] = 0 w=64 h=4 freeMem=16840504 totalMem=38457344 Mon 7/30 22:22:09.162 Loading 9x15 image from file /opt/sagetv/server/STVs/SageTV3/OSDVolSlider.png Mon 7/30 22:22:09.171 Loading 29x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDReplay.png Mon 7/30 22:22:09.184 Loading 30x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDRew.png Mon 7/30 22:22:09.194 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:09.195 VF network encoder playback detected: false Mon 7/30 22:22:09.195 VF waiting for data to appear in new file...liveWait=-475 Mon 7/30 22:22:09.212 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:09.216 Loading 30x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDStop.png Mon 7/30 22:22:09.229 Loading 30x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDPlay.png Mon 7/30 22:22:09.243 Loading 30x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDFwd.png Mon 7/30 22:22:09.275 Loading 29x26 image from file /opt/sagetv/server/STVs/SageTV3/OSDSkip.png Mon 7/30 22:22:09.402 Scheduler awoken Mon 7/30 22:22:09.404 Scheduler.updateSchedule() called time=Mon 7/30 22:22:09.403 manual=[] schedules={video0=[Sched=[] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:22:09.404 # Airs=0 Mon 7/30 22:22:09.404 MUST SEE FINAL-video0-[] Mon 7/30 22:22:09.405 Evaluating Potentials Mon 7/30 22:22:09.405 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:22:09.407 [A[12231,1,"No Data",-392251032@0730.21:00,120]] Mon 7/30 22:22:09.408 Seeker awoken Mon 7/30 22:22:09.409 MARK 1 currRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] enc=video0 clients=[UIManager:localhost@@0050040db957-e2a37b] ir=false Mon 7/30 22:22:09.409 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:09.409 FORCE WATCH abandoned because it's currently being recorded clients=[UIManager:localhost@@0050040db957-e2a37b] Mon 7/30 22:22:09.410 newRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:09.410 Keeping record just the way it is. Mon 7/30 22:22:09.418 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:09.419 VF network encoder playback detected: false Mon 7/30 22:22:09.419 VF waiting for data to appear in new file...liveWait=-699 Mon 7/30 22:22:09.420 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:09.469 RootFile=/ fstype=0xef53 fileLength=0 Mon 7/30 22:22:09.470 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:09.470 VF network encoder playback detected: false Mon 7/30 22:22:09.471 VF waiting for data to appear in new file...liveWait=-750 Mon 7/30 22:22:09.471 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:09.612 Checking video directories for new files Mon 7/30 22:22:09.613 Diskspace checking is running Mon 7/30 22:22:09.614 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:22:09.614 Enforcing keep at most limits for the files... Mon 7/30 22:22:09.614 Seeker clearing unwanted and partial files... Mon 7/30 22:22:09.616 needFreeSize = 0.4941 GB currFreeSize=71.195783168 GB Mon 7/30 22:22:09.616 Seeker waiting for 37 mins. Mon 7/30 22:22:09.674 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:09.675 VF network encoder playback detected: false Mon 7/30 22:22:09.675 VF waiting for data to appear in new file...liveWait=-955 Mon 7/30 22:22:09.676 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:09.879 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:09.879 VF network encoder playback detected: false Mon 7/30 22:22:09.880 VF waiting for data to appear in new file...liveWait=-1159 Mon 7/30 22:22:09.880 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:10.082 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:10.084 VF network encoder playback detected: false Mon 7/30 22:22:10.085 VF waiting for data to appear in new file...liveWait=-1365 Mon 7/30 22:22:10.085 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:10.286 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:10.287 VF network encoder playback detected: false Mon 7/30 22:22:10.287 VF waiting for data to appear in new file...liveWait=-1567 Mon 7/30 22:22:10.288 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:10.446 Found next seq hdr code! Mon 7/30 22:22:10.491 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:10.491 VF network encoder playback detected: false Mon 7/30 22:22:10.492 VF waiting for data to appear in new file...liveWait=-1771 Mon 7/30 22:22:10.492 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:10.695 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:10.695 VF network encoder playback detected: false Mon 7/30 22:22:10.695 VF waiting for data to appear in new file...liveWait=-1975 Mon 7/30 22:22:10.696 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:10.902 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:10.903 VF network encoder playback detected: false Mon 7/30 22:22:10.903 VF waiting for data to appear in new file...liveWait=-2183 Mon 7/30 22:22:10.903 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:11.116 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:11.116 VF network encoder playback detected: false Mon 7/30 22:22:11.117 VF waiting for data to appear in new file...liveWait=-2397 Mon 7/30 22:22:11.117 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:11.319 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:11.319 VF network encoder playback detected: false Mon 7/30 22:22:11.319 VF waiting for data to appear in new file...liveWait=-2599 Mon 7/30 22:22:11.320 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:11.523 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:11.523 VF network encoder playback detected: false Mon 7/30 22:22:11.527 VF processing on UI Thread VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] ifn=null] Mon 7/30 22:22:11.528 VF file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] targetTime = Mon 7/30 22:22:06.720 Mon 7/30 22:22:11.529 VideoFrame.timeSelected(Mon 7/30 22:22:06.720, true) currFile=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Wed 12/31 21:00:00.000]] Mon 7/30 22:22:11.530 initDriver0() Mon 7/30 22:22:11.531 MiniPlayer established for 0050040db957 Mon 7/30 22:22:11.533 getEstimatedBW=0 estimatedBWBytes=0 estimatedBWTime=0 Mon 7/30 22:22:11.533 MiniPlayer was not able to get a bandwidth estimate from the UI system, sending data to get its own estimate... Mon 7/30 22:22:11.536 MiniPlayer got an estimate from the UI on bandwidth of 65584Kbps Mon 7/30 22:22:11.536 MiniPlayer is using Pull mode playback Mon 7/30 22:22:11.536 openURL0() java.net.SocketTimeoutException: Read timed out java.net.SocketTimeoutException: Read timed out Mon 7/30 22:22:26.536 at java.net.SocketInputStream.socketRead0(Native Method) Mon 7/30 22:22:26.536 at java.net.SocketInputStream.read(Unknown Source) Mon 7/30 22:22:26.537 at java.net.SocketInputStream.read(Unknown Source) Mon 7/30 22:22:26.537 at java.io.DataInputStream.readInt(Unknown Source) Mon 7/30 22:22:26.537 at sage.b1.if(Unknown Source) Mon 7/30 22:22:26.537 at sage.b1.load(Unknown Source) Mon 7/30 22:22:26.537 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:26.537 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:26.538 at sage.VideoFrame.run(Unknown Source) Mon 7/30 22:22:26.538 at java.lang.Thread.run(Unknown Source) sage.PlaybackException Mon 7/30 22:22:26.539 at sage.b1.load(Unknown Source) Mon 7/30 22:22:26.540 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:26.540 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:26.540 at sage.VideoFrame.run(Unknown Source) Mon 7/30 22:22:26.540 at java.lang.Thread.run(Unknown Source) Mon 7/30 22:22:26.543 VideFrame had an error loading the file. It must abort the file load. Mon 7/30 22:22:26.543 Closing down MiniPlayer Mon 7/30 22:22:26.544 closeDriver0() Mon 7/30 22:22:26.665 processOptionsMenu optionsMenu=default:null|OptionsMenu:ErrorMessage Mon 7/30 22:22:26.672 VF processing job VFJob[Play r=0.0 t=0 file=null ifn=null] nPlayin=false Mon 7/30 22:22:26.673 VF discarding job VFJob[Play r=0.0 t=0 file=null ifn=null] Mon 7/30 22:22:26.673 VF processing job VFJob[TimeSet r=0.0 t=1185844927688 file=null ifn=null] nPlayin=false Mon 7/30 22:22:26.673 VF discarding job VFJob[TimeSet r=0.0 t=1185844927688 file=null ifn=null] Mon 7/30 22:22:26.673 VF processing job null nPlayin=false Mon 7/30 22:22:26.673 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:31.652 MiniUI got connection from Socket[addr=/127.0.0.1,port=36294,localport=31099] Mon 7/30 22:22:31.668 MiniPlayer is adding to its map:0050040db957 Mon 7/30 22:22:33.534 processOptionsMenu optionsMenu=default:null|OptionsMenu:Wide OSD Options Mon 7/30 22:22:33.965 Loading 240x90 image from file /opt/sagetv/server/STVs/SageTV3/Thumbnailbkgd.png Mon 7/30 22:22:36.470 setUI(sage.b2@502a39[Main Menu]) histIdx=2 uiHistory=[sage.b2@1eef3b0[Main Menu], sage.b2@1d1011a[MediaPlayer OSD], sage.b2@502a39[Main Menu]] Mon 7/30 22:22:36.598 Loading 190x116 image from file /opt/sagetv/server/STVs/SageTV3/RecordingNow.png Mon 7/30 22:22:36.715 Loading 117x102 image from file /opt/sagetv/server/STVs/SageTV3/GoWindowed.png Mon 7/30 22:22:38.901 VF.submitJob(VFJob[CloseMF r=0.0 t=0 file=null ifn=null]) Mon 7/30 22:22:38.904 VF processing job VFJob[CloseMF r=0.0 t=0 file=null ifn=null] nPlayin=false Mon 7/30 22:22:38.905 VF processing on UI Thread VFJob[CloseMF r=0.0 t=0 file=null ifn=null] Mon 7/30 22:22:38.905 Seeker.finishWatch(UIManager:localhost@@0050040db957-e2a37b) Mon 7/30 22:22:38.906 setUI(sage.b2@1d1011a[MediaPlayer OSD]) histIdx=3 uiHistory=[sage.b2@1eef3b0[Main Menu], sage.b2@1d1011a[MediaPlayer OSD], sage.b2@502a39[Main Menu], sage.b2@1d1011a[MediaPlayer OSD]] Mon 7/30 22:22:38.914 VF processing job null nPlayin=false Mon 7/30 22:22:38.914 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:38.932 Seeker awoken Mon 7/30 22:22:38.934 MARK 1 currRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] enc=video0 clients=[] ir=false Mon 7/30 22:22:38.934 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:38.934 newRecord=null Mon 7/30 22:22:38.934 Change in record, logging recorded data. Mon 7/30 22:22:38.936 Seeker.endRecord(Mon 7/30 22:22:38.933) currRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:38.956 Scheduler awoken Mon 7/30 22:22:38.957 VF.submitJob(VFJob[InactiveFile r=0.0 t=0 file=null ifn=/var/media/tv/392251032_1_0730_2222-0.mpg]) Mon 7/30 22:22:38.958 VF.submitJob(VFJob[InactiveFile r=0.0 t=0 file=null ifn=/var/media/tv/392251032_1_0730_2222-0.mpg]) Mon 7/30 22:22:38.959 VF processing job VFJob[InactiveFile r=0.0 t=0 file=null ifn=/var/media/tv/392251032_1_0730_2222-0.mpg] nPlayin=false Mon 7/30 22:22:38.959 VF discarding job VFJob[InactiveFile r=0.0 t=0 file=null ifn=/var/media/tv/392251032_1_0730_2222-0.mpg] Mon 7/30 22:22:38.959 VF processing job null nPlayin=false Mon 7/30 22:22:38.959 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:39.144 NOTHING TO RECORD FOR NOW... Mon 7/30 22:22:39.144 stopEncoding for IVTV capture device Mon 7/30 22:22:39.144 Waiting for IVTV capture thread to terminate Mon 7/30 22:22:39.145 VideoFrame.watch(A[12231,1,"No Data",-392251032@0730.21:00,120]) Mon 7/30 22:22:39.146 watchThisFile=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933]] Mon 7/30 22:22:39.146 Called Seeker.requestWatch(A[12231,1,"No Data",-392251032@0730.21:00,120]) hostname=UIManager:localhost@@0050040db957-e2a37b Mon 7/30 22:22:39.146 findBestEncoderForNow(A[12231,1,"No Data",-392251032@0730.21:00,120] record=false host=UIManager:localhost@@0050040db957-e2a37b) Mon 7/30 22:22:39.147 foundBestEncoder3=sage.ca$c@1089de1[video0] Mon 7/30 22:22:39.148 VF.submitJob(VFJob[Play r=0.0 t=0 file=null ifn=null]) Mon 7/30 22:22:39.148 VF processing job VFJob[Play r=0.0 t=0 file=null ifn=null] nPlayin=false Mon 7/30 22:22:39.148 VF discarding job VFJob[Play r=0.0 t=0 file=null ifn=null] Mon 7/30 22:22:39.149 VF processing job null nPlayin=false Mon 7/30 22:22:39.150 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:39.150 VF.submitJob(VFJob[TimeSet r=0.0 t=1185844959150 file=null ifn=null]) Mon 7/30 22:22:39.150 VF processing job VFJob[TimeSet r=0.0 t=1185844959150 file=null ifn=null] nPlayin=false Mon 7/30 22:22:39.151 VF discarding job VFJob[TimeSet r=0.0 t=1185844959150 file=null ifn=null] Mon 7/30 22:22:39.151 VF processing job null nPlayin=false Mon 7/30 22:22:39.151 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:39.208 IVTV capture thread terminating Mon 7/30 22:22:39.209 MARK 1 currRecord=null enc=video0 clients=[UIManager:localhost@@0050040db957-e2a37b] ir=false Mon 7/30 22:22:39.210 defaultRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:39.210 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:39.210 FORCE WATCH executing clients=[UIManager:localhost@@0050040db957-e2a37b] Mon 7/30 22:22:39.210 newRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:39.210 Change in record to another show. Entering device record mode. - LATER Mon 7/30 22:22:39.211 Change in record to another show. Entering device record mode. - NOW Mon 7/30 22:22:39.211 Seeker.startRecord(video0 A[12231,1,"No Data",-392251032@0730.21:00,120], currTime=Mon 7/30 22:22:39.209) currRecord=null switch=false Mon 7/30 22:22:39.211 Setting up MMC video for recording new show & tuning channel conn=video0 TV Tuner Mon 7/30 22:22:39.212 Using quality setting "Great" for recording Mon 7/30 22:22:39.213 MediaFile startSegment enc=video0 Great MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933]] Mon 7/30 22:22:39.214 MediaFile created subfile:/var/media/tv/392251032_1_0730_2222-1.mpg MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933]] Mon 7/30 22:22:39.215 VF processing job null nPlayin=false Mon 7/30 22:22:39.215 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:39.258 Seeker channel string=1 Mon 7/30 22:22:39.259 startEncoding for IVTV capture device file=/var/media/tv/392251032_1_0730_2222-1.mpg chan=1 Mon 7/30 22:22:39.259 IVTV: video0 PVR card type is Hauppauge WinTV PVR-350 Mon 7/30 22:22:39.259 setInput0 0 0 54 8 Mon 7/30 22:22:39.259 updateColors0 b=128 c=128 h=128 s=128 Mon 7/30 22:22:39.266 setEncodingProperties0 Great Mon 7/30 22:22:39.266 Set encoding property audiooutputmode to 0 Mon 7/30 22:22:39.266 Set encoding property audiocrc to 0 Mon 7/30 22:22:39.266 Set encoding property gopsize to 15 Mon 7/30 22:22:39.266 Set encoding property videobitrate to 3800000 Mon 7/30 22:22:39.267 Set encoding property inversetelecine to 0 Mon 7/30 22:22:39.267 Set encoding property closedgop to 0 Mon 7/30 22:22:39.267 Set encoding property vbr to 0 Mon 7/30 22:22:39.267 Set encoding property outputstreamtype to 10 Mon 7/30 22:22:39.267 Set encoding property width to 720 Mon 7/30 22:22:39.267 Set encoding property height to 576 Mon 7/30 22:22:39.268 Set encoding property audiobitrate to 384 Mon 7/30 22:22:39.268 Set encoding property audiosampling to 48000 Mon 7/30 22:22:39.268 Set encoding property disablefilter to 1 Mon 7/30 22:22:39.268 Set encoding property medianfilter to 3 Mon 7/30 22:22:39.268 Set encoding property fps to 25 Mon 7/30 22:22:39.268 Set encoding property ipb to 0 Mon 7/30 22:22:39.269 Set encoding property deinterlace to 0 Mon 7/30 22:22:39.269 Set encoding property aspectratio to 1 Mon 7/30 22:22:39.269 Default DNR mode=1 spatial=0 temporal=4 type=0 Mon 7/30 22:22:39.286 setup encoding /var/media/tv/392251032_1_0730_2222-1.mpg Mon 7/30 22:22:39.287 RootFile=/ fstype=0xef53 fileLength=0 Mon 7/30 22:22:39.287 Checking video directories for new files Mon 7/30 22:22:39.288 VF processing job null nPlayin=false Mon 7/30 22:22:39.288 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:39.289 Diskspace checking is running Mon 7/30 22:22:39.289 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:22:39.289 Enforcing keep at most limits for the files... Mon 7/30 22:22:39.290 Seeker clearing unwanted and partial files... Mon 7/30 22:22:39.290 needFreeSize = 0.4941 GB currFreeSize=71.179374592 GB Mon 7/30 22:22:39.291 Seeker waiting for 37 mins. Mon 7/30 22:22:39.292 Scheduler.updateSchedule() called time=Mon 7/30 22:22:39.291 manual=[] schedules={video0=[Sched=[A[12231,1,"No Data",-392251032@0730.21:00,120]] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:22:39.292 # Airs=0 Mon 7/30 22:22:39.293 MUST SEE FINAL-video0-[] Mon 7/30 22:22:39.293 Scheduler cleanup - Removing A[12231,1,"No Data",-392251032@0730.21:00,120] from schedule because it has no WP. Mon 7/30 22:22:39.294 Evaluating Potentials Mon 7/30 22:22:39.294 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:22:39.294 [A[12231,1,"No Data",-392251032@0730.21:00,120]] Mon 7/30 22:22:39.294 Seeker awoken Mon 7/30 22:22:39.295 MARK 1 currRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] enc=video0 clients=[UIManager:localhost@@0050040db957-e2a37b] ir=false Mon 7/30 22:22:39.296 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:39.296 FORCE WATCH abandoned because it's currently being recorded clients=[UIManager:localhost@@0050040db957-e2a37b] Mon 7/30 22:22:39.296 newRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:39.296 Keeping record just the way it is. Mon 7/30 22:22:39.310 Starting IVTV capture thread Mon 7/30 22:22:39.320 RootFile=/ fstype=0xef53 fileLength=0 Mon 7/30 22:22:39.321 Checking video directories for new files Mon 7/30 22:22:39.322 Diskspace checking is running Mon 7/30 22:22:39.322 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:22:39.322 Enforcing keep at most limits for the files... Mon 7/30 22:22:39.322 Seeker clearing unwanted and partial files... Mon 7/30 22:22:39.323 needFreeSize = 0.4941 GB currFreeSize=71.179374592 GB Mon 7/30 22:22:39.323 Seeker waiting for 37 mins. Mon 7/30 22:22:39.324 VF processing job null nPlayin=false Mon 7/30 22:22:39.324 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:39.330 VF.submitJob(VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null]) Mon 7/30 22:22:39.331 VF processing job VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:39.333 VF processing on UI Thread VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] Mon 7/30 22:22:39.333 VideoFrame creating new media player for file:MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] Mon 7/30 22:22:39.337 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:39.337 VF network encoder playback detected: false Mon 7/30 22:22:39.338 VF waiting for data to appear in new file...liveWait=1872 Mon 7/30 22:22:39.338 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:39.476 Scheduler awoken Mon 7/30 22:22:39.477 Scheduler.updateSchedule() called time=Mon 7/30 22:22:39.477 manual=[] schedules={video0=[Sched=[A[12231,1,"No Data",-392251032@0730.21:00,120]] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:22:39.478 # Airs=0 Mon 7/30 22:22:39.478 MUST SEE FINAL-video0-[] Mon 7/30 22:22:39.478 Scheduler cleanup - Removing A[12231,1,"No Data",-392251032@0730.21:00,120] from schedule because it has no WP. Mon 7/30 22:22:39.479 Evaluating Potentials Mon 7/30 22:22:39.479 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:22:39.479 [A[12231,1,"No Data",-392251032@0730.21:00,120]] Mon 7/30 22:22:39.479 Seeker awoken Mon 7/30 22:22:39.480 MARK 1 currRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] enc=video0 clients=[UIManager:localhost@@0050040db957-e2a37b] ir=false Mon 7/30 22:22:39.508 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:39.508 FORCE WATCH abandoned because it's currently being recorded clients=[UIManager:localhost@@0050040db957-e2a37b] Mon 7/30 22:22:39.508 newRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:39.509 Keeping record just the way it is. Mon 7/30 22:22:39.540 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:39.541 VF network encoder playback detected: false Mon 7/30 22:22:39.541 VF waiting for data to appear in new file...liveWait=1668 Mon 7/30 22:22:39.541 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:39.556 RootFile=/ fstype=0xef53 fileLength=0 Mon 7/30 22:22:39.557 Checking video directories for new files Mon 7/30 22:22:39.558 Diskspace checking is running Mon 7/30 22:22:39.558 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:22:39.558 Enforcing keep at most limits for the files... Mon 7/30 22:22:39.559 Seeker clearing unwanted and partial files... Mon 7/30 22:22:39.559 needFreeSize = 0.4941 GB currFreeSize=71.1793664 GB Mon 7/30 22:22:39.560 Seeker waiting for 37 mins. Mon 7/30 22:22:39.560 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:39.561 VF network encoder playback detected: false Mon 7/30 22:22:39.561 VF waiting for data to appear in new file...liveWait=1648 Mon 7/30 22:22:39.562 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:39.622 Scheduler awoken Mon 7/30 22:22:39.624 Scheduler.updateSchedule() called time=Mon 7/30 22:22:39.623 manual=[] schedules={video0=[Sched=[A[12231,1,"No Data",-392251032@0730.21:00,120]] MustSee=[]]} scheduleRandSize=0 Mon 7/30 22:22:39.624 # Airs=0 Mon 7/30 22:22:39.625 MUST SEE FINAL-video0-[] Mon 7/30 22:22:39.625 Scheduler cleanup - Removing A[12231,1,"No Data",-392251032@0730.21:00,120] from schedule because it has no WP. Mon 7/30 22:22:39.625 Evaluating Potentials Mon 7/30 22:22:39.625 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE video0 Mon 7/30 22:22:39.626 [A[12231,1,"No Data",-392251032@0730.21:00,120]] Mon 7/30 22:22:39.626 Seeker awoken Mon 7/30 22:22:39.627 MARK 1 currRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] enc=video0 clients=[UIManager:localhost@@0050040db957-e2a37b] ir=false Mon 7/30 22:22:39.627 Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807 Mon 7/30 22:22:39.627 FORCE WATCH abandoned because it's currently being recorded clients=[UIManager:localhost@@0050040db957-e2a37b] Mon 7/30 22:22:39.628 newRecord=A[12231,1,"No Data",-392251032@0730.21:00,120] Mon 7/30 22:22:39.628 Keeping record just the way it is. Mon 7/30 22:22:39.643 RootFile=/ fstype=0xef53 fileLength=0 Mon 7/30 22:22:39.644 Checking video directories for new files Mon 7/30 22:22:39.645 Diskspace checking is running Mon 7/30 22:22:39.645 Verifying existence of all TV media files in database fixDurs=false avoidArchive=true Mon 7/30 22:22:39.645 Enforcing keep at most limits for the files... Mon 7/30 22:22:39.645 Seeker clearing unwanted and partial files... Mon 7/30 22:22:39.646 needFreeSize = 0.4941 GB currFreeSize=71.1793664 GB Mon 7/30 22:22:39.646 Seeker waiting for 37 mins. Mon 7/30 22:22:39.647 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:39.647 VF network encoder playback detected: false Mon 7/30 22:22:39.648 VF waiting for data to appear in new file...liveWait=1561 Mon 7/30 22:22:39.648 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:39.854 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:39.855 VF network encoder playback detected: false Mon 7/30 22:22:39.855 VF waiting for data to appear in new file...liveWait=1354 Mon 7/30 22:22:39.856 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:40.060 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:40.062 VF network encoder playback detected: false Mon 7/30 22:22:40.063 VF waiting for data to appear in new file...liveWait=1147 Mon 7/30 22:22:40.063 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:40.264 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:40.265 VF network encoder playback detected: false Mon 7/30 22:22:40.265 VF waiting for data to appear in new file...liveWait=944 Mon 7/30 22:22:40.265 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:40.468 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:40.469 VF network encoder playback detected: false Mon 7/30 22:22:40.469 VF waiting for data to appear in new file...liveWait=740 Mon 7/30 22:22:40.470 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:40.637 Found next seq hdr code! Mon 7/30 22:22:40.673 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:40.673 VF network encoder playback detected: false Mon 7/30 22:22:40.673 VF waiting for data to appear in new file...liveWait=536 Mon 7/30 22:22:40.674 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:40.877 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:40.877 VF network encoder playback detected: false Mon 7/30 22:22:40.877 VF waiting for data to appear in new file...liveWait=332 Mon 7/30 22:22:40.878 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:41.080 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:41.081 VF network encoder playback detected: false Mon 7/30 22:22:41.081 VF waiting for data to appear in new file...liveWait=128 Mon 7/30 22:22:41.082 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:41.284 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:41.285 VF network encoder playback detected: false Mon 7/30 22:22:41.285 VF waiting for data to appear in new file...liveWait=-76 Mon 7/30 22:22:41.286 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:41.489 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:41.489 VF network encoder playback detected: false Mon 7/30 22:22:41.489 VF waiting for data to appear in new file...liveWait=-280 Mon 7/30 22:22:41.490 VF thread is now waiting for 0:00:00.200 Mon 7/30 22:22:41.694 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] nPlayin=false Mon 7/30 22:22:41.694 VF network encoder playback detected: false Mon 7/30 22:22:41.695 VF processing on UI Thread VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] ifn=null] Mon 7/30 22:22:41.696 VF file=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] targetTime = Mon 7/30 22:22:39.209 Mon 7/30 22:22:41.697 VideoFrame.timeSelected(Mon 7/30 22:22:39.209, true) currFile=MediaFile[id=16659 A[12231,1,"No Data",-392251032@0730.21:00,120] host=localhost encodedBy=video0 Great format=MPEG2-PS 0:00:00 0 kbps [#0 Video[MPEG2-Video 25.0 fps 720x576 4:3 3800 kbps interlaced]#1 Audio[MP2 48000 Hz 2 channels 384 kbps]] /var/media/tv/392251032_1_0730_2222-0.mpg, Seg0[Mon 7/30 22:22:06.720-Mon 7/30 22:22:38.933], Seg1[Mon 7/30 22:22:39.209-Wed 12/31 21:00:00.000]] Mon 7/30 22:22:41.697 initDriver0() Mon 7/30 22:22:41.697 MiniPlayer established for 0050040db957 Mon 7/30 22:22:41.702 getEstimatedBW=65584000 estimatedBWBytes=16396 estimatedBWTime=2 Mon 7/30 22:22:41.702 MiniPlayer got an estimate from the UI on bandwidth of 65584Kbps Mon 7/30 22:22:41.702 MiniPlayer is using Pull mode playback Mon 7/30 22:22:41.707 openURL0() java.net.SocketTimeoutException: Read timed out java.net.SocketTimeoutException: Read timed out Mon 7/30 22:22:56.707 at java.net.SocketInputStream.socketRead0(Native Method) Mon 7/30 22:22:56.707 at java.net.SocketInputStream.read(Unknown Source) Mon 7/30 22:22:56.707 at java.net.SocketInputStream.read(Unknown Source) Mon 7/30 22:22:56.708 at java.io.DataInputStream.readInt(Unknown Source) Mon 7/30 22:22:56.708 at sage.b1.if(Unknown Source) Mon 7/30 22:22:56.708 at sage.b1.load(Unknown Source) Mon 7/30 22:22:56.708 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:56.708 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:56.708 at sage.VideoFrame.run(Unknown Source) Mon 7/30 22:22:56.708 at java.lang.Thread.run(Unknown Source) sage.PlaybackException Mon 7/30 22:22:56.710 at sage.b1.load(Unknown Source) Mon 7/30 22:22:56.710 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:56.710 at sage.VideoFrame.a(Unknown Source) Mon 7/30 22:22:56.710 at sage.VideoFrame.run(Unknown Source) Mon 7/30 22:22:56.710 at java.lang.Thread.run(Unknown Source) Mon 7/30 22:22:56.711 VideFrame had an error loading the file. It must abort the file load. Mon 7/30 22:22:56.711 Closing down MiniPlayer Mon 7/30 22:22:56.711 closeDriver0() Mon 7/30 22:22:56.713 VF processing job null nPlayin=false Mon 7/30 22:22:56.714 VF thread is now waiting for 0:00:00.000 Mon 7/30 22:22:56.720 processOptionsMenu optionsMenu=default:null|OptionsMenu:ErrorMessage Mon 7/30 22:23:01.747 MiniUI got connection from Socket[addr=/127.0.0.1,port=36295,localport=31099] Mon 7/30 22:23:01.767 MiniPlayer is adding to its map:0050040db957 Mon 7/30 22:23:22.222 processOptionsMenu optionsMenu=default:null|OptionsMenu:Wide OSD Options Mon 7/30 22:23:24.549 setUI(sage.b2@502a39[Main Menu]) histIdx=4 uiHistory=[sage.b2@1eef3b0[Main Menu], sage.b2@1d1011a[MediaPlayer OSD], sage.b2@502a39[Main Menu], sage.b2@1d1011a[MediaPlayer OSD], sage.b2@502a39[Main Menu]] Mon 7/30 22:24:04.197 Ministry is waiting for 180 sec