andy vt's tools & blog

Hey Andy,

DVRMS Toolbox does not seem to realize that the xml file for commercials is updating as the show records.  It only recognizes the commercials that were already found when I start watching the program.  I remember this as being a problem in the XP version, and you were able to do something to fix it.  Any ideas?

I should add that if I press stop and then play, everything updates and commercial skipping works again.

Did you get a chance to check it out?

Can you enable addin debug logging and run through the scenario?  Just change the xml file manually to test.

Everything looks OK at first glance.

 I tried running through the following steps to enable debug logging, but I had a couple problems.  Niether of these are in HKLM for me.  I have the DVRMSToolbox and Dtb entries in current users.  There is no specific folder within either called Commercial Skip.  I added these keys in the location  I thought was closest to below, but I am not getting any logs in PUBLIC DvrmsToolbox.  Are these key locations out of date?

Run regedt32 in an escalated process to have ehmsas.exe write a log file add HKLM\Software\DvrmsToolbox, DebugMceState = 1 (DWORD) to have the addin write a log file add HKLM\Software\DvrmsToolbox\CommercialSkip, Debug = 1 (DWORD).  Then either reboot or kill ehmsas.exe and ehshell.exe.  Logfiles for ehmsas.exe and ehexthost.exe (the addin hosting process) will be written in %PUBLIC%\DvrmsToolbox.

