Wed 4/11 23:28:16.506 [main@191beef] user.dir2=C:\Program Files (x86)\SageTV\SageTV
Wed 4/11 23:28:16.512 [main@191beef] classpath=C:\Program Files (x86)\SageTV\SageTV\Sage.jar;C:\Program Files (x86)\SageTV\SageTV\JARs\lucene-core-3.6.0.jar;C:\Program Files (x86)\SageTV\SageTV\xerces.jar;C:\Program Files (x86)\SageTV\SageTV\plugin.jar;C:\Program Files (x86)\SageTV\SageTV\;;JARs\activation.jar;JARs\activemq-all-5.3.1.jar;JARs\ant.jar;JARs\api-common-2.0.jar;JARs\cling-core-2.0.1.jar;JARs\cling-support-2.0.1.jar;JARs\CommercialDetector.jar;JARs\commons-codec-1.9.jar;JARs\commons-dbutils-1.3.jar;JARs\commons-io-2.4.jar;JARs\commons-jxpath-1.1.jar;JARs\commons-lang-2.4.jar;JARs\commons-lang3-3.4.jar;JARs\commons-logging-1.2.jar;JARs\commons-net-1.4.1.jar;JARs\concurrent-1.3.2.jar;JARs\core-3.1.1.jar;JARs\df_sageutils.jar;JARs\dom4j-1.6.1.jar;JARs\EPPlayOn.jar;JARs\gkusnick.sagetv.jar;JARs\GoogleWeather.jar;JARs\gson-1.7.1.jar;JARs\h2-1.2.145.jar;JARs\hamcrest-core-1.3.jar;JARs\htmlparser-1.6.jar;JARs\httpclient-4.5.1.jar;JARs\httpcore-4.4.3.jar;JARs\jackson-annotations-2.6.3.jar;JARs\jackson-core-2.6.3.jar;JARs\jackson-databind-2.6.3.jar;JARs\jcifs-1.1.6.jar;JARs\jcs-1.3.jar;JARs\jdic.jar;JARs\jetty-6.1.19.jar;JARs\jetty-ajp-6.1.19.jar;JARs\jetty-rewrite-handler-6.1.19.jar;JARs\jetty-sslengine-6.1.19.jar;JARs\jetty-starter.jar;JARs\jetty-util-6.1.19.jar;JARs\jsoup.jar;JARs\jsp-2.1-jetty-6.1.19.jar;JARs\jsp-2.1.jar;JARs\jsp-api-2.1.jar;JARs\junit-4.12.jar;JARs\log4j-1.2.17.jar;JARs\lucene-core-3.6.0.jar;JARs\mail.jar;JARs\mailcheck.jar;JARs\nielm_getrssnews.jar;JARs\nielm_sageimdb.jar;JARs\nielm_sagemenureader.jar;JARs\nielm_sageutls.jar;JARs\ortus-mq.jar;JARs\packager.jar;JARs\phoenix.jar;JARs\PlayOnUtils.jar;JARs\sagemc.jar;JARs\sageortus.jar;JARs\SageTCPServer.jar;JARs\sagex-api.jar;JARs\sagex-h2.jar;JARs\sbbi-upnplib-1.0.3.jar;JARs\seamless-http-1.1.0.jar;JARs\seamless-util-1.1.0.jar;JARs\seamless-xml-1.1.0.jar;JARs\servlet-api-2.5-6.1.19.jar;JARs\slf4j-api-1.7.12.jar;JARs\slf4j-log4j12-1.7.12.jar;JARs\themoviedbapi-4.1.jar;JARs\thetvdbapi-1.8.jar;JARs\validation-api-1.1.0.Final.jar;JARs\vecmath.jar
Wed 4/11 23:28:16.525 [main@191beef] JVM version=1.8.0_161
Wed 4/11 23:28:16.530 [main@191beef] OS=Windows 10 10.0
Wed 4/11 23:28:16.534 [main@191beef] client=false
Wed 4/11 23:28:16.538 [main@191beef] locale=en_US
Wed 4/11 23:28:16.544 [ThreadMonitor@15f425b] Thread CPU monitoring started interval=300000
Wed 4/11 23:28:16.548 [main@191beef] SageTV V9.1.8.770
Wed 4/11 23:28:16.564 [main@191beef] hostname=DESKTOP-PM910R9
Wed 4/11 23:28:16.568 [main@191beef] Splash: User Interface Manager is initializing...
Wed 4/11 23:28:16.666 [main@191beef] Splash: Object Database is initializing...
Wed 4/11 23:28:16.734 [main@191beef] dbFile=C:\Program Files\SageTV\SageTV\Wiz.bin(23947429) dbBackupFile=C:\Program Files\SageTV\SageTV\Wiz.bak(25490525)
Wed 4/11 23:28:16.741 [main@191beef] Wizard starting to load database info...
Wed 4/11 23:28:16.746 [main@191beef] Splash: Object Database Source is initializing...
Wed 4/11 23:28:16.759 [main@191beef] Reading DB file:C:\Program Files\SageTV\SageTV\Wiz.bin with version 87
Wed 4/11 23:28:16.762 [main@191beef] DBFile at version 87 FileSize=23947429
Wed 4/11 23:28:16.766 [main@191beef] Wizard allocating table for Year of size 96
Wed 4/11 23:28:16.770 [main@191beef] Splash: Object Database is initializing... 0% done
Wed 4/11 23:28:16.773 [main@191beef] Wizard loading main index for Year bytes=1350
Wed 4/11 23:28:16.777 [main@191beef] Load time for Year 4 msec 0.041666668 msec/object
Wed 4/11 23:28:16.781 [main@191beef] Index check time for Year 0 msec
Wed 4/11 23:28:16.785 [main@191beef] Splash: Object Database is initializing... 0% done
Wed 4/11 23:28:16.788 [main@191beef] Wizard allocating table for Network of size 26
Wed 4/11 23:28:16.792 [main@191beef] Splash: Object Database is initializing... 0% done
Wed 4/11 23:28:16.795 [main@191beef] Wizard loading main index for Network bytes=383
Wed 4/11 23:28:16.799 [main@191beef] Load time for Network 4 msec 0.15384616 msec/object
Wed 4/11 23:28:16.802 [main@191beef] Index check time for Network 0 msec
Wed 4/11 23:28:16.806 [main@191beef] Splash: Object Database is initializing... 0% done
Wed 4/11 23:28:16.809 [main@191beef] Wizard allocating table for Title of size 8663
Wed 4/11 23:28:16.813 [main@191beef] Splash: Object Database is initializing... 0% done
Wed 4/11 23:28:16.817 [main@191beef] Wizard loading main index for Title bytes=280046
Wed 4/11 23:28:16.829 [main@191beef] Load time for Title 12 msec 0.0013852015 msec/object
Wed 4/11 23:28:16.837 [main@191beef] Index check time for Title 4 msec
Wed 4/11 23:28:16.842 [main@191beef] Splash: Object Database is initializing... 0% done
Wed 4/11 23:28:16.845 [main@191beef] Wizard loading alt index 1 for Title bytes=34658
Wed 4/11 23:28:16.850 [main@191beef] Load time for alt index 1 for Title 5 msec
Wed 4/11 23:28:16.855 [main@191beef] Index check time for alt index 1 for Title 1 msec
Wed 4/11 23:28:16.859 [main@191beef] Splash: Object Database is initializing... 1% done
Wed 4/11 23:28:16.862 [main@191beef] Wizard allocating table for Channel of size 506
Wed 4/11 23:28:16.866 [main@191beef] Splash: Object Database is initializing... 1% done
Wed 4/11 23:28:16.869 [main@191beef] Wizard loading main index for Channel bytes=27866
Wed 4/11 23:28:16.874 [main@191beef] Load time for Channel 5 msec 0.009881423 msec/object
Wed 4/11 23:28:16.878 [main@191beef] Index check time for Channel 0 msec
Wed 4/11 23:28:16.881 [main@191beef] Splash: Object Database is initializing... 1% done
Wed 4/11 23:28:16.885 [main@191beef] Wizard allocating table for Bonus of size 5671
Wed 4/11 23:28:16.888 [main@191beef] Splash: Object Database is initializing... 1% done
Wed 4/11 23:28:16.891 [main@191beef] Wizard loading main index for Bonus bytes=118390
Wed 4/11 23:28:16.896 [main@191beef] Load time for Bonus 5 msec 8.816787E-4 msec/object
Wed 4/11 23:28:16.900 [main@191beef] Index check time for Bonus 0 msec
Wed 4/11 23:28:16.903 [main@191beef] Splash: Object Database is initializing... 1% done
Wed 4/11 23:28:16.907 [main@191beef] Wizard allocating table for People of size 60583
Wed 4/11 23:28:16.910 [main@191beef] Splash: Object Database is initializing... 2% done
Wed 4/11 23:28:16.913 [main@191beef] Wizard loading main index for People bytes=2676458
Wed 4/11 23:28:16.923 [main@191beef] Lucene index(person): rooted at /rw/\lucene/ running at /rw/\lucene-run/ DiskIndex:false RunningDiskIndex:false
Wed 4/11 23:28:17.020 [main@191beef] Lucene index(person) reader opened in 2
Wed 4/11 23:28:17.029 [main@191beef] Lucene index(person) docs: 0
Wed 4/11 23:28:17.036 [main@191beef] Increased Thread pool to size=1
Wed 4/11 23:28:17.041 [main@191beef] Lucene index(person) does not have same item count as wizard (idx:0, wiz:60583) - RESETING
Wed 4/11 23:28:17.048 [main@191beef] Index(person) reset
Wed 4/11 23:28:17.132 [main@191beef] Load time for People 219 msec 0.0036148755 msec/object
Wed 4/11 23:28:17.140 [main@191beef] Index check time for People 2 msec
Wed 4/11 23:28:17.144 [LucenePersonTransactionTask@946c9e] 4.97% / 20120 work queue, 1001 inserted @ 0.09 ms/peep avg [tot:90ms]
Wed 4/11 23:28:17.147 [main@191beef] Lucene index(person) built from Wizard
Wed 4/11 23:28:17.151 [main@191beef] Splash: Object Database is initializing... 2% done
Wed 4/11 23:28:17.154 [main@191beef] Wizard loading alt index 2 for People bytes=242338
Wed 4/11 23:28:17.162 [LucenePersonTransactionTask@946c9e] 9.94% / 20120 work queue, 2001 inserted @ 0.05 ms/peep avg [tot:105ms]
Wed 4/11 23:28:17.166 [main@191beef] Load time for alt index 2 for People 11 msec
Wed 4/11 23:28:17.186 [LucenePersonTransactionTask@946c9e] 14.91% / 20120 work queue, 3001 inserted @ 0.04 ms/peep avg [tot:124ms]
Wed 4/11 23:28:17.191 [main@191beef] Index check time for alt index 2 for People 9 msec
Wed 4/11 23:28:17.194 [main@191beef] Wizard loading alt index 16 for People bytes=242338
Wed 4/11 23:28:17.198 [LucenePersonTransactionTask@946c9e] 19.88% / 20120 work queue, 4001 inserted @ 0.03 ms/peep avg [tot:129ms]
Wed 4/11 23:28:17.202 [main@191beef] Load time for alt index 16 for People 8 msec
Wed 4/11 23:28:17.206 [LucenePersonTransactionTask@946c9e] 24.85% / 20120 work queue, 5001 inserted @ 0.03 ms/peep avg [tot:133ms]
Wed 4/11 23:28:17.210 [main@191beef] Index check time for alt index 16 for People 3 msec
Wed 4/11 23:28:17.213 [main@191beef] Wizard allocating table for SubCategory of size 144
Wed 4/11 23:28:17.216 [LucenePersonTransactionTask@946c9e] 29.82% / 20120 work queue, 6001 inserted @ 0.02 ms/peep avg [tot:137ms]
Wed 4/11 23:28:17.220 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.223 [main@191beef] Wizard loading main index for SubCategory bytes=2707
Wed 4/11 23:28:17.226 [LucenePersonTransactionTask@946c9e] 34.79% / 20120 work queue, 7001 inserted @ 0.02 ms/peep avg [tot:142ms]
Wed 4/11 23:28:17.230 [main@191beef] Load time for SubCategory 3 msec 0.020833334 msec/object
Wed 4/11 23:28:17.234 [main@191beef] Index check time for SubCategory 0 msec
Wed 4/11 23:28:17.238 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.241 [main@191beef] Wizard allocating table for Rated of size 5
Wed 4/11 23:28:17.245 [LucenePersonTransactionTask@946c9e] 39.76% / 20120 work queue, 8001 inserted @ 0.02 ms/peep avg [tot:153ms]
Wed 4/11 23:28:17.255 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.260 [main@191beef] Wizard loading main index for Rated bytes=67
Wed 4/11 23:28:17.263 [LucenePersonTransactionTask@946c9e] 44.73% / 20120 work queue, 9001 inserted @ 0.02 ms/peep avg [tot:159ms]
Wed 4/11 23:28:17.267 [main@191beef] Load time for Rated 3 msec 0.6 msec/object
Wed 4/11 23:28:17.270 [main@191beef] Index check time for Rated 0 msec
Wed 4/11 23:28:17.274 [LucenePersonTransactionTask@946c9e] 49.70% / 20120 work queue, 10001 inserted @ 0.02 ms/peep avg [tot:164ms]
Wed 4/11 23:28:17.277 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.281 [main@191beef] Wizard allocating table for ParentalRating of size 0
Wed 4/11 23:28:17.285 [LucenePersonTransactionTask@946c9e] 54.67% / 20120 work queue, 11001 inserted @ 0.02 ms/peep avg [tot:170ms]
Wed 4/11 23:28:17.288 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.292 [main@191beef] Wizard allocating table for ExtendedRating of size 11
Wed 4/11 23:28:17.295 [LucenePersonTransactionTask@946c9e] 59.64% / 20120 work queue, 12001 inserted @ 0.01 ms/peep avg [tot:175ms]
Wed 4/11 23:28:17.298 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.302 [main@191beef] Wizard loading main index for ExtendedRating bytes=250
Wed 4/11 23:28:17.327 [main@191beef] Load time for ExtendedRating 25 msec 2.2727273 msec/object
Wed 4/11 23:28:17.331 [LucenePersonTransactionTask@946c9e] 64.61% / 20120 work queue, 13001 inserted @ 0.02 ms/peep avg [tot:204ms]
Wed 4/11 23:28:17.335 [main@191beef] Index check time for ExtendedRating 0 msec
Wed 4/11 23:28:17.338 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.342 [LucenePersonTransactionTask@946c9e] 69.58% / 20120 work queue, 14001 inserted @ 0.01 ms/peep avg [tot:208ms]
Wed 4/11 23:28:17.345 [main@191beef] Wizard allocating table for Category of size 138
Wed 4/11 23:28:17.349 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.353 [LucenePersonTransactionTask@946c9e] 74.55% / 20120 work queue, 15001 inserted @ 0.01 ms/peep avg [tot:214ms]
Wed 4/11 23:28:17.356 [main@191beef] Wizard loading main index for Category bytes=2586
Wed 4/11 23:28:17.360 [main@191beef] Load time for Category 7 msec 0.050724637 msec/object
Wed 4/11 23:28:17.363 [LucenePersonTransactionTask@946c9e] 79.52% / 20120 work queue, 16001 inserted @ 0.01 ms/peep avg [tot:219ms]
Wed 4/11 23:28:17.367 [main@191beef] Index check time for Category 0 msec
Wed 4/11 23:28:17.371 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.375 [main@191beef] Wizard allocating table for PrimeTitle of size 0
Wed 4/11 23:28:17.379 [LucenePersonTransactionTask@946c9e] 84.49% / 20120 work queue, 17001 inserted @ 0.01 ms/peep avg [tot:226ms]
Wed 4/11 23:28:17.383 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.386 [main@191beef] Wizard allocating table for Show of size 42738
Wed 4/11 23:28:17.390 [LucenePersonTransactionTask@946c9e] 89.46% / 20120 work queue, 18001 inserted @ 0.01 ms/peep avg [tot:231ms]
Wed 4/11 23:28:17.393 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.397 [main@191beef] Wizard loading main index for Show bytes=13637012
Wed 4/11 23:28:17.401 [LucenePersonTransactionTask@946c9e] 94.43% / 20120 work queue, 19001 inserted @ 0.01 ms/peep avg [tot:237ms]
Wed 4/11 23:28:17.404 [main@191beef] Lucene index(show): rooted at /rw/\lucene/ running at /rw/\lucene-run/ DiskIndex:false RunningDiskIndex:false
Wed 4/11 23:28:17.409 [main@191beef] Lucene index(show) reader opened in 0
Wed 4/11 23:28:17.413 [LucenePersonTransactionTask@946c9e] 99.40% / 20120 work queue, 20001 inserted @ 0.01 ms/peep avg [tot:243ms]
Wed 4/11 23:28:17.417 [main@191beef] Lucene index(show) docs: 0
Wed 4/11 23:28:17.421 [LucenePersonTransactionTask@946c9e] 100% work queue, 20121 insertions @ 0.01 ms/peep [tot:243ms]
Wed 4/11 23:28:17.425 [main@191beef] Lucene index(show) does not have same item count as wizard (idx:0, wiz:42738) - RESETING
Wed 4/11 23:28:17.429 [main@191beef] Index(show) reset
Wed 4/11 23:28:17.433 [LucenePersonTransactionTask@946c9e] 2.47% / 40463 work queue, 21121 inserted @ 0.01 ms/peep avg [tot:248ms]
Wed 4/11 23:28:17.443 [LucenePersonTransactionTask@946c9e] 4.94% / 40463 work queue, 22121 inserted @ 0.01 ms/peep avg [tot:253ms]
Wed 4/11 23:28:17.454 [LucenePersonTransactionTask@946c9e] 7.41% / 40463 work queue, 23121 inserted @ 0.01 ms/peep avg [tot:258ms]
Wed 4/11 23:28:17.473 [LucenePersonTransactionTask@946c9e] 9.89% / 40463 work queue, 24121 inserted @ 0.01 ms/peep avg [tot:271ms]
Wed 4/11 23:28:17.483 [LucenePersonTransactionTask@946c9e] 12.36% / 40463 work queue, 25121 inserted @ 0.01 ms/peep avg [tot:276ms]
Wed 4/11 23:28:17.537 [LucenePersonTransactionTask@946c9e] 14.83% / 40463 work queue, 26121 inserted @ 0.01 ms/peep avg [tot:323ms]
Wed 4/11 23:28:17.551 [LucenePersonTransactionTask@946c9e] 17.30% / 40463 work queue, 27121 inserted @ 0.01 ms/peep avg [tot:332ms]
Wed 4/11 23:28:17.556 [LuceneShowTransactionTask@55bf70] 67.11% / 1490 work queue, 1068 inserted @ 0.11 ms/show avg [tot:122ms]
Wed 4/11 23:28:17.565 [LucenePersonTransactionTask@946c9e] 19.77% / 40463 work queue, 28121 inserted @ 0.01 ms/peep avg [tot:341ms]
Wed 4/11 23:28:17.576 [LuceneShowTransactionTask@55bf70] 100% work queue, 1558 insertions @ 0.09 ms/show [tot:138ms]
Wed 4/11 23:28:17.583 [LucenePersonTransactionTask@946c9e] 22.24% / 40463 work queue, 29121 inserted @ 0.01 ms/peep avg [tot:349ms]
Wed 4/11 23:28:17.611 [LucenePersonTransactionTask@946c9e] 24.71% / 40463 work queue, 30121 inserted @ 0.01 ms/peep avg [tot:372ms]
Wed 4/11 23:28:17.617 [main@191beef] Load time for Show 220 msec 0.005147644 msec/object
Wed 4/11 23:28:17.623 [main@191beef] Index check time for Show 1 msec
Wed 4/11 23:28:17.629 [main@191beef] Lucene index(show) built from Wizard
Wed 4/11 23:28:17.633 [LuceneShowTransactionTask@55bf70] 2.99% / 33395 work queue, 2558 inserted @ 0.07 ms/show avg [tot:180ms]
Wed 4/11 23:28:17.637 [LucenePersonTransactionTask@946c9e] 27.19% / 40463 work queue, 31121 inserted @ 0.01 ms/peep avg [tot:380ms]
Wed 4/11 23:28:17.642 [main@191beef] Splash: Object Database is initializing... 15% done
Wed 4/11 23:28:17.648 [LucenePersonTransactionTask@946c9e] 29.66% / 40463 work queue, 32121 inserted @ 0.01 ms/peep avg [tot:385ms]
Wed 4/11 23:28:17.655 [main@191beef] Wizard loading alt index 3 for Show bytes=170958
Wed 4/11 23:28:17.664 [LucenePersonTransactionTask@946c9e] 32.13% / 40463 work queue, 33121 inserted @ 0.01 ms/peep avg [tot:394ms]
Wed 4/11 23:28:17.671 [main@191beef] Load time for alt index 3 for Show 18 msec
Wed 4/11 23:28:17.740 [LucenePersonTransactionTask@946c9e] 34.60% / 40463 work queue, 34121 inserted @ 0.01 ms/peep avg [tot:463ms]
Wed 4/11 23:28:17.745 [main@191beef] Index check time for alt index 3 for Show 8 msec
Wed 4/11 23:28:17.748 [main@191beef] Wizard allocating table for Airing of size 108961
Wed 4/11 23:28:17.752 [main@191beef] Splash: Object Database is initializing... 73% done
Wed 4/11 23:28:17.756 [LuceneShowTransactionTask@55bf70] 5.99% / 33395 work queue, 3558 inserted @ 0.08 ms/show avg [tot:298ms]
Wed 4/11 23:28:17.759 [LucenePersonTransactionTask@946c9e] 37.07% / 40463 work queue, 35121 inserted @ 0.01 ms/peep avg [tot:471ms]
Wed 4/11 23:28:17.763 [main@191beef] Wizard loading main index for Airing bytes=4249485
Wed 4/11 23:28:17.769 [LucenePersonTransactionTask@946c9e] 39.54% / 40463 work queue, 36121 inserted @ 0.01 ms/peep avg [tot:477ms]
Wed 4/11 23:28:17.778 [LucenePersonTransactionTask@946c9e] 42.01% / 40463 work queue, 37121 inserted @ 0.01 ms/peep avg [tot:481ms]
Wed 4/11 23:28:17.788 [LucenePersonTransactionTask@946c9e] 44.49% / 40463 work queue, 38121 inserted @ 0.01 ms/peep avg [tot:487ms]
Wed 4/11 23:28:17.792 [main@191beef] Load time for Airing 36 msec 3.3039344E-4 msec/object
Wed 4/11 23:28:17.798 [main@191beef] Index check time for Airing 2 msec
Wed 4/11 23:28:17.801 [LucenePersonTransactionTask@946c9e] 46.96% / 40463 work queue, 39121 inserted @ 0.01 ms/peep avg [tot:493ms]
Wed 4/11 23:28:17.805 [main@191beef] Splash: Object Database is initializing... 73% done
Wed 4/11 23:28:17.809 [LuceneShowTransactionTask@55bf70] 8.98% / 33395 work queue, 4558 inserted @ 0.08 ms/show avg [tot:346ms]
Wed 4/11 23:28:17.813 [LucenePersonTransactionTask@946c9e] 49.43% / 40463 work queue, 40121 inserted @ 0.01 ms/peep avg [tot:498ms]
Wed 4/11 23:28:17.816 [main@191beef] Wizard loading alt index 6 for Airing bytes=435850
Wed 4/11 23:28:17.822 [LucenePersonTransactionTask@946c9e] 51.90% / 40463 work queue, 41121 inserted @ 0.01 ms/peep avg [tot:504ms]
Wed 4/11 23:28:17.827 [main@191beef] Load time for alt index 6 for Airing 18 msec
Wed 4/11 23:28:17.833 [LucenePersonTransactionTask@946c9e] 54.37% / 40463 work queue, 42121 inserted @ 0.01 ms/peep avg [tot:510ms]
Wed 4/11 23:28:17.838 [main@191beef] Index check time for alt index 6 for Airing 7 msec
Wed 4/11 23:28:17.859 [main@191beef] Wizard loading alt index 5 for Airing bytes=435850
Wed 4/11 23:28:17.864 [LucenePersonTransactionTask@946c9e] 56.84% / 40463 work queue, 43121 inserted @ 0.01 ms/peep avg [tot:535ms]
Wed 4/11 23:28:17.868 [main@191beef] Load time for alt index 5 for Airing 9 msec
Wed 4/11 23:28:17.873 [LucenePersonTransactionTask@946c9e] 59.31% / 40463 work queue, 44121 inserted @ 0.01 ms/peep avg [tot:540ms]
Wed 4/11 23:28:17.877 [main@191beef] Index check time for alt index 5 for Airing 4 msec
Wed 4/11 23:28:17.881 [main@191beef] Wizard allocating table for ManualRecord of size 0
Wed 4/11 23:28:17.884 [LucenePersonTransactionTask@946c9e] 61.78% / 40463 work queue, 45121 inserted @ 0.01 ms/peep avg [tot:545ms]
Wed 4/11 23:28:17.888 [main@191beef] Splash: Object Database is initializing... 94% done
Wed 4/11 23:28:17.894 [main@191beef] Wizard allocating table for MediaFile of size 1292
Wed 4/11 23:28:17.898 [LuceneShowTransactionTask@55bf70] 11.98% / 33395 work queue, 5558 inserted @ 0.08 ms/show avg [tot:429ms]
Wed 4/11 23:28:17.901 [LucenePersonTransactionTask@946c9e] 64.26% / 40463 work queue, 46121 inserted @ 0.01 ms/peep avg [tot:550ms]
Wed 4/11 23:28:17.905 [main@191beef] Splash: Object Database is initializing... 94% done
Wed 4/11 23:28:17.908 [main@191beef] Wizard loading main index for MediaFile bytes=564699
Wed 4/11 23:28:17.912 [LucenePersonTransactionTask@946c9e] 66.73% / 40463 work queue, 47121 inserted @ 0.01 ms/peep avg [tot:555ms]
Wed 4/11 23:28:17.921 [LucenePersonTransactionTask@946c9e] 69.20% / 40463 work queue, 48121 inserted @ 0.01 ms/peep avg [tot:560ms]
Wed 4/11 23:28:17.933 [LucenePersonTransactionTask@946c9e] 71.67% / 40463 work queue, 49121 inserted @ 0.01 ms/peep avg [tot:565ms]
Wed 4/11 23:28:17.940 [main@191beef] Load time for MediaFile 32 msec 0.024767801 msec/object
Wed 4/11 23:28:17.943 [LucenePersonTransactionTask@946c9e] 74.14% / 40463 work queue, 50121 inserted @ 0.01 ms/peep avg [tot:571ms]
Wed 4/11 23:28:17.947 [main@191beef] Index check time for MediaFile 1 msec
Wed 4/11 23:28:17.950 [LuceneShowTransactionTask@55bf70] 14.97% / 33395 work queue, 6558 inserted @ 0.07 ms/show avg [tot:477ms]
Wed 4/11 23:28:17.954 [LucenePersonTransactionTask@946c9e] 76.61% / 40463 work queue, 51121 inserted @ 0.01 ms/peep avg [tot:577ms]
Wed 4/11 23:28:17.957 [main@191beef] Splash: Object Database is initializing... 94% done
Wed 4/11 23:28:17.961 [main@191beef] Wizard loading alt index 10 for MediaFile bytes=5174
Wed 4/11 23:28:17.964 [LucenePersonTransactionTask@946c9e] 79.08% / 40463 work queue, 52121 inserted @ 0.01 ms/peep avg [tot:583ms]
Wed 4/11 23:28:17.967 [main@191beef] Load time for alt index 10 for MediaFile 3 msec
Wed 4/11 23:28:17.971 [main@191beef] Index check time for alt index 10 for MediaFile 0 msec
Wed 4/11 23:28:17.974 [LucenePersonTransactionTask@946c9e] 81.56% / 40463 work queue, 53121 inserted @ 0.01 ms/peep avg [tot:589ms]
Wed 4/11 23:28:17.978 [main@191beef] Wizard loading alt index 12 for MediaFile bytes=5174
Wed 4/11 23:28:17.981 [main@191beef] Load time for alt index 12 for MediaFile 7 msec
Wed 4/11 23:28:17.998 [main@191beef] Index check time for alt index 12 for MediaFile 0 msec
Wed 4/11 23:28:18.006 [LucenePersonTransactionTask@946c9e] 84.03% / 40463 work queue, 54121 inserted @ 0.01 ms/peep avg [tot:611ms]
Wed 4/11 23:28:18.009 [main@191beef] Wizard allocating table for Watched of size 2
Wed 4/11 23:28:18.013 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.017 [LucenePersonTransactionTask@946c9e] 86.50% / 40463 work queue, 55121 inserted @ 0.01 ms/peep avg [tot:617ms]
Wed 4/11 23:28:18.021 [LuceneShowTransactionTask@55bf70] 17.97% / 33395 work queue, 7558 inserted @ 0.07 ms/show avg [tot:541ms]
Wed 4/11 23:28:18.024 [main@191beef] Wizard loading main index for Watched bytes=126
Wed 4/11 23:28:18.028 [LucenePersonTransactionTask@946c9e] 88.97% / 40463 work queue, 56121 inserted @ 0.01 ms/peep avg [tot:622ms]
Wed 4/11 23:28:18.032 [main@191beef] Load time for Watched 11 msec 5.5 msec/object
Wed 4/11 23:28:18.036 [main@191beef] Index check time for Watched 1 msec
Wed 4/11 23:28:18.039 [LucenePersonTransactionTask@946c9e] 91.44% / 40463 work queue, 57121 inserted @ 0.01 ms/peep avg [tot:627ms]
Wed 4/11 23:28:18.043 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.046 [main@191beef] Wizard loading alt index 7 for Watched bytes=14
Wed 4/11 23:28:18.050 [LucenePersonTransactionTask@946c9e] 93.91% / 40463 work queue, 58121 inserted @ 0.01 ms/peep avg [tot:633ms]
Wed 4/11 23:28:18.053 [main@191beef] Load time for alt index 7 for Watched 4 msec
Wed 4/11 23:28:18.057 [main@191beef] Index check time for alt index 7 for Watched 0 msec
Wed 4/11 23:28:18.061 [main@191beef] Wizard allocating table for Agent of size 0
Wed 4/11 23:28:18.065 [LucenePersonTransactionTask@946c9e] 96.38% / 40463 work queue, 59121 inserted @ 0.01 ms/peep avg [tot:642ms]
Wed 4/11 23:28:18.068 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.072 [main@191beef] Wizard allocating table for Wasted of size 0
Wed 4/11 23:28:18.075 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.079 [LucenePersonTransactionTask@946c9e] 98.86% / 40463 work queue, 60121 inserted @ 0.01 ms/peep avg [tot:652ms]
Wed 4/11 23:28:18.083 [LuceneShowTransactionTask@55bf70] 20.96% / 33395 work queue, 8558 inserted @ 0.07 ms/show avg [tot:594ms]
Wed 4/11 23:28:18.086 [LucenePersonTransactionTask@946c9e] Snapshot index person snap-count: 0
Wed 4/11 23:28:18.089 [main@191beef] Wizard allocating table for Playlist of size 0
Wed 4/11 23:28:18.093 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.096 [main@191beef] Wizard allocating table for TVEditorial of size 0
Wed 4/11 23:28:18.100 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.103 [main@191beef] Wizard allocating table for SeriesInfo of size 1468
Wed 4/11 23:28:18.107 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.111 [main@191beef] Wizard loading main index for SeriesInfo bytes=801660
Wed 4/11 23:28:18.123 [main@191beef] Load time for SeriesInfo 12 msec 0.008174387 msec/object
Wed 4/11 23:28:18.127 [main@191beef] Index check time for SeriesInfo 0 msec
Wed 4/11 23:28:18.131 [main@191beef] Splash: Object Database is initializing... 97% done
Wed 4/11 23:28:18.136 [main@191beef] Wizard loading alt index 13 for SeriesInfo bytes=5878
Wed 4/11 23:28:18.140 [LuceneShowTransactionTask@55bf70] 23.96% / 33395 work queue, 9558 inserted @ 0.07 ms/show avg [tot:647ms]
Wed 4/11 23:28:18.143 [main@191beef] Load time for alt index 13 for SeriesInfo 4 msec
Wed 4/11 23:28:18.147 [main@191beef] Index check time for alt index 13 for SeriesInfo 0 msec
Wed 4/11 23:28:18.151 [main@191beef] Wizard loading alt index 15 for SeriesInfo bytes=5878
Wed 4/11 23:28:18.155 [main@191beef] Load time for alt index 15 for SeriesInfo 4 msec
Wed 4/11 23:28:18.160 [main@191beef] Index check time for alt index 15 for SeriesInfo 1 msec
Wed 4/11 23:28:18.163 [main@191beef] Wizard allocating table for UserRecord of size 0
Wed 4/11 23:28:18.167 [main@191beef] Splash: Object Database is initializing... 100% done
Wed 4/11 23:28:18.171 [main@191beef] Wizard performing validation on database objects...
Wed 4/11 23:28:18.189 [LuceneShowTransactionTask@55bf70] 26.95% / 33395 work queue, 10558 inserted @ 0.07 ms/show avg [tot:692ms]
Wed 4/11 23:28:18.213 [main@191beef] Sage waiting for GC to free up some memory usage%=0.97704935
Wed 4/11 23:28:18.370 [main@191beef] Sage done waiting for GC to free up some memory usage%=0.4191475
Wed 4/11 23:28:18.377 [main@191beef] Wizard DONE loading database info. loadTime=1.636 sec
Wed 4/11 23:28:18.384 [main@191beef] Splash: Object Database is initializing... 100% done
Wed 4/11 23:28:18.392 [main@191beef] Splash: EPG is initializing...
Wed 4/11 23:28:18.398 [LuceneShowTransactionTask@55bf70] 29.94% / 33395 work queue, 11558 inserted @ 0.08 ms/show avg [tot:892ms]
Wed 4/11 23:28:18.414 [main@191beef] Increased hash set pool to size=1
Wed 4/11 23:28:18.441 [main@191beef] Splash: Profiler is initializing...
Wed 4/11 23:28:18.447 [main@191beef] Loaded 0 messages from system message log file
Wed 4/11 23:28:18.505 [main@191beef] Splash: Acquisition System is initializing...
Wed 4/11 23:28:18.515 [main@191beef] MMC calling detectCaptureDevices on sage.NetworkEncoderManager@17faa95
Wed 4/11 23:28:18.520 [main@191beef] devices detected=[]
Wed 4/11 23:28:18.524 [main@191beef] EncoderMap={}
Wed 4/11 23:28:18.528 [main@191beef] MMC calling detectCaptureDevices on sage.DShowCaptureManager@127982
Wed 4/11 23:28:18.532 [main@191beef] Splash: DirectShow WDM Capture Manager is initializing...
Wed 4/11 23:28:18.539 [main@191beef] Setup globalInvalidParameterHandler
Wed 4/11 23:28:18.539 [main@191beef] Device detecting->:{65E8773D-8F56-11D0-A3B9-00A0C9223196}
Wed 4/11 23:28:18.546 [main@191beef] Device found--'Realtek HD Audio Front Mic input'
Wed 4/11 23:28:18.547 [main@191beef] Device found--'Realtek HD Audio Line input'
Wed 4/11 23:28:18.547 [main@191beef] Device found--'Realtek HD Audio Mic input'
Wed 4/11 23:28:18.547 [main@191beef] Device found--'Realtek HD Audio Stereo input'
Wed 4/11 23:28:18.547 [main@191beef] Device found--'Hauppauge Siena Video Capture'
Wed 4/11 23:28:18.547 [main@191beef] Device found--'MSVAD Wave'
Wed 4/11 23:28:18.547 [main@191beef] MergeNameList() Entry: DevName[0] 'À', numDev=0, new DevName1[0] 'Realtek HD Audio Front Mic input', numDev1=6 
Wed 4/11 23:28:18.547 [main@191beef] Device detecting->:{FD0A5AF4-B41D-11d2-9C95-00C04F7971E0}
Wed 4/11 23:28:18.548 [main@191beef] MergeNameList() Entry: DevName[0] 'Realtek HD Audio Front Mic input', numDev=6, new DevName1[0] 'Realtek HD Audio Front Mic input', numDev1=0 
Wed 4/11 23:28:18.548 [main@191beef] Device detecting->:{71985F48-1CA1-11d3-9CC8-00C04F7971E0}
Wed 4/11 23:28:18.548 [main@191beef] MergeNameList() Entry: DevName[0] 'Realtek HD Audio Front Mic input', numDev=6, new DevName1[0] 'Realtek HD Audio Front Mic input', numDev1=0 
Wed 4/11 23:28:18.548 [main@191beef] Device found 'Realtek HD Audio Front Mic input'
Wed 4/11 23:28:18.549 [main@191beef] Device found 'Realtek HD Audio Line input'
Wed 4/11 23:28:18.549 [main@191beef] Device found 'Realtek HD Audio Mic input'
Wed 4/11 23:28:18.549 [main@191beef] Device found 'Realtek HD Audio Stereo input'
Wed 4/11 23:28:18.549 [main@191beef] Device found 'Hauppauge Siena Video Capture'
Wed 4/11 23:28:18.549 [main@191beef] Device found 'MSVAD Wave'
Wed 4/11 23:28:18.549 [main@191beef] systemCapDevices=[Realtek HD Audio Front Mic input, Realtek HD Audio Line input, Realtek HD Audio Mic input, Realtek HD Audio Stereo input, Hauppauge Siena Video Capture, MSVAD Wave]
Wed 4/11 23:28:18.554 [main@191beef] Checking encoder key:392107985
Wed 4/11 23:28:18.559 [main@191beef] Created DShowCapDev object for:Hauppauge Siena Video Capture
Wed 4/11 23:28:18.564 [main@191beef] EncoderMap1={Hauppauge Siena Video Capture=Hauppauge Siena Video Capture}
Wed 4/11 23:28:18.579 [LucenePersonTransactionTask@946c9e] 100% work queue, 60583 insertions @ 0.01 ms/peep [tot:655ms]
Wed 4/11 23:28:18.583 [main@191beef] Capture device Hauppauge Siena Video Capture (0) exists
Wed 4/11 23:28:18.584 [main@191beef] Get CaptureMask from registry SOFTWARE\Frey Technologies\Common\AdditionalCaptureSetups\Hauppauge Siena Video Capture, 0x800 (hybrid:'')
Wed 4/11 23:28:18.586 [main@191beef] @DEBUG@ device found 'Realtek HD Audio Front Mic input' (index:0) for 'Hauppauge Siena Video Capture'.
Wed 4/11 23:28:18.586 [main@191beef] @DEBUG@ device found 'Realtek HD Audio Line input' (index:0) for 'Hauppauge Siena Video Capture'.
Wed 4/11 23:28:18.586 [main@191beef] @DEBUG@ device found 'Realtek HD Audio Mic input' (index:0) for 'Hauppauge Siena Video Capture'.
Wed 4/11 23:28:18.587 [main@191beef] @DEBUG@ device found 'Realtek HD Audio Stereo input' (index:0) for 'Hauppauge Siena Video Capture'.
Wed 4/11 23:28:18.587 [main@191beef] @DEBUG@ device found 'Hauppauge Siena Video Capture' (index:0) for 'Hauppauge Siena Video Capture'.
Wed 4/11 23:28:18.588 [main@191beef] Device desc:'@oem20.inf,%siena.e504.devicedesc%;Hauppauge HD-PVR2 Gaming Plus (Model 157xxx)'.
Wed 4/11 23:28:18.588 [main@191beef] It's Hauppauge device.
Wed 4/11 23:28:18.589 [main@191beef] skip BDACrossbar check for tuner; detailsCaptureMask=0x800 detailsChipsetMask=0x100000 
Wed 4/11 23:28:18.589 [main@191beef] DeviceCap: 0x100800 hasBDAInput=0 
Wed 4/11 23:28:18.597 [main@191beef] BAD Tuner index :1 dev:\\?\usb#vid_2040&pid_e505#e505-00-00d52689#{65e8773d-8f56-11d0-a3b9-00a0c9223196}\{9b365890-165f-11d0-a195-0020afd156e4} name:@device:pnp:\\?\usb#vid_2040&pid_e505#e505-00-00d52689#{65e8773d-8f56-11d0-a3b9-00a0c9223196}\{9b365890-165f-11d0-a195-0020afd156e4} loc:usb:Port_#0004.Hub_#0002 (1 0) select
Wed 4/11 23:28:18.598 [main@191beef] Check BDA capture device:Hauppauge Siena Video Capture-0 (\\?\usb#vid_2040&pid_e505#e505-00-00d52689#{65e8773d-8f56-11d0-a3b9-00a0c9223196}\{9b365890-165f-11d0-a195-0020afd156e4}) on location:'usb:Port_#0004.Hub_#0002' id:'USB\VID_2040&PID_E505&REV_0800' [state1, index:0] .
Wed 4/11 23:28:18.598 [main@191beef] BDA capture is not found on location:'usb:Port_#0004.Hub_#0002' id:'USB\VID_2040&PID_E505&REV_0800' for Hauppauge Siena Video Capture.
Wed 4/11 23:28:18.598 [main@191beef] Found the pin2 ;)
Wed 4/11 23:28:18.598 [main@191beef] BDA FindVideoPin:0xf1cff4 hasBDAInput:0 on Hauppauge Siena Video Capture
Wed 4/11 23:28:18.599 [main@191beef] not found tuner pin in crossbar for device, try search second cross bar Hauppauge Siena Video Capture
Wed 4/11 23:28:18.599 [main@191beef] pin index i=0 pinType=6 relatedPin=4 foundSPDIFCompInput=0 foundOtherCompInput=0 
Wed 4/11 23:28:18.599 [main@191beef] pin index i=1 pinType=5 relatedPin=6 foundSPDIFCompInput=1 foundOtherCompInput=0 
Wed 4/11 23:28:18.599 [main@191beef] pin index i=2 pinType=2 relatedPin=5 foundSPDIFCompInput=1 foundOtherCompInput=0 
Wed 4/11 23:28:18.599 [main@191beef] pin index i=3 pinType=3 relatedPin=5 foundSPDIFCompInput=1 foundOtherCompInput=0 
Wed 4/11 23:28:18.599 [main@191beef] pin index i=4 pinType=4099 relatedPin=0 foundSPDIFCompInput=1 foundOtherCompInput=0 
Wed 4/11 23:28:18.599 [main@191beef] pin index i=5 pinType=4097 relatedPin=2 foundSPDIFCompInput=1 foundOtherCompInput=0 
Wed 4/11 23:28:18.600 [main@191beef] pin index i=6 pinType=4100 relatedPin=1 foundSPDIFCompInput=1 foundOtherCompInput=0 
Wed 4/11 23:28:18.600 [main@191beef] hasMultiAudioCompInput=0 
Wed 4/11 23:28:18.600 [main@191beef] HDMI AV has Related audio pin: reportedHdmiPinType[0]=6 
Wed 4/11 23:28:18.600 [main@191beef] HDMI AV has other audio pin: reportedHdmiPinType[1]=80 
Wed 4/11 23:28:18.600 [main@191beef] HDMI AV has other audio pin: reportedHdmiPinType[2]=82 
Wed 4/11 23:28:18.600 [main@191beef] pin list: pin 0 pinType=6 
Wed 4/11 23:28:18.600 [main@191beef] pin list: pin 1 pinType=80 
Wed 4/11 23:28:18.600 [main@191beef] pin list: pin 2 pinType=82 
Wed 4/11 23:28:18.600 [main@191beef] pin list: pin 3 pinType=90 
Wed 4/11 23:28:18.600 [main@191beef] pin list: pin 4 pinType=2 
Wed 4/11 23:28:18.600 [main@191beef] pin list: pin 5 pinType=3 
Wed 4/11 23:28:18.600 [main@191beef] Encoder passed the check:Hauppauge Siena Video Capture
Wed 4/11 23:28:18.605 [main@191beef] Saving properties file to C:\Program Files (x86)\SageTV\SageTV\Sage.properties
Wed 4/11 23:28:18.632 [main@191beef] Done writing out the data to the properties file
Wed 4/11 23:28:18.639 [main@191beef] Processing new system dev:Realtek HD Audio Front Mic input
Wed 4/11 23:28:18.643 [main@191beef] Processing new system dev:Realtek HD Audio Line input
Wed 4/11 23:28:18.646 [main@191beef] Processing new system dev:Realtek HD Audio Mic input
Wed 4/11 23:28:18.650 [main@191beef] Processing new system dev:Realtek HD Audio Stereo input
Wed 4/11 23:28:18.653 [main@191beef] Processing new system dev:Hauppauge Siena Video Capture
Wed 4/11 23:28:18.657 [main@191beef] Device already has been processed
Wed 4/11 23:28:18.661 [main@191beef] Processing new system dev:MSVAD Wave
Wed 4/11 23:28:18.664 [main@191beef] devices detected=[Hauppauge Siena Video Capture]
Wed 4/11 23:28:18.668 [main@191beef] EncoderMap={Hauppauge Siena Video Capture=Hauppauge Siena Video Capture}
Wed 4/11 23:28:18.671 [main@191beef] Splash: SageTV Core is initializing...
Wed 4/11 23:28:18.699 [main@191beef] Checking video directories for new files
Wed 4/11 23:28:18.728 [main@191beef] DShowFilters=[AC3 Parser Filter, AC3Filter, ACM Wrapper, ArcSoft AAC Encoder, ArcSoft Audio Decoder HD, ArcSoft MPEG Demux, ArcSoft Realtime Mplex Filter, ArcSoft TS Muxer, ArcSoft Video Decoder, ArcSoft Video Encoder Pro, Audio Generator Filter, Audio Mixer Filter, AVI Decompressor, AVI Draw, AVI Mux, AVI Splitter, AVI/WAV File Source, BDA MPEG2 Transport Information Filter, Closed Captions Analysis Filter, Color Space Converter, DV Muxer, DV Splitter, DV Video Decoder, DVD Navigator, Enhanced Video Renderer, File Source (Async.), File Source (URL), File stream renderer, File writer, GDCL Mpeg-4 Demultiplexor, Hauppauge AAC Encoder, Hauppauge AC3 Decoder, Hauppauge CC Dump, Hauppauge CC Inserter, Hauppauge E-AC3 Decoder, Hauppauge MPEG Layer-1/2 Audio Decoder, Hauppauge Mux Wrapper, Hauppauge Net Push Source, Hauppauge PSI Parser, Hauppauge Raw Sink, Hauppauge Raw Source, Hauppauge Transport Analog Teletext, Hauppauge Transport Filter, Hauppauge Transport Reader, Hauppauge Transport Subtitles, Hauppauge Transport Teletext, Hauppauge Transport Writer, Infinite Pin Tee Filter, Internal Script Command Renderer, Line 21 Decoder, Line 21 Decoder 2, MainConcept (HCW) Layer II Audio Encoder, MainConcept (HCW) MPEG Multiplexer-Plus, MainConcept (HCW) MPEG-2 Video Decoder, MainConcept (HCW) MPEG-2 Video Encoder, Microsoft AC3 Encoder, Microsoft DTV-DVD Audio Decoder, Microsoft DTV-DVD Video Decoder, Microsoft MPEG-2 Audio Encoder, Microsoft MPEG-2 Encoder, Microsoft MPEG-2 Video Encoder, MIDI Parser, MJPEG Decompressor, MP3 Decoder DMO, MPEG Audio Decoder, MPEG Video Decoder, MPEG-2 Demultiplexer, MPEG-2 Sections and Tables, MPEG-2 Splitter, MPEG-2 Video Stream Analyzer, MPEG-I Stream Splitter, MPEG2Dump, Mpeg4 Decoder DMO, Mpeg43 Decoder DMO, Mpeg4s Decoder DMO, Multi-file Parser, Nablet "Live Broadcaster", NPVR AAC Encoder, NPVR Frame Cap, NPVR Video Mixer, Null Renderer, Overlay Mixer, Overlay Mixer2, Pinnacle CSC, Pinnacle Image Converter, Pinnacle Image Scaler, Pinnacle Video AntiJitter, Pinnacle Video Block Filter, Pinnacle Video Deinterlacer, PlayLaterVideoSource Filter, PlayLaterVideoSplitter Filter, SageTV FileSource, SageTV MPEG Layer II Audio Encoder, SageTV MpegDeMux, SageTV MpegMux, SageTV Music Visualization, SageTV Stream Demuxer, SageTV TS Splitter 3.0, SAMI (CC) Parser, SampleGrabber, SBE2FileScan, SBE2MediaTypeProfile, Smart Tee, StreamBufferSink, StreamBufferSink2, StreamBufferSource, VBI Codec, VBI Surface Allocator, VGA 16 Color Ditherer, Video Frame Grab Filter, Video Mixer Filter, Video Mixing Renderer 9, Video Port Manager, Video Renderer, Video Renderer, VPS Decoder, Wave Parser, WM ASF Reader, WM ASF Writer, WMAPro over S/PDIF DMO, WMAudio Decoder DMO, WMSpeech Decoder DMO, WMV Screen decoder DMO, WMVideo Decoder DMO, WST Pager]
Wed 4/11 23:28:18.735 [main@191beef] EVR support detected=true
Wed 4/11 23:28:18.742 [SageTV@15103c] Splash: Profiler is initializing... 0% done
Wed 4/11 23:28:18.746 [LuceneShowTransactionTask@55bf70] 32.94% / 33395 work queue, 12558 inserted @ 0.10 ms/show avg [tot:1232ms]
Wed 4/11 23:28:18.774 [SageTV@15103c] CARNY building airing maps...
Wed 4/11 23:28:18.794 [LuceneShowTransactionTask@55bf70] 35.93% / 33395 work queue, 13558 inserted @ 0.09 ms/show avg [tot:1276ms]
Wed 4/11 23:28:18.884 [LuceneShowTransactionTask@55bf70] 38.93% / 33395 work queue, 14558 inserted @ 0.09 ms/show avg [tot:1359ms]
Wed 4/11 23:28:18.933 [SageTV@15103c] CARNY Processing 0 Agents & 75980 Airs
Wed 4/11 23:28:18.940 [LuceneShowTransactionTask@55bf70] 41.92% / 33395 work queue, 15558 inserted @ 0.09 ms/show avg [tot:1404ms]
Wed 4/11 23:28:18.947 [SageTV@15103c] CARNY has no agents to process.
Wed 4/11 23:28:18.953 [SageTV@15103c] Splash: Profiler is initializing... 100% done
Wed 4/11 23:28:18.958 [Seeker@8a14e] Verifying existence of all TV media files in database fixDurs=true avoidArchive=false
Wed 4/11 23:28:18.965 [MsgMgrSocket@fa1b05] Spawned thread for MsgManger server socket listening...
Wed 4/11 23:28:18.972 [SageTV@15103c] Splash: Waiting for SageTV to finish initialization...
Wed 4/11 23:28:18.979 [Scheduler@72d6a6] initGraph0 (ver 2.1.0) called capDev='Hauppauge Siena Video Capture-0', Country:'United States of America', TuningMode:, TunerType: Cap:0x100800
Wed 4/11 23:28:18.979 [EPG@b56219] Increased ArrayList pool to size=1
Wed 4/11 23:28:18.985 [FSManager@c3234e] FSManager is running...
Wed 4/11 23:28:18.990 [Carny@1c5107c] Carny waiting for awhile...
Wed 4/11 23:28:18.994 [EPG@b56219] sage.epg.sd.SDRipper@14f8404 needs an update in 0:00:00
Wed 4/11 23:28:18.998 [Scheduler@72d6a6] Add analog filters for device=Hauppauge Siena Video Capture
Wed 4/11 23:28:18.999 [EPG@b56219] EPG needs an update in 0 minutes
Wed 4/11 23:28:19.003 [LuceneShowTransactionTask@55bf70] 44.92% / 33395 work queue, 16558 inserted @ 0.09 ms/show avg [tot:1452ms]
Wed 4/11 23:28:19.007 [EPG@b56219] EPG attempting to expand Comcast - Digital - Nashville (sdepg)
Wed 4/11 23:28:19.012 [Scheduler@72d6a6] Found the pin2 ;)
Wed 4/11 23:28:19.012 [EPG@b56219] expand called on Comcast - Digital - Nashville (sdepg) at Wed 4/11 23:28:19.012 expandedUntil=Wed 4/11 23:27:17.296 scannedUntil=Sun 8/17 1:12:55.807
Wed 4/11 23:28:19.017 [Scheduler@72d6a6] Found the pin2 ;)
Wed 4/11 23:28:19.017 [EPG@b56219] EPG Expanding Comcast - Digital - Nashville (sdepg) at Wed 4/11 23:28:19.017
Wed 4/11 23:28:19.022 [MainMsg@5320e3] switchToConnector0 tuningMode:.
Wed 4/11 23:28:19.022 [MainMsg@5320e3] switchToConnector0 7980712 type:90 index:0 country:1 format:1 Mode:
Wed 4/11 23:28:19.022 [MainMsg@5320e3] Crossbar route: videoIn pin:1, auido:6 videoOutNum=0 audioOutNum=1 
Wed 4/11 23:28:19.022 [MainMsg@5320e3] DONE: switchToConnector0 7980712 type=90 index=0
Wed 4/11 23:28:19.023 [MainMsg@5320e3] Set capture brightness: (0 10000)-36 val:1411 hr:0x0 Hauppauge Siena Video Capture-0
Wed 4/11 23:28:19.031 [Scheduler@72d6a6] Scheduler.updateSchedule() called  manual=[] schedules={Hauppauge Siena Video Capture=[Sched=[] MustSee=[]]} scheduleRandSize=0
Wed 4/11 23:28:19.038 [Scheduler@72d6a6] # Airs=0
Wed 4/11 23:28:19.042 [Scheduler@72d6a6] MUST SEE FINAL-Hauppauge Siena Video Capture-[]
Wed 4/11 23:28:19.047 [Scheduler@72d6a6] Evaluating Potentials
Wed 4/11 23:28:19.051 [Scheduler@72d6a6] COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE
Wed 4/11 23:28:19.056 [LuceneShowTransactionTask@55bf70] 47.91% / 33395 work queue, 17558 inserted @ 0.09 ms/show avg [tot:1499ms]
Wed 4/11 23:28:19.060 [Scheduler@72d6a6] Hauppauge Siena Video Capture
Wed 4/11 23:28:19.060 [Scheduler@72d6a6] []
Wed 4/11 23:28:19.064 [Scheduler@72d6a6] Total Schedule eval time=33 msec
Wed 4/11 23:28:19.069 [Scheduler@72d6a6] Scheduler awoken
Wed 4/11 23:28:19.074 [Scheduler@72d6a6] Scheduler.updateSchedule() called  manual=[] schedules={Hauppauge Siena Video Capture=[Sched=[] MustSee=[]]} scheduleRandSize=0
Wed 4/11 23:28:19.079 [Scheduler@72d6a6] # Airs=0
Wed 4/11 23:28:19.084 [Scheduler@72d6a6] MUST SEE FINAL-Hauppauge Siena Video Capture-[]
Wed 4/11 23:28:19.088 [Scheduler@72d6a6] Evaluating Potentials
Wed 4/11 23:28:19.093 [Scheduler@72d6a6] COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE
Wed 4/11 23:28:19.097 [Scheduler@72d6a6] Hauppauge Siena Video Capture
Wed 4/11 23:28:19.097 [Scheduler@72d6a6] []
Wed 4/11 23:28:19.102 [Scheduler@72d6a6] Total Schedule eval time=28 msec
Wed 4/11 23:28:19.127 [Scheduler@72d6a6] Scheduler starting wait...
Wed 4/11 23:28:19.135 [LuceneShowTransactionTask@55bf70] 50.91% / 33395 work queue, 18558 inserted @ 0.08 ms/show avg [tot:1574ms]
Wed 4/11 23:28:19.188 [LuceneShowTransactionTask@55bf70] 53.90% / 33395 work queue, 19558 inserted @ 0.08 ms/show avg [tot:1622ms]
Wed 4/11 23:28:19.200 [AsyncPropSaver@3cc85e] Saving properties file to C:\Program Files (x86)\SageTV\SageTV\Sage.properties
Wed 4/11 23:28:19.205 [LibraryImporter@19df500] Checking video directories for new files
Wed 4/11 23:28:19.216 [Seeker@8a14e] Checking video directories for new files
Wed 4/11 23:28:19.222 [AsyncPropSaver@3cc85e] Done writing out the data to the properties file
Wed 4/11 23:28:19.229 [Seeker@8a14e] Diskspace checking is running
Wed 4/11 23:28:19.234 [Seeker@8a14e] Verifying existence of all TV media files in database fixDurs=false avoidArchive=true
Wed 4/11 23:28:19.238 [Seeker@8a14e] Enforcing keep at most limits for the files...
Wed 4/11 23:28:19.242 [LuceneShowTransactionTask@55bf70] 56.89% / 33395 work queue, 20558 inserted @ 0.08 ms/show avg [tot:1671ms]
Wed 4/11 23:28:19.247 [Seeker@8a14e] DONE enforcing keep at most limits for the files.
Wed 4/11 23:28:19.252 [Seeker@8a14e] Seeker clearing unwanted and partial files...
Wed 4/11 23:28:19.256 [Seeker@8a14e] DONE clearing unwanted and partial files.
Wed 4/11 23:28:19.261 [Seeker@8a14e] Seeker waiting for 153722841889124 mins.
Wed 4/11 23:28:19.279 [Seeker@8a14e] Seeker awoken
Wed 4/11 23:28:19.283 [Seeker@8a14e] MemStats: Used=138MB Total=201MB Max=778MB
Wed 4/11 23:28:19.288 [Seeker@8a14e] Seeker adding new Encoder: Hauppauge Siena Video Capture
Wed 4/11 23:28:19.293 [Seeker@8a14e] MARK 1 currRecord=null enc=Hauppauge Siena Video Capture clients=[] ir=false
Wed 4/11 23:28:19.297 [Seeker@8a14e] Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807
Wed 4/11 23:28:19.301 [LuceneShowTransactionTask@55bf70] 59.89% / 33395 work queue, 21558 inserted @ 0.08 ms/show avg [tot:1725ms]
Wed 4/11 23:28:19.305 [Seeker@8a14e] newRecord=null
Wed 4/11 23:28:19.309 [Seeker@8a14e] NOTHING TO RECORD FOR NOW...
Wed 4/11 23:28:19.313 [Seeker@8a14e] Seeker waiting for -25391788 mins.
Wed 4/11 23:28:19.326 [Seeker@8a14e] Seeker awoken
Wed 4/11 23:28:19.330 [Seeker@8a14e] MemStats: Used=142MB Total=201MB Max=778MB
Wed 4/11 23:28:19.334 [Seeker@8a14e] MARK 1 currRecord=null enc=Hauppauge Siena Video Capture clients=[] ir=false
Wed 4/11 23:28:19.338 [Seeker@8a14e] Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807
Wed 4/11 23:28:19.342 [Seeker@8a14e] newRecord=null
Wed 4/11 23:28:19.345 [Seeker@8a14e] NOTHING TO RECORD FOR NOW...
Wed 4/11 23:28:19.349 [Seeker@8a14e] Checking video directories for new files
Wed 4/11 23:28:19.353 [Seeker@8a14e] Diskspace checking is running
Wed 4/11 23:28:19.357 [LuceneShowTransactionTask@55bf70] 62.88% / 33395 work queue, 22558 inserted @ 0.08 ms/show avg [tot:1774ms]
Wed 4/11 23:28:19.362 [Seeker@8a14e] Verifying existence of all TV media files in database fixDurs=false avoidArchive=true
Wed 4/11 23:28:19.366 [Seeker@8a14e] Enforcing keep at most limits for the files...
Wed 4/11 23:28:19.370 [Seeker@8a14e] DONE enforcing keep at most limits for the files.
Wed 4/11 23:28:19.374 [Seeker@8a14e] Seeker clearing unwanted and partial files...
Wed 4/11 23:28:19.378 [Seeker@8a14e] DONE clearing unwanted and partial files.
Wed 4/11 23:28:19.382 [Seeker@8a14e] Seeker waiting for 153722841889124 mins.
Wed 4/11 23:28:19.412 [LuceneShowTransactionTask@55bf70] 65.88% / 33395 work queue, 23558 inserted @ 0.08 ms/show avg [tot:1825ms]
Wed 4/11 23:28:19.461 [LuceneShowTransactionTask@55bf70] 68.87% / 33395 work queue, 24558 inserted @ 0.08 ms/show avg [tot:1870ms]
Wed 4/11 23:28:19.467 [SageTVServer@5587d9] SageTVServer was instantiated loadDelay=2.92 sec
Wed 4/11 23:28:19.472 [SageTVDiscoveryServer@131dbfb] SageTVDiscoveryServer was instantiated.
Wed 4/11 23:28:19.478 [SageTVMiniDiscoveryServer@1d5ca18] SageTVMiniDiscoveryServer was instantiated.
Wed 4/11 23:28:19.484 [SageTV@15103c] Trying to find lan network interface
Wed 4/11 23:28:19.641 [SageTV@15103c] addr: /127.0.0.1
Wed 4/11 23:28:19.648 [SageTV@15103c] addr: /0:0:0:0:0:0:0:1
Wed 4/11 23:28:19.655 [SageTV@15103c] addr: /2001:0:4137:9e76:4c5:9b6:b834:2982
Wed 4/11 23:28:19.661 [SageTV@15103c] addr: /fe80:0:0:0:4c5:9b6:b834:2982%net0
Wed 4/11 23:28:19.667 [SageTV@15103c] addr: /fe80:0:0:0:8929:811e:2cc3:64f1%eth0
Wed 4/11 23:28:19.673 [SageTV@15103c] addr: /fe80:0:0:0:212c:d244:1605:c0e6%eth1
Wed 4/11 23:28:19.677 [SageTV@15103c] addr: /192.168.1.100
Wed 4/11 23:28:19.681 [SageTV@15103c] Miniserver running on 192.168.1.100
Wed 4/11 23:28:19.685 [SageTV@15103c] Parsed 0 clients
Wed 4/11 23:28:19.690 [MiniBootp@18a171f] 0.0.0.0/0.0.0.0 16867
Wed 4/11 23:28:19.694 [SageTV@15103c] Loading locator keys from filesystem since they already exist.
Wed 4/11 23:28:19.698 [MiniMVP@a5b9a2] 0.0.0.0/0.0.0.0 16881
Wed 4/11 23:28:19.703 [MiniTftp@571753] 0.0.0.0/0.0.0.0 16869
Wed 4/11 23:28:19.707 [PSNATMGR@6ac6b3] Starting UPnP NAT Manager...
Wed 4/11 23:28:19.710 [SageTV@15103c] Splash: User Interface Manager is initializing...
Wed 4/11 23:28:19.715 [SageTV@15103c] Loading all core plugins...
Wed 4/11 23:28:19.806 [LibraryImporter@19df500] Seeker is starting the library import scan...
Wed 4/11 23:28:19.813 [HotplugStorage@124cfe4] StorageDeviceDetector started...
Wed 4/11 23:28:19.820 [SageTV@15103c] LOADED PLUGINS=[]
Wed 4/11 23:28:19.827 [EPG@b56219] SDEPG Successfully got token: 23e5327cd048e3478e91030f16a917d1
Wed 4/11 23:28:19.834 [SageTV@15103c] Starting all core plugins...
Wed 4/11 23:28:19.841 [SageTV@15103c] Done starting core plugins.
Wed 4/11 23:28:19.846 [PluginRepoUpdater@53619e] Checking to see if the plugin repository file SageTVPlugins.xml needs to be updated using MD5 URL: http://download.sagetv.com/SageTVPlugins.md5.txt
Wed 4/11 23:28:19.850 [PSNATMGR@612dc1] Starting UPnP NAT Manager...
Wed 4/11 23:28:19.870 [LibraryImporter@19df500] Seeker has finished the library import scan.
Wed 4/11 23:28:19.882 [LuceneShowTransactionTask@55bf70] 71.87% / 33395 work queue, 25558 inserted @ 0.09 ms/show avg [tot:2285ms]
Wed 4/11 23:28:19.925 [LuceneShowTransactionTask@55bf70] 74.86% / 33395 work queue, 26558 inserted @ 0.09 ms/show avg [tot:2324ms]
Wed 4/11 23:28:19.950 [PluginRepoUpdater@53619e] Local plugin repository file's checksum matches server's, no need to download a new one for SageTVPlugins.xml
Wed 4/11 23:28:19.958 [PluginRepoUpdater@53619e] Checking to see if the plugin repository file SageTVPluginsV9.xml needs to be updated using MD5 URL: https://raw.githubusercontent.com/OpenSageTV/sagetv-plugin-repo/master/SageTVPluginsV9.md5
Wed 4/11 23:28:19.977 [LuceneShowTransactionTask@55bf70] 77.86% / 33395 work queue, 27558 inserted @ 0.09 ms/show avg [tot:2371ms]
Wed 4/11 23:28:20.022 [LuceneShowTransactionTask@55bf70] 80.85% / 33395 work queue, 28558 inserted @ 0.08 ms/show avg [tot:2412ms]
Wed 4/11 23:28:20.072 [LuceneShowTransactionTask@55bf70] 83.84% / 33395 work queue, 29558 inserted @ 0.08 ms/show avg [tot:2457ms]
Wed 4/11 23:28:20.125 [LuceneShowTransactionTask@55bf70] 86.84% / 33395 work queue, 30558 inserted @ 0.08 ms/show avg [tot:2503ms]
Wed 4/11 23:28:20.155 [PluginRepoUpdater@53619e] Local plugin repository file's checksum matches server's, no need to download a new one for SageTVPluginsV9.xml
Wed 4/11 23:28:20.161 [PluginRepoUpdater@53619e] Analyzing plugin repository XML file: SageTVPlugins.xml
Wed 4/11 23:28:20.179 [LuceneShowTransactionTask@55bf70] 89.83% / 33395 work queue, 31558 inserted @ 0.08 ms/show avg [tot:2549ms]
Wed 4/11 23:28:20.246 [PluginRepoUpdater@53619e] Done processing plugin repository XML file[SageTVPlugins.xml]  repositoryVersion=1.0.2000
Wed 4/11 23:28:20.254 [LuceneShowTransactionTask@55bf70] 92.83% / 33395 work queue, 32558 inserted @ 0.08 ms/show avg [tot:2617ms]
Wed 4/11 23:28:20.260 [PluginRepoUpdater@53619e] Analyzing plugin repository XML file: SageTVPluginsV9.xml
Wed 4/11 23:28:20.270 [PluginRepoUpdater@53619e] Done processing plugin repository XML file[SageTVPluginsV9.xml]  repositoryVersion=2018.0308.2318
Wed 4/11 23:28:20.320 [LuceneShowTransactionTask@55bf70] 95.82% / 33395 work queue, 33558 inserted @ 0.08 ms/show avg [tot:2676ms]
Wed 4/11 23:28:20.329 [EPG@b56219] SDEPG got 505 channels
Wed 4/11 23:28:20.372 [LuceneShowTransactionTask@55bf70] 98.82% / 33395 work queue, 34558 inserted @ 0.08 ms/show avg [tot:2724ms]
Wed 4/11 23:28:20.405 [LuceneShowTransactionTask@55bf70] 100% work queue, 34953 insertions @ 0.08 ms/show [tot:2750ms]
Wed 4/11 23:28:20.460 [LuceneShowTransactionTask@55bf70] 12.84% / 7786 work queue, 35953 inserted @ 0.08 ms/show avg [tot:2797ms]
Wed 4/11 23:28:20.509 [LuceneShowTransactionTask@55bf70] 25.69% / 7786 work queue, 36953 inserted @ 0.08 ms/show avg [tot:2839ms]
Wed 4/11 23:28:20.639 [Scheduler@72d6a6] Scheduler awoken
Wed 4/11 23:28:20.646 [Scheduler@72d6a6] Scheduler.updateSchedule() called  manual=[] schedules={Hauppauge Siena Video Capture=[Sched=[] MustSee=[]]} scheduleRandSize=0
Wed 4/11 23:28:20.653 [Scheduler@72d6a6] # Airs=0
Wed 4/11 23:28:20.658 [Scheduler@72d6a6] MUST SEE FINAL-Hauppauge Siena Video Capture-[]
Wed 4/11 23:28:20.662 [Scheduler@72d6a6] Evaluating Potentials
Wed 4/11 23:28:20.666 [Scheduler@72d6a6] COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE
Wed 4/11 23:28:20.670 [Scheduler@72d6a6] Hauppauge Siena Video Capture
Wed 4/11 23:28:20.670 [Scheduler@72d6a6] []
Wed 4/11 23:28:20.674 [Scheduler@72d6a6] Total Schedule eval time=28 msec
Wed 4/11 23:28:20.678 [Seeker@8a14e] Seeker awoken
Wed 4/11 23:28:20.682 [Scheduler@72d6a6] Scheduler starting wait...
Wed 4/11 23:28:20.686 [Seeker@8a14e] MemStats: Used=154MB Total=216MB Max=778MB
Wed 4/11 23:28:20.690 [Seeker@8a14e] MARK 1 currRecord=null enc=Hauppauge Siena Video Capture clients=[] ir=false
Wed 4/11 23:28:20.694 [Seeker@8a14e] Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807
Wed 4/11 23:28:20.698 [Seeker@8a14e] newRecord=null
Wed 4/11 23:28:20.702 [Seeker@8a14e] NOTHING TO RECORD FOR NOW...
Wed 4/11 23:28:20.706 [Seeker@8a14e] Checking video directories for new files
Wed 4/11 23:28:20.711 [Seeker@8a14e] Diskspace checking is running
Wed 4/11 23:28:20.714 [Seeker@8a14e] Verifying existence of all TV media files in database fixDurs=false avoidArchive=true
Wed 4/11 23:28:20.719 [Seeker@8a14e] Enforcing keep at most limits for the files...
Wed 4/11 23:28:20.722 [Seeker@8a14e] DONE enforcing keep at most limits for the files.
Wed 4/11 23:28:20.726 [Seeker@8a14e] Seeker clearing unwanted and partial files...
Wed 4/11 23:28:20.730 [Seeker@8a14e] DONE clearing unwanted and partial files.
Wed 4/11 23:28:20.734 [Seeker@8a14e] Seeker waiting for 153722841889124 mins.
Wed 4/11 23:28:20.766 [LuceneShowTransactionTask@55bf70] 38.53% / 7786 work queue, 37953 inserted @ 0.08 ms/show avg [tot:3091ms]
Wed 4/11 23:28:20.862 [LuceneShowTransactionTask@55bf70] 51.37% / 7786 work queue, 38953 inserted @ 0.08 ms/show avg [tot:3183ms]
Wed 4/11 23:28:20.905 [LuceneShowTransactionTask@55bf70] 64.22% / 7786 work queue, 39953 inserted @ 0.08 ms/show avg [tot:3217ms]
Wed 4/11 23:28:20.954 [LuceneShowTransactionTask@55bf70] 77.06% / 7786 work queue, 40953 inserted @ 0.08 ms/show avg [tot:3259ms]
Wed 4/11 23:28:21.002 [LuceneShowTransactionTask@55bf70] 89.90% / 7786 work queue, 41953 inserted @ 0.08 ms/show avg [tot:3301ms]
Wed 4/11 23:28:21.040 [LuceneShowTransactionTask@55bf70] Snapshot index show snap-count: 0
Wed 4/11 23:28:21.142 [LuceneShowTransactionTask@55bf70] 100% work queue, 42738 insertions @ 0.08 ms/show [tot:3334ms]
Wed 4/11 23:28:23.483 [SageTVServer@5587d9] SageTV received connection from:Socket[addr=/127.0.0.1,port=57558,localport=42024]
Wed 4/11 23:28:23.535 [SageTVServer@5587d9] Suspending DB writes while we send the DB to the client...
Wed 4/11 23:28:23.539 [SageTVServer@5587d9] Sending DB to client of size:23947425
Wed 4/11 23:28:23.849 [EPG@b56219] SDEPG Importing 509 programs for 2018-04-12...
Wed 4/11 23:28:23.951 [Ministry@1ea30a2] Ministry is starting
Wed 4/11 23:28:23.961 [Ministry@1ea30a2] Ministry is waiting for 180 sec
Wed 4/11 23:28:24.353 [SageTVServer@5587d9] Logging 0 DB xcts to file and sending them to the new client...
Wed 4/11 23:28:24.359 [SageTVServer@5587d9] DONE sending DB to the client and client is now added as a DB sync listener
Wed 4/11 23:28:24.557 [ClientListenerParallelizer@3cc85e] Listener parallelizer thread has spawned for /127.0.0.1:57558
Wed 4/11 23:28:24.579 [SageTVServer@5587d9] SageTV received connection from:Socket[addr=/127.0.0.1,port=57560,localport=42024]
Wed 4/11 23:28:24.585 [SageTVServer@5587d9] Increased Thread pool to size=6
Wed 4/11 23:28:24.589 [ConnSendQueue@138b881] MsgSend thread spawned for /127.0.0.1:57558
Wed 4/11 23:28:24.594 [ConnRecvQueue@34ce21] MsgRecv thread has spawned for /127.0.0.1:57558
Wed 4/11 23:28:24.842 [Scheduler@72d6a6] Scheduler awoken
Wed 4/11 23:28:24.848 [Scheduler@72d6a6] Scheduler.updateSchedule() called  manual=[] schedules={Hauppauge Siena Video Capture=[Sched=[] MustSee=[]]} scheduleRandSize=0
Wed 4/11 23:28:24.855 [Scheduler@72d6a6] # Airs=0
Wed 4/11 23:28:24.861 [Scheduler@72d6a6] MUST SEE FINAL-Hauppauge Siena Video Capture-[]
Wed 4/11 23:28:24.872 [Scheduler@72d6a6] Evaluating Potentials
Wed 4/11 23:28:24.876 [Scheduler@72d6a6] COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE
Wed 4/11 23:28:24.880 [Scheduler@72d6a6] Hauppauge Siena Video Capture
Wed 4/11 23:28:24.880 [Scheduler@72d6a6] []
Wed 4/11 23:28:24.884 [Scheduler@72d6a6] Total Schedule eval time=36 msec
Wed 4/11 23:28:24.888 [Scheduler@72d6a6] Scheduler starting wait...
Wed 4/11 23:28:24.892 [Seeker@8a14e] Seeker awoken
Wed 4/11 23:28:24.896 [Seeker@8a14e] MemStats: Used=159MB Total=216MB Max=778MB
Wed 4/11 23:28:24.900 [Seeker@8a14e] MARK 1 currRecord=null enc=Hauppauge Siena Video Capture clients=[] ir=false
Wed 4/11 23:28:24.904 [Seeker@8a14e] Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807
Wed 4/11 23:28:24.908 [Seeker@8a14e] newRecord=null
Wed 4/11 23:28:24.912 [Seeker@8a14e] NOTHING TO RECORD FOR NOW...
Wed 4/11 23:28:24.917 [Seeker@8a14e] Checking video directories for new files
Wed 4/11 23:28:24.921 [Seeker@8a14e] Diskspace checking is running
Wed 4/11 23:28:24.925 [Seeker@8a14e] Verifying existence of all TV media files in database fixDurs=false avoidArchive=true
Wed 4/11 23:28:24.929 [Seeker@8a14e] Enforcing keep at most limits for the files...
Wed 4/11 23:28:24.933 [Seeker@8a14e] DONE enforcing keep at most limits for the files.
Wed 4/11 23:28:24.937 [Seeker@8a14e] Seeker clearing unwanted and partial files...
Wed 4/11 23:28:24.942 [Seeker@8a14e] DONE clearing unwanted and partial files.
Wed 4/11 23:28:24.946 [Seeker@8a14e] Seeker waiting for 153722841889124 mins.
Wed 4/11 23:28:25.594 [ConnRecvQueue@34ce21] Recieving 14 capabilties for client /127.0.0.1:57558
Wed 4/11 23:28:25.600 [ConnRecvQueue@34ce21]   SystemStatusChanged = true
Wed 4/11 23:28:25.607 [ConnRecvQueue@34ce21]   RequestToExceedParentalRestrictions = true
Wed 4/11 23:28:25.612 [ConnRecvQueue@34ce21]   MediaPlayerFileLoadComplete = true
Wed 4/11 23:28:25.616 [ConnRecvQueue@34ce21]   RecordRequestLiveConflict = true
Wed 4/11 23:28:25.619 [ConnRecvQueue@34ce21]   MediaFilesImported = true
Wed 4/11 23:28:25.623 [ConnRecvQueue@34ce21]   ApplicationStarted = true
Wed 4/11 23:28:25.626 [ConnRecvQueue@34ce21]   MediaPlayerError = true
Wed 4/11 23:28:25.630 [ConnRecvQueue@34ce21]   DenyChannelChangeToRecord = true
Wed 4/11 23:28:25.634 [ConnRecvQueue@34ce21]   StorageDeviceAdded = true
Wed 4/11 23:28:25.637 [ConnRecvQueue@34ce21]   NewUnresolvedSchedulingConflicts = true
Wed 4/11 23:28:25.641 [ConnRecvQueue@34ce21]   RecordingScheduleChanged = true
Wed 4/11 23:28:25.645 [ConnRecvQueue@34ce21]   ApplicationExiting = true
Wed 4/11 23:28:25.652 [ConnRecvQueue@34ce21]   RecordRequestScheduleConflict = true
Wed 4/11 23:28:25.659 [ConnRecvQueue@34ce21]   WatchRequestConflict = true
Wed 4/11 23:28:35.679 [EPG@b56219] SDEPG Importing 507 programs for 2018-04-12...
Wed 4/11 23:28:46.460 [EPG@b56219] SDEPG Importing 504 programs for 2018-04-12...
Wed 4/11 23:28:52.577 [EPG@b56219] SDEPG Importing 514 programs for 2018-04-12...
Wed 4/11 23:28:58.874 [EPG@b56219] SDEPG Importing 101 programs for 2018-04-12...
Wed 4/11 23:29:00.455 [EPG@b56219] SDEPG Importing up to 4903 airings across 178 stations for 2018-04-12...
Wed 4/11 23:29:01.192 [EPG@b56219] SDEPG Importing 505 programs for 2018-04-13...
Wed 4/11 23:29:11.054 [EPG@b56219] SDEPG Importing 508 programs for 2018-04-13...
Wed 4/11 23:29:16.392 [EPG@b56219] SDEPG Importing 512 programs for 2018-04-13...
Wed 4/11 23:29:16.614 [PooledThread@13aa742] Seeker.finishWatch(/127.0.0.1:57558@@SAGETV_PROCESS_LOCAL_UI)
Wed 4/11 23:29:16.657 [PooledThread@13aa742] Seeker.finishWatch(/127.0.0.1:57558@@SAGETV_PROCESS_LOCAL_UI)
Wed 4/11 23:29:16.666 [PooledThread@13aa742] Seeker.finishWatch(/127.0.0.1:57558@@SAGETV_PROCESS_LOCAL_UI)
Wed 4/11 23:29:18.974 [ConnRecvQueue@34ce21] Error communicating with server:java.io.EOFException
Wed 4/11 23:29:18.981 [ConnRecvQueue@34ce21] Cleaning up c/s connection
Wed 4/11 23:29:18.988 [ConnRecvQueue@34ce21] NetworkManager CommunicationFailure : /127.0.0.1:57558 type=1
Wed 4/11 23:29:18.994 [ConnRecvQueue@34ce21] NetworkClient fullCleanup /127.0.0.1:57558
Wed 4/11 23:29:19.000 [ConnRecvQueue@34ce21] Cleaning up c/s connection
Wed 4/11 23:29:19.006 [ConnRecvQueue@34ce21] Cleaning up c/s connection
Wed 4/11 23:29:19.010 [ConnRecvQueue@34ce21] MsgRecv thread is terminating for /127.0.0.1:57558
Wed 4/11 23:29:19.014 [Seeker@8a14e] Seeker awoken
Wed 4/11 23:29:19.018 [Seeker@8a14e] MemStats: Used=147MB Total=216MB Max=778MB
Wed 4/11 23:29:19.023 [Seeker@8a14e] MARK 1 currRecord=null enc=Hauppauge Siena Video Capture clients=[] ir=false
Wed 4/11 23:29:19.027 [Seeker@8a14e] Seeker in AUTOMATIC mode nextRecord=null nextTTA=9223372036854775807
Wed 4/11 23:29:19.031 [Seeker@8a14e] newRecord=null
Wed 4/11 23:29:19.035 [Seeker@8a14e] NOTHING TO RECORD FOR NOW...
Wed 4/11 23:29:19.039 [Seeker@8a14e] Checking video directories for new files
Wed 4/11 23:29:19.043 [Seeker@8a14e] Diskspace checking is running
Wed 4/11 23:29:19.048 [Seeker@8a14e] Verifying existence of all TV media files in database fixDurs=false avoidArchive=true
Wed 4/11 23:29:19.052 [Seeker@8a14e] Enforcing keep at most limits for the files...
Wed 4/11 23:29:19.055 [Seeker@8a14e] DONE enforcing keep at most limits for the files.
Wed 4/11 23:29:19.060 [Seeker@8a14e] Seeker clearing unwanted and partial files...
Wed 4/11 23:29:19.064 [Seeker@8a14e] DONE clearing unwanted and partial files.
Wed 4/11 23:29:19.067 [Seeker@8a14e] Seeker waiting for 153722841889123 mins.
Wed 4/11 23:29:19.784 [KeepAlive@19df500] Error with c/s comm: keepAlive:java.lang.NullPointerException
Wed 4/11 23:29:19.792 [KeepAlive@19df500] java.lang.NullPointerException
Wed 4/11 23:29:19.792 [KeepAlive@19df500] 	at sage.SageTVConnection.keepAlive(SageTVConnection.java:2525)
Wed 4/11 23:29:19.792 [KeepAlive@19df500] 	at sage.SageTVConnection.access$100(SageTVConnection.java:21)
Wed 4/11 23:29:19.792 [KeepAlive@19df500] 	at sage.SageTVConnection$3.run(SageTVConnection.java:3021)
Wed 4/11 23:29:19.792 [KeepAlive@19df500] 	at sage.Pooler$PooledThread.run(Pooler.java:254)
Wed 4/11 23:29:19.793 [KeepAlive@19df500] NetworkManager CommunicationFailure : /127.0.0.1:57558 type=2
Wed 4/11 23:29:19.800 [KeepAlive@19df500] NetworkManager CommunicationFailure : /127.0.0.1:57558 type=2
Wed 4/11 23:29:22.141 [main@191beef] Sage.exit() called.
Wed 4/11 23:29:22.146 [main@191beef] Stopping all core plugins
Wed 4/11 23:29:22.150 [main@191beef] Destroying all core plugins
Wed 4/11 23:29:22.154 [main@191beef] Cleaning up servers
Wed 4/11 23:29:22.158 [SageTVMiniDiscoveryServer@1d5ca18] Error w/SageTV client connection:java.net.SocketException: socket closed
Wed 4/11 23:29:22.162 [MiniMVP@a5b9a2] MiniError-1:java.net.SocketException: socket closed
Wed 4/11 23:29:22.166 [MiniBootp@18a171f] MiniError-3:java.net.SocketException: socket closed
Wed 4/11 23:29:22.170 [MiniTftp@571753] MiniError-2:java.net.SocketException: socket closed
Wed 4/11 23:29:22.812 [EPG@b56219] SDEPG Importing 282 programs for 2018-04-13...
Wed 4/11 23:29:24.582 [ClientListenerParallelizer@3cc85e] Listener parallelizer  thread is terminating for /127.0.0.1:57558
Wed 4/11 23:29:27.014 [EPG@b56219] SDEPG Importing up to 4897 airings across 178 stations for 2018-04-13...
Wed 4/11 23:29:27.159 [main@191beef] Cleaning up PM
Wed 4/11 23:29:27.167 [main@191beef] Killed Carny.
Wed 4/11 23:29:27.173 [main@191beef] Killed Scheduler.
Wed 4/11 23:29:27.178 [main@191beef] Error calling finishWatch from VF goodbye:java.lang.NullPointerException
Wed 4/11 23:29:27.182 [Ministry@1ea30a2] Ministry is shutting down....destroying the converts in progress
Wed 4/11 23:29:27.186 [main@191beef] FSManager goodbye()
Wed 4/11 23:29:27.190 [main@191beef] Killed Seeker.
Wed 4/11 23:29:27.194 [main@191beef] Killed EPG.
Wed 4/11 23:29:27.198 [main@191beef] freeDevice called for Hauppauge Siena Video Capture
Wed 4/11 23:29:27.203 [main@191beef] teardownGraph0 called for device='Hauppauge Siena Video Capture'
Wed 4/11 23:29:27.203 [main@191beef] teardownGraph0 step-1 
Wed 4/11 23:29:27.203 [main@191beef] teardownGraph0 step0 
Wed 4/11 23:29:27.203 [main@191beef] teardownGraph0 step1 
Wed 4/11 23:29:27.203 [main@191beef] teardownGraph0 step2 
Wed 4/11 23:29:27.203 [main@191beef] teardownGraph0 step3 
Wed 4/11 23:29:27.204 [main@191beef] teardownGraph0 step4 
Wed 4/11 23:29:27.204 [main@191beef] teardownGraph0 step4-1 0x0 
Wed 4/11 23:29:27.204 [main@191beef] teardownGraph0 step5 
Wed 4/11 23:29:27.204 [main@191beef] teardownGraph0 step6. 
Wed 4/11 23:29:27.204 [main@191beef] teardownGraph0 pBuilder. 
Wed 4/11 23:29:27.204 [main@191beef] teardownGraph0 pGraph. 
Wed 4/11 23:29:27.205 [main@191beef] teardownGraph0 step8 
Wed 4/11 23:29:27.205 [main@191beef] teardownGraph0 step9 
Wed 4/11 23:29:27.205 [main@191beef] teardownGraph0 step10 
Wed 4/11 23:29:27.205 [main@191beef] Killed MMC.
Wed 4/11 23:29:27.209 [main@191beef] Killing UIMgr UIManager:localhost@@SAGETV_PROCESS_LOCAL_UI-175e2db
Wed 4/11 23:29:27.213 [main@191beef] Error calling finishWatch from VF goodbye:java.lang.NullPointerException
Wed 4/11 23:29:27.217 [main@191beef] Killed VideoFrame
Wed 4/11 23:29:27.232 [main@191beef] Disposed Window
Wed 4/11 23:29:27.236 [main@191beef] Killed UIManager.
Wed 4/11 23:29:27.248 [main@191beef] Killed Wizard.
Wed 4/11 23:29:27.253 [main@191beef] Saving properties file to C:\Program Files (x86)\SageTV\SageTV\Sage.properties
Wed 4/11 23:29:27.275 [main@191beef] Done writing out the data to the properties file
Wed 4/11 23:29:27.282 [main@191beef] Bye-bye.
Wed 4/11 23:29:27.286 [SageTV Shutdown@d2ee56] SageTV SHUTDOWN is activating!