Mon 5/22 16:53:41.413 user.dir2=C:\Program Files\SageTV\SageTV
Mon 5/22 16:53:41.414 classpath=C:\Program Files\SageTV\SageTV\Sage.jar;C:\Program Files\SageTV\SageTV\xerces.jar;C:\Program Files\SageTV\SageTV\plugin.jar;C:\Program Files\SageTV\SageTV\;;JARs\commons-jxpath-1.1.jar;JARs\commons-logging-api.jar;JARs\commons-logging.jar;JARs\jcifs-1.1.6.jar;JARs\jdic.jar;JARs\mx4j-impl.jar;JARs\mx4j-jmx.jar;JARs\mx4j-remote.jar;JARs\mx4j-tools.jar;JARs\nielm_autoaspect.jar;JARs\nielm_sageutls.jar;JARs\nielm_sagewebserver.jar;JARs\nielm_sagexmlinfo.jar;JARs\sbbi-jmx-1.0.jar;JARs\sbbi-upnplib-1.0.3.jar;JARs\servlet.jar
Mon 5/22 16:53:41.415 JVM version=1.5.0_05
Mon 5/22 16:53:41.415 OS=Windows XP 5.1
Mon 5/22 16:53:41.420 Succesfully setup system shell hook
Mon 5/22 16:53:41.421 not specifiy WinkeyboardHook in registery, load default one
Mon 5/22 16:53:41.584 ImageUtils loading URL jar:file:/C:/Program%20Files/SageTV/SageTV/Sage.jar!/images/splash.gif
Mon 5/22 16:53:41.595 ImageUtils creating BI copy sun.awt.image.ToolkitImage@b4d3d5
Mon 5/22 16:53:41.618 SageTV V5.0.2.90
Mon 5/22 16:53:41.624 hostname=hammer
Mon 5/22 16:53:41.685 ImageUtils loading URL jar:file:/C:/Program%20Files/SageTV/SageTV/Sage.jar!/images/tvicon.gif
Mon 5/22 16:53:41.686 ImageUtils creating BI copy sun.awt.image.ToolkitImage@a401c2
Mon 5/22 16:53:41.751 ImageUtils loading URL jar:file:/C:/Program%20Files/SageTV/SageTV/Sage.jar!/images/tvicon_anim0.gif
Mon 5/22 16:53:41.753 ImageUtils creating BI copy sun.awt.image.ToolkitImage@19bd03e
Mon 5/22 16:53:41.764 ImageUtils loading URL jar:file:/C:/Program%20Files/SageTV/SageTV/Sage.jar!/images/tvicon_anim1.gif
Mon 5/22 16:53:41.767 ImageUtils creating BI copy sun.awt.image.ToolkitImage@bfbdb0
Mon 5/22 16:53:41.768 ImageUtils loading URL jar:file:/C:/Program%20Files/SageTV/SageTV/Sage.jar!/images/tvicon_anim2.gif
Mon 5/22 16:53:41.770 ImageUtils creating BI copy sun.awt.image.ToolkitImage@19fcc69
Mon 5/22 16:53:41.772 ImageUtils loading URL jar:file:/C:/Program%20Files/SageTV/SageTV/Sage.jar!/images/tvicon_anim3.gif
Mon 5/22 16:53:41.774 ImageUtils creating BI copy sun.awt.image.ToolkitImage@209f4e
Mon 5/22 16:53:41.890 Wizard starting to load database info...
Mon 5/22 16:53:41.892 Wizard DONE loading database info. loadTime=0.0010 sec
Mon 5/22 16:53:41.946 SageTV received connection from:Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:42.678 Received command of:PROPERTY_SYNC 396 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:42.862 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:42.864 Wizard allocating table for Year of size 100
Mon 5/22 16:53:42.865 Wizard loading main index for Year
Mon 5/22 16:53:42.867 Wizard allocating table for Network of size 29
Mon 5/22 16:53:42.868 Wizard loading main index for Network
Mon 5/22 16:53:42.869 Wizard allocating table for Title of size 4332
Mon 5/22 16:53:42.870 Wizard loading main index for Title
Mon 5/22 16:53:42.974 Wizard building alt. index 0 for Title
Mon 5/22 16:53:42.990 Wizard allocating table for Channel of size 365
Mon 5/22 16:53:42.991 Wizard loading main index for Channel
Mon 5/22 16:53:43.009 Wizard allocating table for People of size 22308
Mon 5/22 16:53:43.021 Wizard loading main index for People
Mon 5/22 16:53:43.214 Wizard building alt. index 0 for People
Mon 5/22 16:53:43.239 Wizard allocating table for SubCategory of size 118
Mon 5/22 16:53:43.240 Wizard loading main index for SubCategory
Mon 5/22 16:53:43.241 Wizard allocating table for Rated of size 7
Mon 5/22 16:53:43.241 Wizard loading main index for Rated
Mon 5/22 16:53:43.241 Wizard allocating table for ParentalRating of size 0
Mon 5/22 16:53:43.242 Wizard allocating table for ExtendedRating of size 10
Mon 5/22 16:53:43.242 Wizard loading main index for ExtendedRating
Mon 5/22 16:53:43.242 Wizard allocating table for Category of size 79
Mon 5/22 16:53:43.242 Wizard loading main index for Category
Mon 5/22 16:53:43.243 Wizard allocating table for PrimeTitle of size 0
Mon 5/22 16:53:43.243 Wizard allocating table for Bonus of size 538
Mon 5/22 16:53:43.244 Wizard loading main index for Bonus
Mon 5/22 16:53:43.249 Wizard allocating table for Show of size 15719
Mon 5/22 16:53:43.258 Wizard loading main index for Show
Mon 5/22 16:53:44.628 Wizard building alt. index 0 for Show
Mon 5/22 16:53:44.656 Wizard allocating table for Airing of size 39713
Mon 5/22 16:53:44.657 Wizard loading main index for Airing
Mon 5/22 16:53:45.170 Wizard building alt. index 0 for Airing
Mon 5/22 16:53:45.193 Wizard building alt. index 1 for Airing
Mon 5/22 16:53:45.216 Wizard allocating table for ManualRecord of size 27
Mon 5/22 16:53:45.216 Wizard loading main index for ManualRecord
Mon 5/22 16:53:45.220 Wizard allocating table for MediaFile of size 238
Mon 5/22 16:53:45.220 Wizard loading main index for MediaFile
Mon 5/22 16:53:45.246 Wizard building alt. index 0 for MediaFile
Mon 5/22 16:53:45.247 Wizard allocating table for Watched of size 4091
Mon 5/22 16:53:45.247 Wizard loading main index for Watched
Mon 5/22 16:53:45.336 Wizard building alt. index 0 for Watched
Mon 5/22 16:53:45.339 Wizard allocating table for Agent of size 2985
Mon 5/22 16:53:45.339 Wizard loading main index for Agent
Mon 5/22 16:53:45.467 Wizard building alt. index 0 for Agent
Mon 5/22 16:53:45.472 Wizard allocating table for Wasted of size 3366
Mon 5/22 16:53:45.472 Wizard loading main index for Wasted
Mon 5/22 16:53:45.485 Wizard allocating table for Playlist of size 2
Mon 5/22 16:53:45.486 Wizard loading main index for Playlist
Mon 5/22 16:53:45.500 Received command of:CARNY_SYNC_CAUSEMAP 5187 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:45.543 Received command of:CARNY_SYNC_WPMAP 5055 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:45.571 Received command of:CARNY_SYNC_MUSTSEE 167 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:45.578 Received command of:CARNY_SYNC_LOVE 2187 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:45.585 SageTV received connection from:Socket[addr=localhost/127.0.0.1,port=42024,localport=2600]
Mon 5/22 16:53:45.869 MMC calling detectCaptureDevices on sage.o@1bab2a6
Mon 5/22 16:53:45.889 devices detected=[Hauppauge WinTV PVR PCI II Capture, Hauppauge WinTV PVR PCI II Capture #2, Hauppauge WinTV PVR PCI II Capture #3, SGraphRecorder on 127.0.0.1:6969]
Mon 5/22 16:53:45.889 EncoderMap={Hauppauge WinTV PVR PCI II Capture #2=Hauppauge WinTV PVR PCI II Capture #2, SGraphRecorder on 127.0.0.1:6969=SGraphRecorder on 127.0.0.1:6969, Hauppauge WinTV PVR PCI II Capture=Hauppauge WinTV PVR PCI II Capture, Hauppauge WinTV PVR PCI II Capture #3=Hauppauge WinTV PVR PCI II Capture #3}
Mon 5/22 16:53:46.553 DShowFilters=[.RAM file Parser, 9x8Resize, AC3 Parser Filter, ACELP.net Sipro Lab Audio Decoder, ACM Wrapper, Allocator Fix, ASF ACM Handler, ASF DIB Handler, ASF DJPEG Handler, ASF embedded stuff Handler, ASF ICM Handler, ASF JPEG Handler, ASF URL Handler, ASX file Parser, ASX v.2 file Parser, Audio Source, AVI Decompressor, AVI Draw, AVI Mux, AVI Splitter, AVI/WAV File Source, Bitmap Generate, Color Converter, Color Space Converter, CyberLink Audio Decoder, CyberLink Audio Effect, CyberLink DxVA Filter 2, CyberLink Video/SP Decoder, Deinterlace Filter, Disk Record Queue, Dump, DV Muxer, DV Scenes, DV Source Filter, DV Splitter, DV Video Decoder, DVD Navigator, File Source (Async.), File Source (Netshow URL), File Source (URL), File stream renderer, File writer, Frame Eater, Full Screen Renderer, G.711 Codec, Hauppauge WinTV Color Format Converter, Hauppauge WinTV Color Format Converter 2, Hauppauge WinTV File Reader, Hauppauge WinTV File Writer, Hauppauge WinTV MPEG Splitter, Hauppauge WinTV SnapShot, I-Media Multiple MPEG2 Source, Indeo® audio software, Indeo® video 4.4 Compression Filter, Indeo® video 4.4 Decompression Filter, Indeo® video 5.10 Compression Filter, Indeo® video 5.10 Decompression Filter, Infinite Pin Tee Filter, Internal Script Command Renderer, InterVideo Audio Decoder, IVF source filter, LAME MPEG Layer III Audio Encoder, Ligos MPEG Splitter, Line 21 Decoder, Line 21 Decoder 2, Lyric Parser, Microsoft MPEG-4 Video Decompressor, Microsoft Screen Video Decompressor, MIDI Parser, Minimal Null, MJPEG Decompressor, MPEG Audio Decoder, MPEG Layer-3 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, Nero Audio CD Filter, Nero Audio CD Navigator, Nero Audio Processor, Nero Audio Sample Renderer, Nero Audio Stream Renderer, Nero Digital Audio Decoder, Nero Digital AVC Audio Encoder, Nero Digital AVC File Writer, Nero Digital AVC Muxer, Nero Digital AVC Null Renderer, Nero Digital AVC Subpicture Enc, Nero Digital AVC Video Enc, Nero Digital Parser, Nero DV Splitter, Nero DVD Decoder, Nero DVD Navigator, Nero ES Video Reader, Nero File Source, Nero File Source (Async.), Nero File Source / Splitter, Nero Format Converter, Nero Frame Capture, Nero InteractiveGraphics Decoder, Nero Mpeg2 Encoder, Nero Overlay Mixer, Nero Photo Source, Nero PresentationGraphics Decoder, Nero PS Muxer, Nero QuickTime(tm) Audio Decoder, Nero QuickTime(tm) Video Decoder, Nero Resize, Nero Scene Detector, Nero Scene Detector 2, Nero Splitter, Nero Stream Buffer Sink, Nero Stream Buffer Source, Nero Subpicture Decoder, Nero Vcd Navigator, Nero Video Analyzer, Nero Video Decoder, Nero Video Decoder HD, Nero Video Processor, Nero Video Sample Renderer, Nero Video Stream Renderer, NSC file Parser, Null Renderer, NVIDIA ATSC File, NVIDIA Audio Decoder, NVIDIA Cd Audio Reader, NVIDIA MultiSource Filter, NVIDIA Navigator, NVIDIA Transport Demux, NVIDIA TS Info Parser, NVIDIA Video Decoder, NVIDIA Video Post Processor, Overlay Mixer, Overlay Mixer2, QT Decompressor, QuickTime Movie Parser, Record Queue, SageTV MPEG Audio Decoder, SageTV MPEG Audio Encoder, SageTV MPEG Encoder, SageTV MPEG Layer II Audio Encoder, SageTV MPEG Multiplexer, SageTV MPEG Splitter, SageTV MPEG Video Decoder, SageTV MPEG Video Encoder, SageTV MpegDeMux, SageTV MpegMux, SageTV Music Visualization, SageTV TS Splitter 1.0, SAMI (CC) Parser, SampleGrabber, SBDARecorderDump, Screen Capture filter, Screen Capture filter, Shared File Source (Async.), ShotBoundaryDet, Smart Tee, StreamBufferSink, StreamBufferSource, Stretch Video, Uncompressed Domain Shot Detection Filter, VBI Surface Allocator, VGA 16 Color Ditherer, Video Mixing Renderer 9, Video Port Manager, Video Renderer, Video Renderer, Video Source, WAV Dest, Wave Parser, WIA Stream Snapshot Filter, Windows Media Audio Decoder, Windows Media Multiplexer, Windows Media Pad VU Data Grabber, Windows Media source filter, Windows Media Update Filter, Windows Media Video Decoder, Windows Media Video Decoder, WM ASF Reader, WM ASF Writer, WMAPro over S/PDIF DMO, WMAudio Decoder DMO, WMSpeech Decoder DMO, WMT AudioAnalyzer, WMT Black Frame Generator, WMT DirectX Transform Wrapper, WMT DV Extract, WMT Format Conversion, WMT Import Filter, WMT Interlacer, WMT Log Filter, WMT MuxDeMux Filter, WMT Sample Information Filter, WMT Screen Capture filter, WMT Switch Filter, WMT VIH2 Fix, WMT Virtual Renderer, WMT Virtual Source, WMT Volume, WMV Screen decoder DMO, WMVideo Advanced Decoder DMO, WMVideo Decoder DMO, WST Decoder, XML Playlist]
Mon 5/22 16:53:46.836 sage.aw@c8d62f needs an update in 1:40:23
Mon 5/22 16:53:46.842 MsgRecv thread has spawned for /127.0.0.1:42024
Mon 5/22 16:53:46.842 MsgSend thread spawned for /127.0.0.1:42024
Mon 5/22 16:53:46.842 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:46.843 VF thread is now running...
Mon 5/22 16:53:46.843 Loading startup runnable:net.sf.sageplugins.webserver.StartServer
Mon 5/22 16:53:46.844 SetFullScreen(true)
Mon 5/22 16:53:46.844 sage.aw@159d10 needs an update in 7:00:14
Mon 5/22 16:53:46.845 StorageDeviceDetector started...
Mon 5/22 16:53:46.845 FullScreen set to true
Mon 5/22 16:53:46.846 VF thread is now waiting for 0:00:00.000
Mon 5/22 16:53:46.846 EPG needs an update in 100 minutes
Mon 5/22 16:53:46.848 Loaded startup runnable:net.sf.sageplugins.webserver.StartServer
Mon 5/22 16:53:46.848 UIMgr loading UI from: C:\Program Files\SageTV\SageTV\STVs\SageTV3\SageTV3-5.xml
Mon 5/22 16:53:46.852 EPG's works is done. Waiting...
Mon 5/22 16:53:47.196 Starting webserver with args: [-p, 8080, -root, webserver, -t, throttles.properties, -s, servlets.properties, -r, realms.properties, -a, aliases.properties, -nohup]
Mon 5/22 16:53:47.454 locale = en
Mon 5/22 16:53:47.804 AWTThread Hang Detected - hang time = 750
Mon 5/22 16:53:47.848 DatePat=EEE, MMM d orgPat=EEEE, MMMM d, yyyy
Mon 5/22 16:53:47.859 setUI(sage.bz@12801c5[Main Menu]) histIdx=0 uiHistory=[sage.bz@12801c5[Main Menu]]
Mon 5/22 16:53:48.244 Rendered new font to cache font=java.awt.Font[family=Arial,name=Arial,style=bold,size=29] numGlyphs=1674 numCachedGlyphs=280 numImages=3
Mon 5/22 16:53:48.254 VF processing job null nPlayin=false
Mon 5/22 16:53:48.255 VF thread is now waiting for 0:00:00.000
Mon 5/22 16:53:48.434 Rendered new font to cache font=java.awt.Font[family=Arial,name=Arial,style=bold,size=23] numGlyphs=1674 numCachedGlyphs=292 numImages=2
Mon 5/22 16:53:48.637 Rendered new font to cache font=java.awt.Font[family=Arial,name=Arial,style=bold,size=42] numGlyphs=1674 numCachedGlyphs=242 numImages=5
Mon 5/22 16:53:48.872 Rendered new font to cache font=java.awt.Font[family=Arial,name=Arial,style=plain,size=45] numGlyphs=1674 numCachedGlyphs=258 numImages=7
Mon 5/22 16:53:48.878 Initializing DirectX9
Mon 5/22 16:53:48.881 Using DX9 Full Screen Exclusive Mode
Mon 5/22 16:53:48.882 Creating D3D Device
Mon 5/22 16:53:48.927 Done Initializing DirectX9
Mon 5/22 16:53:48.929 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\Background.jpg
Mon 5/22 16:53:48.958 ImageUtils creating BI copy sun.awt.image.ToolkitImage@b9e9a3
Mon 5/22 16:53:48.961 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.035 Creating DirectX9 Texture from memory w=600 h=450
Mon 5/22 16:53:49.037 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\SageLogo256.png
Mon 5/22 16:53:49.062 ImageUtils creating BI copy sun.awt.image.ToolkitImage@e7a15b
Mon 5/22 16:53:49.062 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.071 Creating DirectX9 Texture from memory w=256 h=78
Mon 5/22 16:53:49.072 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\GoWindowed.png
Mon 5/22 16:53:49.082 ImageUtils creating BI copy sun.awt.image.ToolkitImage@82acef
Mon 5/22 16:53:49.085 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.088 Creating DirectX9 Texture from memory w=117 h=102
Mon 5/22 16:53:49.089 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\GoSleep.png
Mon 5/22 16:53:49.093 ImageUtils creating BI copy sun.awt.image.ToolkitImage@1927ba1
Mon 5/22 16:53:49.093 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.096 Creating DirectX9 Texture from memory w=97 h=121
Mon 5/22 16:53:49.096 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.107 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:49.108 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.119 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:49.120 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.131 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:49.132 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.142 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:49.143 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\MenuBarLong.png
Mon 5/22 16:53:49.148 ImageUtils creating BI copy sun.awt.image.ToolkitImage@1f4e1c6
Mon 5/22 16:53:49.148 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.154 Creating DirectX9 Texture from memory w=586 h=47
Mon 5/22 16:53:49.154 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.165 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:49.165 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.176 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:49.177 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:49.188 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:51.353 setUI(sage.bz@1573872[SageRecordings SHORTCUTS]) histIdx=1 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@1573872[SageRecordings SHORTCUTS]]
Mon 5/22 16:53:51.365 setUI(sage.bz@17e5cbd[SageRecordings STYLE LINKS]) histIdx=1 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@17e5cbd[SageRecordings STYLE LINKS]]
Mon 5/22 16:53:51.547 setUI(sage.bz@9fa2fb[Xtra: SageTV Recordings by malore]) histIdx=1 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@9fa2fb[Xtra: SageTV Recordings by malore]]
Mon 5/22 16:53:51.595 setUI(sage.bz@677ea2[Xtra: SageTV Recordings by malore]) histIdx=1 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore]]
Mon 5/22 16:53:51.719 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\guideLeft.png
Mon 5/22 16:53:51.721 ImageUtils creating BI copy sun.awt.image.ToolkitImage@4ef122
Mon 5/22 16:53:51.722 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:51.723 Creating DirectX9 Texture from memory w=14 h=71
Mon 5/22 16:53:51.843 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:53:52.170 Rendered new font to cache font=java.awt.Font[family=Verdana,name=Verdana,style=bold,size=19] numGlyphs=893 numCachedGlyphs=322 numImages=2
Mon 5/22 16:53:52.170 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:52.183 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:52.317 Rendered new font to cache font=java.awt.Font[family=Verdana,name=Verdana,style=bold,size=22] numGlyphs=893 numCachedGlyphs=251 numImages=2
Mon 5/22 16:53:52.318 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:52.330 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:52.421 Rendered new font to cache font=java.awt.Font[family=Tahoma,name=Tahoma,style=bold,size=19] numGlyphs=2034 numCachedGlyphs=354 numImages=2
Mon 5/22 16:53:52.423 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:52.435 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:52.441 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\MarkerFirstRun.png
Mon 5/22 16:53:52.446 ImageUtils creating BI copy sun.awt.image.ToolkitImage@b950d1
Mon 5/22 16:53:52.447 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:52.450 Creating DirectX9 Texture from memory w=121 h=121
Mon 5/22 16:53:55.881 Rendered new font to cache font=java.awt.Font[family=Verdana,name=Verdana,style=bolditalic,size=19] numGlyphs=893 numCachedGlyphs=310 numImages=2
Mon 5/22 16:53:55.882 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:55.904 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:53:55.909 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\MarkerWatched.png
Mon 5/22 16:53:55.915 ImageUtils creating BI copy sun.awt.image.ToolkitImage@1abcd5e
Mon 5/22 16:53:55.916 Premultiplying alpha for BuffImage...
Mon 5/22 16:53:55.923 Creating DirectX9 Texture from memory w=121 h=121
Mon 5/22 16:53:56.843 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:01.184 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\MarkerHDTV.png
Mon 5/22 16:54:01.192 ImageUtils creating BI copy sun.awt.image.ToolkitImage@1ff66bd
Mon 5/22 16:54:01.193 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:01.199 Creating DirectX9 Texture from memory w=121 h=121
Mon 5/22 16:54:01.845 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:04.350 VideoFrame.watch(A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30])
Mon 5/22 16:54:04.351 watchThisFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:04.353 Watch airing is a file & over, do that instead dvd=false
Mon 5/22 16:54:04.356 VF.submitJob(VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] ifn=null])
Mon 5/22 16:54:04.357 VF processing job VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] ifn=null] nPlayin=false
Mon 5/22 16:54:04.360 VF processing on UI Thread VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] ifn=null]
Mon 5/22 16:54:04.362 VF digital TV playback detected: false
Mon 5/22 16:54:04.363 VideoFrame creating new media player for file:MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:04.364 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] ifn=null] nPlayin=false
Mon 5/22 16:54:04.364 VF network encoder playback detected: false
Mon 5/22 16:54:04.367 VF processing on UI Thread VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] ifn=null]
Mon 5/22 16:54:04.367 VF file=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] targetTime = Thu 4/27 10:00:03.011
Mon 5/22 16:54:04.368 VideoFrame.timeSelected(Thu 4/27 10:00:03.011, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:04.373 DShowPlayer setVideoRendererFilter0({51B4ABF3-748F-4E3B-A276-C828330E926A}) called
Mon 5/22 16:54:04.402 Setting up VMR9 deinterlacing
Mon 5/22 16:54:04.402 Curr Mix Prefs=0x1015
Mon 5/22 16:54:04.402 Set to 0x2015, hr=0x0, New Mix Prefs=0x2015
Mon 5/22 16:54:04.403 DShowPlayer setTimeshift=0 buffer=0
Mon 5/22 16:54:04.403 Using the default source filter
Mon 5/22 16:54:04.405 NATIVE Loading the source file
Mon 5/22 16:54:04.406 NATIVE Setting up the MPEG demux
Mon 5/22 16:54:04.409 NATIVE RenderAudio called
Mon 5/22 16:54:04.409 NATIVE RenderAudio step 1
Mon 5/22 16:54:04.409 NATIVE RenderAudio step 2
Mon 5/22 16:54:04.410 NATIVE RenderAudio step 3
Mon 5/22 16:54:04.410 NATIVE RenderAudio step 4
Mon 5/22 16:54:04.492 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.493 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.493 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.494 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.495 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.496 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.497 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.498 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.498 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.499 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.500 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.501 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.501 AutoAspect: Setting Aspect Ratio to Source as Default aspect ratio for TV files
Mon 5/22 16:54:04.502 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.503 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.503 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.504 Catbert Method Lookup Failure for:aspect_reason_array
java.lang.ClassNotFoundException: aspect.reason
Mon 5/22 16:54:04.605 NATIVE RenderVideo called
Mon 5/22 16:54:04.605 NATIVE RenderVideo step 1
Mon 5/22 16:54:04.605 NATIVE RenderVideo step 2
Mon 5/22 16:54:04.606 Video source pin information:
Mon 5/22 16:54:04.606 PIN is not connected yet!Mon 5/22 16:54:04.606 M type MEDIATYPE_Video  S type MEDIASUBTYPE_MPEG2_VIDEO F type FORMAT_MPEG2_VIDEO
Mon 5/22 16:54:04.606 NATIVE RenderVideo step 3
Mon 5/22 16:54:04.714 VMR9 alloc 720x540 Offscreen DefaultPool  format=NV12 minBuffs=1 arx=4 ary=3 nativeWidth=720 nativeHeight=540 reqNumBuff=1 allocNumBuff=1 hr=0x0
Mon 5/22 16:54:04.718 Setting up VMR9 deinterlacing
Mon 5/22 16:54:04.718 VM9Deinterlacing Tech: PixelAdaptive
Mon 5/22 16:54:04.718 VM9Deinterlacing Tech: BOBVerticalStretch
Mon 5/22 16:54:04.719 Actual deinterlace: hr=0x0 guid={212DC724-3235-44A4-BD29-E1652BBCC71C}
Mon 5/22 16:54:04.719 deinterlace mode: hr=0x1 guid={00000000-0000-0000-0000-000000000000}
Mon 5/22 16:54:04.719 Setting deinterlace mode to actual mode...
Mon 5/22 16:54:04.719 deinterlace mode: hr=0x0 guid={212DC724-3235-44A4-BD29-E1652BBCC71C}
Mon 5/22 16:54:04.719 Filter Graph Video Renderer Info:
Mon 5/22 16:54:04.719 Video Renderer:CLSID_VideoMixingRenderer9
Mon 5/22 16:54:04.719 M type MEDIATYPE_Video  S type Unknown GUID Name F type FORMAT_VideoInfo2
Mon 5/22 16:54:04.719 Interlaced video
Mon 5/22 16:54:04.719 Both fields per sample
Mon 5/22 16:54:04.719 Field 2 first
Mon 5/22 16:54:04.719 Stream never contains a Field 2
Mon 5/22 16:54:04.720 Either bob or weave mode.
Mon 5/22 16:54:04.720 VMR9 filter detected, using line 21 decoder 2.Mon 5/22 16:54:04.722 DShowGraphFilters=Default DirectSound Device,VidRend,Line21 Decoder,MPEG Audio Decoder,NVIDIA Video Decoder,SageTV MPEG2 Demultiplexer,D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg,
Mon 5/22 16:54:04.723 VideoFrame.timeSelected2(Thu 4/27 10:00:03.011, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 16:54:04.724 About to perform media time selection for 2997
Mon 5/22 16:54:04.724 Running the playback graph.
Mon 5/22 16:54:04.724 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:04.733 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:04.736 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:04.737 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:04.738 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:04.738 Event: 0xd
Mon 5/22 16:54:04.738 Event: 0xe
Mon 5/22 16:54:04.739 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:04.739 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:04.739 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:04.740 VF processing job null nPlayin=true
Mon 5/22 16:54:04.740 isRec=false rd=1798440 base=2997
Mon 5/22 16:54:04.740 VF thread is now waiting for 0:29:55.193
Mon 5/22 16:54:04.810 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:04.810 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:04.810 AutoAspect: Setting Aspect Ratio to Source as Default aspect ratio for TV files
Mon 5/22 16:54:04.811 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:04.811 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:04.811 Event: 0x8065
Mon 5/22 16:54:04.811 VF processing job null nPlayin=true
Mon 5/22 16:54:04.812 isRec=false rd=1798440 base=3053
Mon 5/22 16:54:04.812 VF thread is now waiting for 0:29:55.137
Mon 5/22 16:54:04.819 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:04.820 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:04.820 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:04.820 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:04.820 Event: 0x8065
Mon 5/22 16:54:04.821 VF processing job null nPlayin=true
Mon 5/22 16:54:04.827 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:04.828 isRec=false rd=1798440 base=3069
Mon 5/22 16:54:04.828 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:04.828 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:04.829 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:04.829 Event: 0x8065
Mon 5/22 16:54:04.829 VF processing job null nPlayin=true
Mon 5/22 16:54:04.829 isRec=false rd=1798440 base=3071
Mon 5/22 16:54:04.829 VF thread is now waiting for 0:29:55.119
Mon 5/22 16:54:04.913 VMR9 rendering began VRAM free=355467264
Mon 5/22 16:54:04.918 Created alternate surface
Mon 5/22 16:54:05.398 setUI(sage.bz@f60f20[MediaPlayer OSD]) histIdx=2 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD]]
Mon 5/22 16:54:05.740 Rendered new font to cache font=java.awt.Font[family=Arial,name=Arial,style=bold,size=32] numGlyphs=1674 numCachedGlyphs=293 numImages=4
Mon 5/22 16:54:05.742 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.753 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:54:05.754 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.767 Creating DirectX9 Texture from memory w=256 h=256
Mon 5/22 16:54:05.770 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDStatusPlay.png
Mon 5/22 16:54:05.772 ImageUtils creating BI copy sun.awt.image.ToolkitImage@fb78af
Mon 5/22 16:54:05.773 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.777 Creating DirectX9 Texture from memory w=8 h=8
Mon 5/22 16:54:05.777 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDVolOn.png
Mon 5/22 16:54:05.778 ImageUtils creating BI copy sun.awt.image.ToolkitImage@a9fa9c
Mon 5/22 16:54:05.778 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.779 Creating DirectX9 Texture from memory w=16 h=13
Mon 5/22 16:54:05.779 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDVolBar.png
Mon 5/22 16:54:05.780 ImageUtils creating BI copy sun.awt.image.ToolkitImage@9d1e83
Mon 5/22 16:54:05.780 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.781 Creating DirectX9 Texture from memory w=64 h=4
Mon 5/22 16:54:05.781 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDVolSlider.png
Mon 5/22 16:54:05.781 ImageUtils creating BI copy sun.awt.image.ToolkitImage@14322d1
Mon 5/22 16:54:05.782 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.782 Creating DirectX9 Texture from memory w=9 h=15
Mon 5/22 16:54:05.782 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDReplay.png
Mon 5/22 16:54:05.783 ImageUtils creating BI copy sun.awt.image.ToolkitImage@544b02
Mon 5/22 16:54:05.783 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.784 Creating DirectX9 Texture from memory w=29 h=26
Mon 5/22 16:54:05.784 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDRew.png
Mon 5/22 16:54:05.785 ImageUtils creating BI copy sun.awt.image.ToolkitImage@18c5b4f
Mon 5/22 16:54:05.786 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.787 Creating DirectX9 Texture from memory w=30 h=26
Mon 5/22 16:54:05.788 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDStop.png
Mon 5/22 16:54:05.789 ImageUtils creating BI copy sun.awt.image.ToolkitImage@b8f952
Mon 5/22 16:54:05.789 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.790 Creating DirectX9 Texture from memory w=30 h=26
Mon 5/22 16:54:05.790 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDPause.png
Mon 5/22 16:54:05.791 ImageUtils creating BI copy sun.awt.image.ToolkitImage@1abdb8a
Mon 5/22 16:54:05.792 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.793 Creating DirectX9 Texture from memory w=30 h=26
Mon 5/22 16:54:05.793 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDFwd.png
Mon 5/22 16:54:05.794 ImageUtils creating BI copy sun.awt.image.ToolkitImage@c90a0a
Mon 5/22 16:54:05.794 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.795 Creating DirectX9 Texture from memory w=30 h=26
Mon 5/22 16:54:05.795 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDSkip.png
Mon 5/22 16:54:05.796 ImageUtils creating BI copy sun.awt.image.ToolkitImage@1f75ab1
Mon 5/22 16:54:05.796 Premultiplying alpha for BuffImage...
Mon 5/22 16:54:05.797 Creating DirectX9 Texture from memory w=29 h=26
Mon 5/22 16:54:06.846 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:07.207 VF.submitJob(VFJob[TimeSet r=0.0 t=1146157242820 file=null ifn=null])
Mon 5/22 16:54:07.208 VF processing job VFJob[TimeSet r=0.0 t=1146157242820 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.210 VF processing on UI Thread VFJob[TimeSet r=0.0 t=1146157242820 file=null ifn=null]
Mon 5/22 16:54:07.211 VideoFrame.timeSelected(Thu 4/27 10:00:42.820, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:07.212 VideoFrame.timeSelected2(Thu 4/27 10:00:42.820, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 16:54:07.212 About to perform media time selection for 42772
Mon 5/22 16:54:07.317 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.319 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.320 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.321 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.321 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.321 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.322 Event: 0x8065
Mon 5/22 16:54:07.322 Event: 0x8065
Mon 5/22 16:54:07.322 Event: 0x8065
Mon 5/22 16:54:07.322 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.323 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.323 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.323 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.324 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.324 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.325 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.325 Event: 0x8065
Mon 5/22 16:54:07.325 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.326 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.326 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.327 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.327 Event: 0x8065
Mon 5/22 16:54:07.327 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.328 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.328 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.329 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.329 Event: 0x8065
Mon 5/22 16:54:07.329 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.330 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.330 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.334 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.335 Event: 0x8065
Mon 5/22 16:54:07.335 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.336 Event: 0x8065
Mon 5/22 16:54:07.336 Event: 0x8065
Mon 5/22 16:54:07.336 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.337 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.341 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.342 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.343 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.343 Event: 0x8065
Mon 5/22 16:54:07.348 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.349 Event: 0x8065
Mon 5/22 16:54:07.350 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:07.350 Event: 0x8065
Mon 5/22 16:54:07.350 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.351 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.351 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.352 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.352 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.353 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.353 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.354 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.355 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.355 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.356 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.356 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.357 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:07.357 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:07.358 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:07.358 VF processing job null nPlayin=true
Mon 5/22 16:54:07.359 isRec=false rd=1798440 base=43070
Mon 5/22 16:54:07.360 VF thread is now waiting for 0:29:15.120
Mon 5/22 16:54:08.615 VF.submitJob(VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null])
Mon 5/22 16:54:08.615 VF processing job VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.616 VF processing on UI Thread VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null]
Mon 5/22 16:54:08.617 VideoFrame.timeSelected(Thu 4/27 10:01:14.357, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:08.617 VideoFrame.timeSelected2(Thu 4/27 10:01:14.357, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 16:54:08.618 About to perform media time selection for 74282
Mon 5/22 16:54:08.723 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:08.725 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.726 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:08.727 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:08.727 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:08.728 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:08.728 Event: 0x8065
Mon 5/22 16:54:08.728 Event: 0x8065
Mon 5/22 16:54:08.728 Event: 0x8065
Mon 5/22 16:54:08.728 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.730 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:08.732 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:08.732 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.733 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:08.733 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:08.734 VF processing job null nPlayin=true
Mon 5/22 16:54:08.734 isRec=false rd=1798440 base=74282
Mon 5/22 16:54:08.734 VF thread is now waiting for 0:28:43.908
Mon 5/22 16:54:08.735 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:08.736 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.736 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:08.738 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:08.738 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:08.739 Event: 0x8065
Mon 5/22 16:54:08.739 Event: 0x8065
Mon 5/22 16:54:08.739 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.741 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:08.744 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:08.744 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:08.745 Event: 0x8065
Mon 5/22 16:54:08.745 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:08.746 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:08.746 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:08.746 VF processing job null nPlayin=true
Mon 5/22 16:54:08.747 isRec=false rd=1798440 base=74288
Mon 5/22 16:54:08.747 VF thread is now waiting for 0:28:43.902
Mon 5/22 16:54:09.631 VF.submitJob(VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null])
Mon 5/22 16:54:09.632 VF processing job VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.633 VF processing on UI Thread VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null]
Mon 5/22 16:54:09.634 VideoFrame.timeSelected(Thu 4/27 10:01:45.610, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:09.635 VideoFrame.timeSelected2(Thu 4/27 10:01:45.610, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 16:54:09.635 About to perform media time selection for 105508
Mon 5/22 16:54:09.740 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.742 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.743 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.743 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.744 Event: 0x8065
Mon 5/22 16:54:09.744 VF processing job null nPlayin=true
Mon 5/22 16:54:09.744 isRec=false rd=1798440 base=105508
Mon 5/22 16:54:09.745 VF thread is now waiting for 0:28:12.682
Mon 5/22 16:54:09.746 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.746 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.747 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.747 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.748 Event: 0x8065
Mon 5/22 16:54:09.748 Event: 0x8065
Mon 5/22 16:54:09.748 VF processing job null nPlayin=true
Mon 5/22 16:54:09.750 isRec=false rd=1798440 base=105508
Mon 5/22 16:54:09.751 VF thread is now waiting for 0:28:12.682
Mon 5/22 16:54:09.752 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.753 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.753 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.754 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.760 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.761 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.761 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.761 Event: 0x8065
Mon 5/22 16:54:09.762 Event: 0x8065
Mon 5/22 16:54:09.762 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.763 Event: 0x8065
Mon 5/22 16:54:09.763 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.764 Event: 0x8065
Mon 5/22 16:54:09.764 Event: 0x8065
Mon 5/22 16:54:09.764 Event: 0x8065
Mon 5/22 16:54:09.764 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:09.769 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.770 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.771 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.771 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.772 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.772 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.773 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.773 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.774 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.774 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.776 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.777 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.778 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.779 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.780 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.780 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:09.781 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:09.784 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:09.785 VF processing job null nPlayin=true
Mon 5/22 16:54:09.785 isRec=false rd=1798440 base=105700
Mon 5/22 16:54:09.786 VF thread is now waiting for 0:28:12.490
Mon 5/22 16:54:11.661 VF.submitJob(VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null])
Mon 5/22 16:54:11.662 VF processing job VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.663 VF processing on UI Thread VFJob[TimeAdjust r=0.0 t=30000 file=null ifn=null]
Mon 5/22 16:54:11.664 VideoFrame.timeSelected(Thu 4/27 10:02:17.662, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 16:54:11.665 VideoFrame.timeSelected2(Thu 4/27 10:02:17.662, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 16:54:11.665 About to perform media time selection for 137532
Mon 5/22 16:54:11.769 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.772 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.772 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.773 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.773 Event: 0x8065
Mon 5/22 16:54:11.773 VF processing job null nPlayin=true
Mon 5/22 16:54:11.774 isRec=false rd=1798440 base=137532
Mon 5/22 16:54:11.774 VF thread is now waiting for 0:27:40.658
Mon 5/22 16:54:11.787 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.788 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.789 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.789 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.789 Event: 0x8065
Mon 5/22 16:54:11.789 VF processing job null nPlayin=true
Mon 5/22 16:54:11.790 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.790 isRec=false rd=1798440 base=137541
Mon 5/22 16:54:11.791 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.791 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.792 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.792 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.793 Event: 0x8065
Mon 5/22 16:54:11.793 Event: 0x8065
Mon 5/22 16:54:11.793 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.794 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.794 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.796 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.796 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.797 Event: 0x8065
Mon 5/22 16:54:11.797 Event: 0x8065
Mon 5/22 16:54:11.797 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.798 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.798 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.799 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.799 Event: 0x8065
Mon 5/22 16:54:11.800 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.800 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.801 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.801 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.801 Event: 0x8065
Mon 5/22 16:54:11.802 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.802 Event: 0x8065
Mon 5/22 16:54:11.802 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.803 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.804 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.804 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.805 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.805 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.805 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.806 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.806 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.806 VF processing job null nPlayin=true
Mon 5/22 16:54:11.807 isRec=false rd=1798440 base=137870
Mon 5/22 16:54:11.807 VF thread is now waiting for 0:27:40.319
Mon 5/22 16:54:11.807 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.808 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.808 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.809 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.809 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.810 Event: 0x8065
Mon 5/22 16:54:11.810 Event: 0x8065
Mon 5/22 16:54:11.810 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.810 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.811 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.811 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 16:54:11.812 Event: 0x8065
Mon 5/22 16:54:11.812 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 16:54:11.812 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 16:54:11.815 DShowMediaPlayer is consuming the events...
Mon 5/22 16:54:11.816 VF processing job null nPlayin=true
Mon 5/22 16:54:11.817 isRec=false rd=1798440 base=137875
Mon 5/22 16:54:11.818 VF thread is now waiting for 0:27:40.315
Mon 5/22 16:54:11.847 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:16.848 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:21.849 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:26.850 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:31.850 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:36.851 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:41.853 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:46.854 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:51.856 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:54:56.857 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:01.858 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:06.860 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:11.861 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:16.864 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:21.864 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:26.866 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:31.867 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:36.868 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:41.871 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:46.873 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:51.874 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:55:56.874 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:01.875 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:06.877 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:11.878 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:16.879 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:21.880 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:26.882 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:31.883 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:36.884 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:41.885 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:46.887 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:51.888 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:56:56.889 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:01.890 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:06.891 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:11.893 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:16.896 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:21.897 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:26.898 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:31.899 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:36.901 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:41.902 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:46.903 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:51.905 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:57:56.906 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:01.907 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:06.908 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:11.909 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:16.911 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:21.912 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:26.913 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.137 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.140 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.142 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.145 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.147 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.148 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.150 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.151 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.153 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.170 Received command of:CARNY_SYNC_LOVE 2187 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.198 Received command of:CARNY_SYNC_WPMAP 4965 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.289 Received command of:CARNY_SYNC_CAUSEMAP 5095 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:30.343 Received command of:CARNY_SYNC_MUSTSEE 165 from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:31.914 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:32.804 VF processing job null nPlayin=true
Mon 5/22 16:58:32.806 isRec=false rd=1798440 base=398835
Mon 5/22 16:58:32.806 VF thread is now waiting for 0:23:19.355
Mon 5/22 16:58:36.915 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:41.916 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:46.917 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:51.918 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:58:56.919 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:01.921 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:06.922 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:11.923 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:16.812 Screen Saver Timeout expired....tv=true playin=true fs=true sleepy=false currSS=false
Mon 5/22 16:59:16.924 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:21.926 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:26.927 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:31.928 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:36.929 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:41.931 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:46.932 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:51.933 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 16:59:56.934 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:01.936 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:06.937 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:11.938 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:16.939 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:21.941 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:26.944 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:31.945 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:36.946 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:41.947 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:46.949 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:51.950 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:00:56.951 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:01.952 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:06.954 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:11.955 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:16.956 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:21.957 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:26.958 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:31.960 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:36.961 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:41.962 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:46.963 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:51.965 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:01:56.966 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:01.967 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:06.968 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:11.970 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:16.971 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:21.972 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:26.975 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:31.978 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:36.980 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:41.981 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:46.982 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:51.983 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:02:56.984 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:01.984 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:06.985 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:11.987 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:16.988 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:21.988 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:26.989 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:31.990 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:33.021 VF processing job null nPlayin=true
Mon 5/22 17:03:33.021 isRec=false rd=1798440 base=699049
Mon 5/22 17:03:33.022 VF thread is now waiting for 0:18:19.140
Mon 5/22 17:03:35.160 VF.submitJob(VFJob[TimeSet r=0.0 t=1146158107352 file=null ifn=null])
Mon 5/22 17:03:35.161 VF processing job VFJob[TimeSet r=0.0 t=1146158107352 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.162 VF processing on UI Thread VFJob[TimeSet r=0.0 t=1146158107352 file=null ifn=null]
Mon 5/22 17:03:35.163 VideoFrame.timeSelected(Thu 4/27 10:15:07.352, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 17:03:35.163 VideoFrame.timeSelected2(Thu 4/27 10:15:07.352, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 17:03:35.163 About to perform media time selection for 906556
Mon 5/22 17:03:35.269 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.271 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.272 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.273 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.273 Event: 0x8065
Mon 5/22 17:03:35.273 VF processing job null nPlayin=true
Mon 5/22 17:03:35.274 isRec=false rd=1798440 base=906556
Mon 5/22 17:03:35.274 VF thread is now waiting for 0:14:51.634
Mon 5/22 17:03:35.289 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.290 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.290 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.291 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.291 Event: 0x8065
Mon 5/22 17:03:35.291 VF processing job null nPlayin=true
Mon 5/22 17:03:35.291 isRec=false rd=1798440 base=906566
Mon 5/22 17:03:35.292 VF thread is now waiting for 0:14:51.624
Mon 5/22 17:03:35.292 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.293 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.293 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.294 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.295 Event: 0x8065
Mon 5/22 17:03:35.295 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.295 Event: 0x8065
Mon 5/22 17:03:35.296 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.297 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.297 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.298 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.298 Event: 0x8065
Mon 5/22 17:03:35.298 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.302 Event: 0x8065
Mon 5/22 17:03:35.302 Event: 0x8065
Mon 5/22 17:03:35.302 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.303 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.303 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.304 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.304 Event: 0x8065
Mon 5/22 17:03:35.304 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.304 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.305 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.305 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.306 Event: 0x8065
Mon 5/22 17:03:35.306 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.306 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.307 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:03:35.307 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.308 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.308 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.311 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.313 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:03:35.313 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:03:35.314 DShowMediaPlayer is consuming the events...
Mon 5/22 17:03:35.314 VF processing job null nPlayin=true
Mon 5/22 17:03:35.315 isRec=false rd=1798440 base=906742
Mon 5/22 17:03:35.316 VF thread is now waiting for 0:14:51.448
Mon 5/22 17:03:36.992 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:41.992 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:46.996 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:51.996 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:03:56.997 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:01.998 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:06.999 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:12.000 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:17.001 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:22.003 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:27.004 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:32.005 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:37.006 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:42.008 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:47.009 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:52.010 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:04:57.011 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:02.013 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:07.014 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:12.015 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:17.016 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:22.018 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:27.019 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:32.019 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:37.021 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:42.022 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:47.023 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:52.024 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:05:57.025 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:02.026 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:07.029 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:12.030 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:17.031 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:22.033 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:27.034 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:32.036 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:37.037 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:42.037 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:47.039 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:52.040 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:06:57.041 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:02.043 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:07.044 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:12.047 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:17.048 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:22.049 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:27.050 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:32.052 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:37.053 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:42.054 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:47.054 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:52.056 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:07:57.057 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:02.058 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:07.058 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:12.059 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:17.060 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:22.060 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:27.062 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:32.063 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:33.310 VF processing job null nPlayin=true
Mon 5/22 17:08:33.311 isRec=false rd=1798440 base=1204712
Mon 5/22 17:08:33.311 VF thread is now waiting for 0:09:53.477
Mon 5/22 17:08:37.064 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:42.065 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:44.242 Screen Saver Timeout expired....tv=true playin=true fs=true sleepy=false currSS=false
Mon 5/22 17:08:47.066 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:52.067 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:08:57.068 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:02.069 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:07.070 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:12.072 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:17.073 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:22.074 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:27.074 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:32.075 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:37.077 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:42.078 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:47.079 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:52.080 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:09:57.082 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:02.084 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:07.085 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:12.086 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:17.088 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:22.089 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:27.090 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:32.091 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:37.093 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:42.094 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:47.095 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:52.096 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:10:57.097 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:02.099 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:07.100 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:12.101 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:14.450 VF.submitJob(VFJob[TimeSet r=0.0 t=1146158685630 file=null ifn=null])
Mon 5/22 17:11:14.451 VF processing job VFJob[TimeSet r=0.0 t=1146158685630 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.451 VF processing on UI Thread VFJob[TimeSet r=0.0 t=1146158685630 file=null ifn=null]
Mon 5/22 17:11:14.452 VideoFrame.timeSelected(Thu 4/27 10:24:45.630, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 17:11:14.452 VideoFrame.timeSelected2(Thu 4/27 10:24:45.630, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 17:11:14.453 About to perform media time selection for 1484333
Mon 5/22 17:11:14.558 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.561 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.562 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.562 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.562 Event: 0x8065
Mon 5/22 17:11:14.563 VF processing job null nPlayin=true
Mon 5/22 17:11:14.563 isRec=false rd=1798440 base=1484333
Mon 5/22 17:11:14.563 VF thread is now waiting for 0:05:13.857
Mon 5/22 17:11:14.578 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.578 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.579 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.579 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.580 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.580 Event: 0x8065
Mon 5/22 17:11:14.580 Event: 0x8065
Mon 5/22 17:11:14.580 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.581 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.581 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.582 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.582 Event: 0x8065
Mon 5/22 17:11:14.583 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.583 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.584 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.584 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.585 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.585 Event: 0x8065
Mon 5/22 17:11:14.585 Event: 0x8065
Mon 5/22 17:11:14.586 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.586 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.586 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.587 Event: 0x8065
Mon 5/22 17:11:14.587 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.587 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.588 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.588 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.589 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.589 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.589 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.590 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.590 Event: 0x8065
Mon 5/22 17:11:14.590 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.591 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.591 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.591 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.592 Event: 0x8065
Mon 5/22 17:11:14.592 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.592 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.593 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.593 VF processing job null nPlayin=true
Mon 5/22 17:11:14.593 isRec=false rd=1798440 base=1484347
Mon 5/22 17:11:14.594 VF thread is now waiting for 0:05:13.843
Mon 5/22 17:11:14.596 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.597 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.598 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.598 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.598 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.599 Event: 0x8065
Mon 5/22 17:11:14.599 Event: 0x8065
Mon 5/22 17:11:14.600 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:11:14.600 Event: 0x8065
Mon 5/22 17:11:14.600 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.601 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.601 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.602 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:11:14.602 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:11:14.603 DShowMediaPlayer is consuming the events...
Mon 5/22 17:11:14.603 VF processing job null nPlayin=true
Mon 5/22 17:11:14.603 isRec=false rd=1798440 base=1484347
Mon 5/22 17:11:14.604 VF thread is now waiting for 0:05:13.843
Mon 5/22 17:11:17.102 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:22.103 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:27.104 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:32.105 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:37.106 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:42.108 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:47.110 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:52.111 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:11:57.112 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:02.113 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:07.114 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:12.115 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:17.116 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:22.117 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:27.119 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:32.120 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:37.121 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:42.122 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:47.123 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:52.124 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:12:57.125 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:02.126 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:07.128 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:12.129 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:17.130 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:22.131 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:27.132 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:32.132 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:33.594 VF processing job null nPlayin=true
Mon 5/22 17:13:33.595 isRec=false rd=1798440 base=1623329
Mon 5/22 17:13:33.595 VF thread is now waiting for 0:02:54.861
Mon 5/22 17:13:37.133 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:42.134 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:47.136 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:50.457 VF.submitJob(VFJob[TimeAdjust r=0.0 t=120000 file=null ifn=null])
Mon 5/22 17:13:50.458 VF processing job VFJob[TimeAdjust r=0.0 t=120000 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:50.458 VF processing on UI Thread VFJob[TimeAdjust r=0.0 t=120000 file=null ifn=null]
Mon 5/22 17:13:50.459 VideoFrame.timeSelected(Thu 4/27 10:29:21.624, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 17:13:50.459 VideoFrame.timeSelected2(Thu 4/27 10:29:21.624, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 17:13:50.460 About to perform media time selection for 1760088
Mon 5/22 17:13:50.565 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:50.567 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:50.567 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:50.568 DShowMediaPlayer is consuming the events...
Mon 5/22 17:13:50.568 Event: 0x8065
Mon 5/22 17:13:50.568 VF processing job null nPlayin=true
Mon 5/22 17:13:50.569 isRec=false rd=1798440 base=1760088
Mon 5/22 17:13:50.569 VF thread is now waiting for 0:00:38.102
Mon 5/22 17:13:50.576 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:50.577 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:50.577 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:50.578 DShowMediaPlayer is consuming the events...
Mon 5/22 17:13:50.579 Event: 0x8065
Mon 5/22 17:13:50.580 VF processing job null nPlayin=true
Mon 5/22 17:13:50.580 isRec=false rd=1798440 base=1760092
Mon 5/22 17:13:50.580 VF thread is now waiting for 0:00:38.098
Mon 5/22 17:13:50.582 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:50.583 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:50.584 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:50.585 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:50.585 DShowMediaPlayer is consuming the events...
Mon 5/22 17:13:50.586 Event: 0x8065
Mon 5/22 17:13:50.586 Event: 0x8065
Mon 5/22 17:13:50.586 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:50.586 Event: 0x8065
Mon 5/22 17:13:50.587 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:50.587 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:50.588 DShowMediaPlayer is consuming the events...
Mon 5/22 17:13:50.588 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:50.588 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:50.589 DShowMediaPlayer is consuming the events...
Mon 5/22 17:13:50.589 VF processing job null nPlayin=true
Mon 5/22 17:13:50.589 isRec=false rd=1798440 base=1760097
Mon 5/22 17:13:50.590 VF thread is now waiting for 0:00:38.093
Mon 5/22 17:13:51.887 VF.submitJob(VFJob[TimeAdjust r=0.0 t=120000 file=null ifn=null])
Mon 5/22 17:13:51.888 VF processing job VFJob[TimeAdjust r=0.0 t=120000 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:51.889 VF processing on UI Thread VFJob[TimeAdjust r=0.0 t=120000 file=null ifn=null]
Mon 5/22 17:13:51.889 VideoFrame.timeSelected(Thu 4/27 10:31:22.901, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]]
Mon 5/22 17:13:51.890 VideoFrame.timeSelected2(Thu 4/27 10:30:00.009, true) currFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]] realDur=1798440
Mon 5/22 17:13:51.890 About to perform media time selection for 1798440
Mon 5/22 17:13:51.996 VF processing job null nPlayin=true
Mon 5/22 17:13:51.996 isRec=false rd=1798440 base=1798440
Mon 5/22 17:13:51.997 VF processing job VFJob[StdComplete r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:51.997 VF processing on UI Thread VFJob[StdComplete r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:51.998 VF.submitJob(VFJob[Pause r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:52.002 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.004 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.005 VF logFileWatch doneAir=A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] theTime=Thu 4/27 10:30:00.009 recTime=Thu 4/27 10:00:00.011
Mon 5/22 17:13:52.006 VF processing job VFJob[Pause r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:13:52.007 VF processing on UI Thread VFJob[Pause r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:52.007 Pausing the playback graph.
Mon 5/22 17:13:52.011 processOptionsMenu optionsMenu=default:null|OptionsMenu:AskToDeleteRecording context=Context[parent=Context[parent=Context[parent=null map={}] map={commercials2=[Ljava.lang.String;@114441e, DisplayInfo=false, comautoskip=false, DisplayChanStatus=false, ChannelSurf=, DisplayTimeStatus=true, comautorunning=true, commerciallist=1146157200044	1146157242820	1146157900478	1146158107352	1146158564576	1146158685630	1146158838983	1146158998409	, DisplayVolTransportsTime=false, DisplayVolStatus=false, TimeScrollTime=-1, ShowVideoBGWidget=true, forkstop=false, MaxChannel=9999}] map={MediaFile=MediaFile[id=1910859 A[1866551,1866359,"I Dream of Jeannie",26046@0427.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play D:\Sage\IDreamofJeannie-TheCaseofMyVanishingMaster-1866551-0.mpg, Seg0[Thu 4/27 10:00:00.011-Thu 4/27 10:30:00.009]], AskToDelete=true, _SAGE_HOOKSOURCEWIDGET=java.lang.Object@18425b7, ReturnValue=null, CheckToDelete=true}]
Mon 5/22 17:13:52.023 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:52.030 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.030 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=false
Mon 5/22 17:13:52.031 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:52.031 DShowMediaPlayer is consuming the events...
Mon 5/22 17:13:52.031 Event: 0xe
Mon 5/22 17:13:52.031 VF processing job null nPlayin=false
Mon 5/22 17:13:52.032 isRec=false rd=1798440 base=1798440
Mon 5/22 17:13:52.032 VF thread is now waiting for 0:00:00.000
Mon 5/22 17:13:52.034 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.037 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.040 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.042 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.044 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.047 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.049 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.052 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:52.076 ImageUtils loading file C:\Program Files\SageTV\SageTV\STVs\SageTV3\OSDStatusPause.png
Mon 5/22 17:13:52.078 ImageUtils creating BI copy sun.awt.image.ToolkitImage@d73256
Mon 5/22 17:13:52.079 Premultiplying alpha for BuffImage...
Mon 5/22 17:13:52.080 Creating DirectX9 Texture from memory w=6 h=8
Mon 5/22 17:13:52.137 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:54.732 VF.submitJob(VFJob[CloseMF r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:13:54.733 VF processing job VFJob[CloseMF r=0.0 t=0 file=null ifn=null] nPlayin=false
Mon 5/22 17:13:54.733 VF processing on UI Thread VFJob[CloseMF r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:13:54.735 Stopping the playback graph.
Mon 5/22 17:13:54.738 Tearing down playback graph
Mon 5/22 17:13:54.738 NATIVE Deallocating the CPlayerData object
Mon 5/22 17:13:54.751 VMR9 rendering done VRAM free=372244480
Mon 5/22 17:13:54.776 NATIVE Finished destroying the playback graph
Mon 5/22 17:13:54.778 VF processing job null nPlayin=false
Mon 5/22 17:13:54.778 VF thread is now waiting for 0:00:00.000
Mon 5/22 17:13:54.784 VF processing job null nPlayin=false
Mon 5/22 17:13:54.785 VF thread is now waiting for 0:00:00.000
Mon 5/22 17:13:54.792 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:54.990 Received command of:WIZARD_SYNC from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:54.993 setUI(sage.bz@1573872[SageRecordings SHORTCUTS]) histIdx=3 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@1573872[SageRecordings SHORTCUTS]]
Mon 5/22 17:13:54.995 setUI(sage.bz@17e5cbd[SageRecordings STYLE LINKS]) histIdx=3 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@17e5cbd[SageRecordings STYLE LINKS]]
Mon 5/22 17:13:54.998 setUI(sage.bz@9fa2fb[Xtra: SageTV Recordings by malore]) histIdx=3 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@9fa2fb[Xtra: SageTV Recordings by malore]]
Mon 5/22 17:13:55.026 setUI(sage.bz@677ea2[Xtra: SageTV Recordings by malore]) histIdx=3 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@677ea2[Xtra: SageTV Recordings by malore]]
Mon 5/22 17:13:55.086 setUI(sage.bz@1573872[SageRecordings SHORTCUTS]) histIdx=4 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@1573872[SageRecordings SHORTCUTS]]
Mon 5/22 17:13:55.090 setUI(sage.bz@17e5cbd[SageRecordings STYLE LINKS]) histIdx=4 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@17e5cbd[SageRecordings STYLE LINKS]]
Mon 5/22 17:13:55.092 setUI(sage.bz@9fa2fb[Xtra: SageTV Recordings by malore]) histIdx=4 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@9fa2fb[Xtra: SageTV Recordings by malore]]
Mon 5/22 17:13:55.096 setUI(sage.bz@677ea2[Xtra: SageTV Recordings by malore]) histIdx=4 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@677ea2[Xtra: SageTV Recordings by malore]]
Mon 5/22 17:13:57.138 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:13:57.435 VF processing job null nPlayin=false
Mon 5/22 17:13:57.435 VF thread is now waiting for 0:00:00.000
Mon 5/22 17:14:02.138 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:02.646 VideoFrame.watch(A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30])
Mon 5/22 17:14:02.647 watchThisFile=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]]
Mon 5/22 17:14:02.649 Watch airing is a file & over, do that instead dvd=false
Mon 5/22 17:14:02.650 VF.submitJob(VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] ifn=null])
Mon 5/22 17:14:02.651 VF processing job VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] ifn=null] nPlayin=false
Mon 5/22 17:14:02.653 VF processing on UI Thread VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] ifn=null]
Mon 5/22 17:14:02.654 VF digital TV playback detected: false
Mon 5/22 17:14:02.654 VideoFrame creating new media player for file:MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]]
Mon 5/22 17:14:02.655 VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] ifn=null] nPlayin=false
Mon 5/22 17:14:02.655 VF network encoder playback detected: false
Mon 5/22 17:14:02.657 VF processing on UI Thread VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] ifn=null]
Mon 5/22 17:14:02.658 VF file=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] targetTime = Mon 5/1 10:00:03.013
Mon 5/22 17:14:02.658 VideoFrame.timeSelected(Mon 5/1 10:00:03.013, true) currFile=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]]
Mon 5/22 17:14:02.660 DShowPlayer setVideoRendererFilter0({51B4ABF3-748F-4E3B-A276-C828330E926A}) called
Mon 5/22 17:14:02.684 Setting up VMR9 deinterlacing
Mon 5/22 17:14:02.684 Curr Mix Prefs=0x1015
Mon 5/22 17:14:02.684 Set to 0x2015, hr=0x0, New Mix Prefs=0x2015
Mon 5/22 17:14:02.685 DShowPlayer setTimeshift=0 buffer=0
Mon 5/22 17:14:02.685 Using the default source filter
Mon 5/22 17:14:02.685 NATIVE Loading the source file
Mon 5/22 17:14:02.697 NATIVE Setting up the MPEG demux
Mon 5/22 17:14:02.712 NATIVE RenderAudio called
Mon 5/22 17:14:02.712 NATIVE RenderAudio step 1
Mon 5/22 17:14:02.713 NATIVE RenderAudio step 2
Mon 5/22 17:14:02.713 NATIVE RenderAudio step 3
Mon 5/22 17:14:02.713 NATIVE RenderAudio step 4
Mon 5/22 17:14:02.718 AutoAspect: Setting Aspect Ratio to Source as Default aspect ratio for TV files
Mon 5/22 17:14:02.764 NATIVE RenderVideo called
Mon 5/22 17:14:02.764 NATIVE RenderVideo step 1
Mon 5/22 17:14:02.764 NATIVE RenderVideo step 2
Mon 5/22 17:14:02.764 Video source pin information:
Mon 5/22 17:14:02.764 PIN is not connected yet!Mon 5/22 17:14:02.764 M type MEDIATYPE_Video  S type MEDIASUBTYPE_MPEG2_VIDEO F type FORMAT_MPEG2_VIDEO
Mon 5/22 17:14:02.764 NATIVE RenderVideo step 3
Mon 5/22 17:14:02.880 VMR9 alloc 720x540 Offscreen DefaultPool  format=NV12 minBuffs=1 arx=4 ary=3 nativeWidth=720 nativeHeight=540 reqNumBuff=1 allocNumBuff=1 hr=0x0
Mon 5/22 17:14:02.884 Setting up VMR9 deinterlacing
Mon 5/22 17:14:02.884 VM9Deinterlacing Tech: PixelAdaptive
Mon 5/22 17:14:02.884 VM9Deinterlacing Tech: BOBVerticalStretch
Mon 5/22 17:14:02.884 Actual deinterlace: hr=0x0 guid={212DC724-3235-44A4-BD29-E1652BBCC71C}
Mon 5/22 17:14:02.884 deinterlace mode: hr=0x1 guid={00000000-0000-0000-0000-000000000000}
Mon 5/22 17:14:02.884 Setting deinterlace mode to actual mode...
Mon 5/22 17:14:02.884 deinterlace mode: hr=0x0 guid={212DC724-3235-44A4-BD29-E1652BBCC71C}
Mon 5/22 17:14:02.884 Filter Graph Video Renderer Info:
Mon 5/22 17:14:02.885 Video Renderer:CLSID_VideoMixingRenderer9
Mon 5/22 17:14:02.885 M type MEDIATYPE_Video  S type Unknown GUID Name F type FORMAT_VideoInfo2
Mon 5/22 17:14:02.885 Interlaced video
Mon 5/22 17:14:02.885 Both fields per sample
Mon 5/22 17:14:02.885 Field 2 first
Mon 5/22 17:14:02.885 Stream never contains a Field 2
Mon 5/22 17:14:02.885 Either bob or weave mode.
Mon 5/22 17:14:02.885 VMR9 filter detected, using line 21 decoder 2.Mon 5/22 17:14:02.886 DShowGraphFilters=Default DirectSound Device,VidRend,Line21 Decoder,MPEG Audio Decoder,NVIDIA Video Decoder,SageTV MPEG2 Demultiplexer,E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg,
Mon 5/22 17:14:02.886 VideoFrame.timeSelected2(Mon 5/1 10:00:03.013, true) currFile=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] realDur=1798774
Mon 5/22 17:14:02.887 About to perform media time selection for 2998
Mon 5/22 17:14:02.887 Running the playback graph.
Mon 5/22 17:14:02.887 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:02.894 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:02.896 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:02.896 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:02.896 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:02.896 Event: 0xd
Mon 5/22 17:14:02.897 Event: 0xe
Mon 5/22 17:14:02.897 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:02.897 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:02.897 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:02.898 VF processing job null nPlayin=true
Mon 5/22 17:14:02.898 isRec=false rd=1798774 base=2998
Mon 5/22 17:14:02.898 VF thread is now waiting for 0:29:55.526
Mon 5/22 17:14:02.986 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:02.986 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:02.987 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:02.987 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:02.988 Event: 0x8065
Mon 5/22 17:14:02.988 VF processing job null nPlayin=true
Mon 5/22 17:14:02.989 isRec=false rd=1798774 base=3062
Mon 5/22 17:14:02.990 VF thread is now waiting for 0:29:55.461
Mon 5/22 17:14:02.996 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:02.996 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:02.997 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:02.997 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:02.997 Event: 0x8065
Mon 5/22 17:14:02.997 VF processing job null nPlayin=true
Mon 5/22 17:14:02.997 isRec=false rd=1798774 base=3070
Mon 5/22 17:14:02.998 VF thread is now waiting for 0:29:55.453
Mon 5/22 17:14:03.082 VMR9 rendering began VRAM free=353370112
Mon 5/22 17:14:03.311 AutoAspect: Setting Aspect Ratio to Source as Default aspect ratio for TV files
Mon 5/22 17:14:04.066 setUI(sage.bz@f60f20[MediaPlayer OSD]) histIdx=5 uiHistory=[sage.bz@12801c5[Main Menu], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@677ea2[Xtra: SageTV Recordings by malore], sage.bz@f60f20[MediaPlayer OSD]]
Mon 5/22 17:14:05.692 VF.submitJob(VFJob[TimeSet r=0.0 t=1146502827407 file=null ifn=null])
Mon 5/22 17:14:05.693 VF processing job VFJob[TimeSet r=0.0 t=1146502827407 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.693 VF processing on UI Thread VFJob[TimeSet r=0.0 t=1146502827407 file=null ifn=null]
Mon 5/22 17:14:05.694 VideoFrame.timeSelected(Mon 5/1 10:00:27.407, true) currFile=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]]
Mon 5/22 17:14:05.695 VideoFrame.timeSelected2(Mon 5/1 10:00:27.407, true) currFile=MediaFile[id=1928145 A[1882322,1882251,"I Dream of Jeannie",26046@0501.10:00,30] host=hammer encodedBy=Hauppauge WinTV PVR PCI II Capture #2 DVD Long Play E:\Sage\IDreamofJeannie-RideEmAstronaut-1882322-0.mpg, Seg0[Mon 5/1 10:00:00.013-Mon 5/1 10:30:00.010]] realDur=1798774
Mon 5/22 17:14:05.695 About to perform media time selection for 27375
Mon 5/22 17:14:05.800 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.802 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.803 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.803 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.804 Event: 0x8065
Mon 5/22 17:14:05.804 VF processing job null nPlayin=true
Mon 5/22 17:14:05.804 isRec=false rd=1798774 base=27375
Mon 5/22 17:14:05.805 VF thread is now waiting for 0:29:31.149
Mon 5/22 17:14:05.818 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.819 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.820 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.820 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.821 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.821 Event: 0x8065
Mon 5/22 17:14:05.821 Event: 0x8065
Mon 5/22 17:14:05.821 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.822 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.822 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.822 Event: 0x8065
Mon 5/22 17:14:05.823 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.823 VF processing job null nPlayin=true
Mon 5/22 17:14:05.824 isRec=false rd=1798774 base=27386
Mon 5/22 17:14:05.824 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.825 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.825 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.826 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.827 Event: 0x8065
Mon 5/22 17:14:05.827 Event: 0x8065
Mon 5/22 17:14:05.827 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.829 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.830 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.830 Event: 0x8065
Mon 5/22 17:14:05.830 Event: 0x8065
Mon 5/22 17:14:05.831 VF processing job null nPlayin=true
Mon 5/22 17:14:05.831 isRec=false rd=1798774 base=27390
Mon 5/22 17:14:05.832 VF thread is now waiting for 0:29:31.134
Mon 5/22 17:14:05.832 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.833 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.833 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.834 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.835 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.835 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.835 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.836 Event: 0x8065
Mon 5/22 17:14:05.836 Event: 0x8065
Mon 5/22 17:14:05.836 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.837 Event: 0x8065
Mon 5/22 17:14:05.837 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.837 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.838 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.839 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.839 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.840 Event: 0x8065
Mon 5/22 17:14:05.843 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.844 Event: 0x8065
Mon 5/22 17:14:05.844 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.845 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.845 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.845 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.846 Event: 0x8065
Mon 5/22 17:14:05.846 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.847 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.847 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.847 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.848 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.848 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.848 VF.submitJob(VFJob[DirectControl r=0.0 t=0 file=null ifn=null])
Mon 5/22 17:14:05.850 Event: 0x8065
Mon 5/22 17:14:05.850 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.851 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.853 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.854 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.854 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.856 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.856 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.858 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.858 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.859 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.860 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.860 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.861 VF processing job VFJob[DirectControl r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 5/22 17:14:05.862 VF processing on UI Thread VFJob[DirectControl r=0.0 t=0 file=null ifn=null]
Mon 5/22 17:14:05.862 DShowMediaPlayer is consuming the events...
Mon 5/22 17:14:05.863 VF processing job null nPlayin=true
Mon 5/22 17:14:05.863 isRec=false rd=1798774 base=27673
Mon 5/22 17:14:05.865 VF thread is now waiting for 0:29:30.850
Mon 5/22 17:14:07.140 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:12.141 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:17.142 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:22.146 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:27.147 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:32.149 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:37.150 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:42.151 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:47.153 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:52.154 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:14:57.155 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:15:02.156 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:15:07.158 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:15:12.159 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]
Mon 5/22 17:15:17.160 Received command of:NOOP from Socket[addr=localhost/127.0.0.1,port=42024,localport=2599]