The debug keys are in HKLM (I should really add them to the settings tool), you only need the CommercialSkip, Debug one since we only need to figure out why the addin (ehexthost_###.log) isn't detecting a new xml file.

It was right around 4:27 when I was told cannot skip past the end of the show.  I then hit stop and play and the skip happened immediately.

------------------------------------------------------------------------
1/22/2010 4:10:02 PM : Initialize Registry Settings, DTBAddin Version 1.0.0.4
CurrentAtscZoom = One
CurrentTvZoom = One
IsRegistered = False
NumberOfProcessors = 4
AutoReloadSettings = True
WriteOnMceStateChangeEvents = False
SkipBoxMinMinutes = 0
SkipDisplayType = Classic
SkipMaxMinutes = 65535
AutoSkip = True
WriteEvents = True
PromptScan = Prompt
KeyHandleDisableTime = 30
DisableAutoSkipOnBack = False
DisableKey = D1
ForwardKey = Right
BackKey = Left
SkipOnKey = Down
SkipOffKey = Down
CCToggle = D2
KeepDisplayActive = False
SuppressNotFound = False
Debug = True
TerminateAddin = D3
HandleKeys = True
SkipCommericals = True
TrackDvds = False
TrackDvdPerUser = False
BookmarkPath = C:\Users\Public\DvrmsToolbox\VideoBookmark
ReuseInterval = 30
DebugFilePath =
AllowedVariance = 10
WolMac = System.String[
WakeExperience = System.String[
ReprocessShow = D4
BookmarkResponseTimeout = 60
ToggleZoom = D5
ATSC169 = One
ATSC43 = Four
TV169 = One
TV43 = Four
AutoZoom = False
ProcessProfile =
TreatAsTv = False
UseGraphForDetection = False
ForwardOnly = False
ProppageNag = True
SupressSkipDialog = False

1/22/2010 4:11:44 PM : PollCurrentPosition: current = 59.81, noskip = 0, isPlaying = True
1/22/2010 4:11:44 PM : File is watched type
1/22/2010 4:26:44 PM : autoskip = True, lastposition = 1367.71, tracktime = 1367
1/22/2010 4:26:44 PM : PollCurrentPosition: current = 1368.25, noskip = 0, isPlaying = True
1/22/2010 4:26:44 PM : File is watched type
1/22/2010 4:26:44 PM : autoskip = True, lastposition = 1368.25, tracktime = 1368
1/22/2010 4:26:44 PM : PollCurrentPosition: current = 1368.69, noskip = 0, isPlaying = True
1/22/2010 4:26:45 PM : File is watched type
1/22/2010 4:26:45 PM : autoskip = True, lastposition = 1368.69, tracktime = 1369
1/22/2010 4:26:45 PM : PollCurrentPosition: current = 1369.68, noskip = 0, isPlaying = True
1/22/2010 4:26:46 PM : File is watched type
1/22/2010 4:26:46 PM : autoskip = True, lastposition = 1369.68, tracktime = 1369
1/22/2010 4:26:46 PM : PollCurrentPosition: current = 1370.22, noskip = 0, isPlaying = True
1/22/2010 4:26:46 PM : File is watched type
1/22/2010 4:26:46 PM : autoskip = True, lastposition = 1370.22, tracktime = 1370
1/22/2010 4:26:46 PM : PollCurrentPosition: current = 1370.77, noskip = 0, isPlaying = True
1/22/2010 4:26:47 PM : File is watched type
1/22/2010 4:26:47 PM : autoskip = True, lastposition = 1370.77, tracktime = 1370
1/22/2010 4:26:47 PM : PollCurrentPosition: current = 1371.31, noskip = 0, isPlaying = True
1/22/2010 4:26:47 PM : File is watched type
1/22/2010 4:26:47 PM : autoskip = True, lastposition = 1371.31, tracktime = 1371
1/22/2010 4:26:47 PM : PollCurrentPosition: current = 1371.75, noskip = 0, isPlaying = True
1/22/2010 4:26:48 PM : File is watched type
1/22/2010 4:26:48 PM : autoskip = True, lastposition = 1371.75, tracktime = 1371
1/22/2010 4:26:48 PM : PollCurrentPosition: current = 1372.3, noskip = 0, isPlaying = True
1/22/2010 4:26:48 PM : File is watched type
1/22/2010 4:26:48 PM : autoskip = True, lastposition = 1372.3, tracktime = 1373
1/22/2010 4:26:48 PM : PollCurrentPosition: current = 1372.73, noskip = 0, isPlaying = True
1/22/2010 4:26:49 PM : File is watched type
1/22/2010 4:26:49 PM : autoskip = True, lastposition = 1372.73, tracktime = 1373
1/22/2010 4:26:49 PM : PollCurrentPosition: current = 1373.28, noskip = 0, isPlaying = True
1/22/2010 4:26:49 PM : File is watched type
1/22/2010 4:26:49 PM : autoskip = True, lastposition = 1373.28, tracktime = 1374
1/22/2010 4:26:49 PM : PollCurrentPosition: current = 1373.82, noskip = 0, isPlaying = True
1/22/2010 4:26:50 PM : File is watched type
1/22/2010 4:26:50 PM : autoskip = True, lastposition = 1373.82, tracktime = 1374
1/22/2010 4:26:50 PM : PollCurrentPosition: current = 1374.8, noskip = 0, isPlaying = True
1/22/2010 4:26:51 PM : File is watched type
1/22/2010 4:26:51 PM : autoskip = True, lastposition = 1374.8, tracktime = 1376
1/22/2010 4:26:51 PM : PollCurrentPosition: current = 1375.79, noskip = 0, isPlaying = True
1/22/2010 4:26:52 PM : File is watched type
1/22/2010 4:26:52 PM : autoskip = True, lastposition = 1375.79, tracktime = 1376
1/22/2010 4:26:52 PM : PollCurrentPosition: current = 1376.33, noskip = 0, isPlaying = True
1/22/2010 4:26:52 PM : File is watched type
1/22/2010 4:26:52 PM : autoskip = True, lastposition = 1376.33, tracktime = 1377
1/22/2010 4:26:52 PM : PollCurrentPosition: current = 1376.88, noskip = 0, isPlaying = True
1/22/2010 4:26:53 PM : File is watched type
1/22/2010 4:26:53 PM : autoskip = True, lastposition = 1376.88, tracktime = 1377
1/22/2010 4:26:53 PM : PollCurrentPosition: current = 1377.32, noskip = 0, isPlaying = True
1/22/2010 4:26:53 PM : File is watched type
1/22/2010 4:26:53 PM : autoskip = True, lastposition = 1377.32, tracktime = 1378
1/22/2010 4:26:53 PM : PollCurrentPosition: current = 1377.86, noskip = 0, isPlaying = True
1/22/2010 4:26:54 PM : File is watched type
1/22/2010 4:26:54 PM : autoskip = True, lastposition = 1377.86, tracktime = 1378
1/22/2010 4:26:54 PM : PollCurrentPosition: current = 1378.41, noskip = 0, isPlaying = True
1/22/2010 4:26:54 PM : File is watched type
1/22/2010 4:26:54 PM : autoskip = True, lastposition = 1378.41, tracktime = 1379
1/22/2010 4:26:54 PM : PollCurrentPosition: current = 1378.84, noskip = 0, isPlaying = True
1/22/2010 4:26:55 PM : File is watched type
1/22/2010 4:26:55 PM : autoskip = True, lastposition = 1378.84, tracktime = 1379
1/22/2010 4:26:55 PM : PollCurrentPosition: current = 1379.39, noskip = 0, isPlaying = True
1/22/2010 4:26:56 PM : File is watched type
1/22/2010 4:26:56 PM : autoskip = True, lastposition = 1379.39, tracktime = 1380
1/22/2010 4:26:56 PM : PollCurrentPosition: current = 1379.93, noskip = 0, isPlaying = True
1/22/2010 4:26:56 PM : File is watched type
1/22/2010 4:26:56 PM : autoskip = True, lastposition = 1379.93, tracktime = 1380
1/22/2010 4:26:56 PM : PollCurrentPosition: current = 1380.37, noskip = 0, isPlaying = True
1/22/2010 4:26:57 PM : File is watched type
1/22/2010 4:26:57 PM : autoskip = True, lastposition = 1380.37, tracktime = 1381
1/22/2010 4:26:57 PM : PollCurrentPosition: current = 1380.92, noskip = 0, isPlaying = True
1/22/2010 4:26:57 PM : File is watched type
1/22/2010 4:26:57 PM : autoskip = True, lastposition = 1380.92, tracktime = 1381
1/22/2010 4:26:57 PM : PollCurrentPosition: current = 1381.35, noskip = 0, isPlaying = True
1/22/2010 4:26:57 PM : File is watched type
1/22/2010 4:26:57 PM : autoskip = True, lastposition = 1381.35, tracktime = 1382
1/22/2010 4:26:58 PM : PollCurrentPosition: current = 1381.9, noskip = 0, isPlaying = True
1/22/2010 4:26:58 PM : File is watched type
1/22/2010 4:26:58 PM : autoskip = True, lastposition = 1381.9, tracktime = 1382
1/22/2010 4:26:58 PM : PollCurrentPosition: current = 1382.51, noskip = 0, isPlaying = True
1/22/2010 4:26:59 PM : File is watched type
1/22/2010 4:26:59 PM : autoskip = True, lastposition = 1382.51, tracktime = 1383
1/22/2010 4:26:59 PM : PollCurrentPosition: current = 1382.6, noskip = 0, isPlaying = True
1/22/2010 4:27:00 PM : File is watched type
1/22/2010 4:27:00 PM : Start polling
1/22/2010 4:27:00 PM : In Start keysHooked = True
1/22/2010 4:27:00 PM : filepath = C:\Users\Public\Recorded TV\Oprah Winfrey_WISCDT_2010_01_22_16_00_25.wtv
1/22/2010 4:27:00 PM : CurrentMediaInfo=C:\Users\Public\Recorded TV\Oprah Winfrey_WISCDT_2010_01_22_16_00_25.wtv
1/22/2010 4:27:00 PM : FileName = C:\Users\Public\Recorded TV\Oprah Winfrey_WISCDT_2010_01_22_16_00_25.wtv
1/22/2010 4:27:00 PM : Started: uniqueid = 152a176d-3cad-4964-a485-a4c85c8024e0, reportedShowLength = 1590
1/22/2010 4:27:00 PM : File is watched type
1/22/2010 4:27:00 PM : autoskip = True, lastposition = 1382.6, tracktime = 1383
1/22/2010 4:27:00 PM : PollCurrentPosition: current = 1383.35, noskip = 0, isPlaying = True
1/22/2010 4:27:01 PM : File is watched type
1/22/2010 4:27:01 PM : autoskip = True, lastposition = 1383.35, tracktime = 1383
1/22/2010 4:27:01 PM : PollCurrentPosition: current = 1383.79, noskip = 0, isPlaying = True
1/22/2010 4:27:01 PM : File is watched type
1/22/2010 4:27:01 PM : autoskip = True, lastposition = 1383.79, tracktime = 1383
1/22/2010 4:27:01 PM : PollCurrentPosition: current = 1384.34, noskip = 0, isPlaying = True
1/22/2010 4:27:02 PM : File is watched type
1/22/2010 4:27:02 PM : autoskip = True, lastposition = 1384.34, tracktime = 1384
1/22/2010 4:27:02 PM : PollCurrentPosition: current = 1384.77, noskip = 0, isPlaying = True
1/22/2010 4:27:02 PM : File is watched type
1/22/2010 4:27:02 PM : autoskip = True, lastposition = 1384.77, tracktime = 1384
1/22/2010 4:27:02 PM : PollCurrentPosition: current = 1385.32, noskip = 0, isPlaying = True
1/22/2010 4:27:03 PM : File is watched type
1/22/2010 4:27:03 PM : autoskip = True, lastposition = 1385.32, tracktime = 1385
1/22/2010 4:27:03 PM : PollCurrentPosition: current = 1385.86, noskip = 0, isPlaying = True
1/22/2010 4:27:03 PM : File is watched type
1/22/2010 4:27:03 PM : autoskip = True, lastposition = 1385.86, tracktime = 1385
1/22/2010 4:27:03 PM : PollCurrentPosition: current = 1386.3, noskip = 0, isPlaying = True
1/22/2010 4:27:04 PM : File is watched type
1/22/2010 4:27:04 PM : autoskip = True, lastposition = 1386.3, tracktime = 1386
1/22/2010 4:27:04 PM : PollCurrentPosition: current = 1386.84, noskip = 0, isPlaying = True
1/22/2010 4:27:04 PM : File is watched type
1/22/2010 4:27:04 PM : autoskip = True, lastposition = 1386.84, tracktime = 1386
1/22/2010 4:27:04 PM : PollCurrentPosition: current = 1387.39, noskip = 0, isPlaying = True
1/22/2010 4:27:05 PM : File is watched type
1/22/2010 4:27:05 PM : autoskip = True, lastposition = 1387.39, tracktime = 1388
1/22/2010 4:27:05 PM : PollCurrentPosition: current = 1387.83, noskip = 0, isPlaying = True
1/22/2010 4:27:05 PM : File is watched type
1/22/2010 4:27:05 PM : autoskip = True, lastposition = 1387.83, tracktime = 1388
1/22/2010 4:27:05 PM : PollCurrentPosition: current = 1388.37, noskip = 0, isPlaying = True
1/22/2010 4:27:06 PM : File is watched type
1/22/2010 4:27:06 PM : autoskip = True, lastposition = 1388.37, tracktime = 1388
1/22/2010 4:27:06 PM : PollCurrentPosition: current = 1388.92, noskip = 0, isPlaying = True
1/22/2010 4:27:06 PM : File is watched type
1/22/2010 4:27:06 PM : autoskip = True, lastposition = 1388.92, tracktime = 1388
1/22/2010 4:27:06 PM : PollCurrentPosition: current = 1389.36, noskip = 0, isPlaying = True
1/22/2010 4:27:07 PM : File is watched type
1/22/2010 4:27:07 PM : autoskip = True, lastposition = 1389.36, tracktime = 1389
1/22/2010 4:27:07 PM : PollCurrentPosition: current = 1389.9, noskip = 0, isPlaying = True
1/22/2010 4:27:07 PM : File is watched type
1/22/2010 4:27:07 PM : autoskip = True, lastposition = 1389.9, tracktime = 1389
1/22/2010 4:27:07 PM : PollCurrentPosition: current = 1390.45, noskip = 0, isPlaying = True
1/22/2010 4:27:08 PM : File is watched type
1/22/2010 4:27:08 PM : autoskip = True, lastposition = 1390.45, tracktime = 1390
1/22/2010 4:27:08 PM : PollCurrentPosition: current = 1390.89, noskip = 0, isPlaying = True
1/22/2010 4:27:08 PM : File is watched type
1/22/2010 4:27:08 PM : autoskip = True, lastposition = 1390.89, tracktime = 1390
1/22/2010 4:27:08 PM : PollCurrentPosition: current = 1391.43, noskip = 0, isPlaying = True
1/22/2010 4:27:09 PM : File is watched type
1/22/2010 4:27:09 PM : autoskip = True, lastposition = 1391.43, tracktime = 1392
1/22/2010 4:27:09 PM : PollCurrentPosition: current = 1391.98, noskip = 0, isPlaying = True
1/22/2010 4:27:09 PM : File is watched type
1/22/2010 4:27:09 PM : autoskip = True, lastposition = 1391.98, tracktime = 1392
1/22/2010 4:27:09 PM : PollCurrentPosition: current = 1392.42, noskip = 0, isPlaying = True
1/22/2010 4:27:10 PM : File is watched type
1/22/2010 4:27:10 PM : autoskip = True, lastposition = 1392.42, tracktime = 1393
1/22/2010 4:27:10 PM : PollCurrentPosition: current = 1392.96, noskip = 0, isPlaying = True
1/22/2010 4:27:10 PM : File is watched type
1/22/2010 4:27:10 PM : autoskip = True, lastposition = 1392.96, tracktime = 1393
1/22/2010 4:27:10 PM : PollCurrentPosition: current = 1393.5, noskip = 0, isPlaying = True
1/22/2010 4:27:11 PM : File is watched type
1/22/2010 4:27:11 PM : autoskip = True, lastposition = 1393.5, tracktime = 1394
1/22/2010 4:27:11 PM : PollCurrentPosition: current = 1393.94, noskip = 0, isPlaying = True
1/22/2010 4:27:12 PM : File is watched type
1/22/2010 4:27:12 PM : autoskip = True, lastposition = 1393.94, tracktime = 1395
1/22/2010 4:27:12 PM : PollCurrentPosition: current = 1394.93, noskip = 0, isPlaying = True
1/22/2010 4:27:13 PM : File is watched type
1/22/2010 4:27:13 PM : autoskip = True, lastposition = 1394.93, tracktime = 1396
1/22/2010 4:27:13 PM : PollCurrentPosition: current = 1396.02, noskip = 0, isPlaying = True
1/22/2010 4:27:13 PM : File is watched type
1/22/2010 4:27:13 PM : autoskip = True, lastposition = 1396.02, tracktime = 1396
1/22/2010 4:27:13 PM : PollCurrentPosition: current = 1396.45, noskip = 0, isPlaying = True
1/22/2010 4:27:14 PM : File is watched type
1/22/2010 4:27:14 PM : autoskip = True, lastposition = 1396.45, tracktime = 1397
1/22/2010 4:27:14 PM : PollCurrentPosition: current = 1397, noskip = 0, isPlaying = True
1/22/2010 4:27:14 PM : File is watched type
1/22/2010 4:27:14 PM : autoskip = True, lastposition = 1397, tracktime = 1397
1/22/2010 4:27:14 PM : PollCurrentPosition: current = 1397.55, noskip = 0, isPlaying = True
1/22/2010 4:27:15 PM : File is watched type
1/22/2010 4:27:15 PM : autoskip = True, lastposition = 1397.55, tracktime = 1398
1/22/2010 4:27:15 PM : PollCurrentPosition: current = 1397.98, noskip = 0, isPlaying = True
1/22/2010 4:27:16 PM : File is watched type
1/22/2010 4:27:16 PM : autoskip = True, lastposition = 1397.98, tracktime = 1399
1/22/2010 4:27:16 PM : PollCurrentPosition: current = 1399.07, noskip = 0, isPlaying = True
1/22/2010 4:27:16 PM : File is watched type
1/22/2010 4:27:16 PM : autoskip = True, lastposition = 1399.07, tracktime = 1399
1/22/2010 4:27:16 PM : PollCurrentPosition: current = 1399.51, noskip = 0, isPlaying = True
1/22/2010 4:27:17 PM : File is watched type
1/22/2010 4:27:17 PM : autoskip = True, lastposition = 1399.51, tracktime = 1400
1/22/2010 4:27:17 PM : PollCurrentPosition: current = 1400.06, noskip = 0, isPlaying = True

the 1.0.0.5 addin has addtional logging.

Also, can you attach the log next time:)

New log attached.  8:57 PM

Sorry, it was for Biggest Loser.  2/2/10 around 8:47.  I didn't realize 2/1/10 was in there too.

Everything looks good with that file as well.

Is it possible that you're overrunning SAV1's progress through the file (I see at least 2 simultaneous scans going on)?

Hmmm...very weird.  I know I am not overrunning because my fix is to stop and restart and the skip will happen immediately.

OK, try this one.  It wil dump the contents of the xml doc to the log so I can compare it.