New recordings won't play until older ones are played

  Thread Rating:
  • 0 Votes - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Post Reply
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #1
I user ServerWMC to watch WMC recordings on my TV via a small computer running OpenELEC.

Since I upgraded to the latest version of ServerWMC, I've noticed a problem with newly recorded shows simply will not play. This occurs if I leave my TV-based computer running all day. When I come back, all the newly recorded shows will appear in the Live TV list, but none will play.

If i play an older show, and then go and play the newer shows, they play just fine. And if I reboot my machine, all the shows play just fine. And if a new show is added to the list while I'm actively using the XBMC, it seems to play just fine as well. But, if a new show is added while the machine is idle (idle, but not sleeping), those shows will not play.

Here's what the log files show when I try to play a new show first:

09:54:43 T:140629886089024 NOTICE: DVDPlayer: Opening: smb://mediapc:mediapc@10.2.2.80/Recorded TV/Dinosaur Train_KOPBDT_2014_04_18_08_30_00.wtv
09:54:43 T:140629886089024 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
09:54:43 T:140629886089024 NOTICE: CXBMCRenderManager::ResetRenderBuffer - using 5 render buffers
09:54:43 T:140628784064256 NOTICE: Thread CDVDPlayer start, auto delete: false
09:54:43 T:140628784064256 NOTICE: Creating InputStream
09:54:43 T:140628784064256 ERROR: CDVDPlayer::OpenInputStream - error opening [smb://mediapc:mediapc@10.2.2.80/Recorded TV/Dinosaur Train_KOPBDT_2014_04_18_08_30_00.30_00.wtv

And if I play the same show after starting an older show, it works just fine:

Any thoughts? I initially suspected a permission issues, but I've verified that all permissions are set fine, and if there was a permissions issue, the older files shouldn't play either.
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #2
It looks like it can't find the file. Can you post a link to the serverwmc log too (when you get a failure)? Include the full log, not just a portion of it.

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
(This post was last modified: 2014-04-18 19:32 by krustyreturns.)
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #3
I agree that it cannot find the file, but when I go to watch an older show, it plays fine, and then then newer shows work as well.

My current log is dated from 2/20, which doesn't sound right either...

2014/02/20 16:18:16.968 ServerWMC started at 2/20/2014 4:18:16 PM
2014/02/20 16:18:16.968 Assembly version: 1.0.0.20, build: 1101
2014/02/20 16:18:16.968 Config file version: 32
2014/02/20 16:18:16.968 Click-once deployment: False
2014/02/20 16:18:16.968 OS: Windows 7 Service Pack 1 64-bit
2014/02/20 16:18:16.968 OS Version: 6.1.7601.65536
2014/02/20 16:18:18.325 Processor: Intel® Core™ i3 CPU 540 @ 3.07GHz
2014/02/20 16:18:18.325 Graphics: LogMeIn Mirror Driver
2014/02/20 16:18:18.325 Server MachineName: MEDIAPC
2014/02/20 16:18:18.435 RecService> Starting recording service...
2014/02/20 16:18:18.450 EPG> loading...
2014/02/20 16:18:18.450 EPG> 1. opening store2
2014/02/20 16:18:19.043 EPG> 1b. TV store opened
2014/02/20 16:18:19.043 EnumerateRecorders> Tuner Devices and TuningSpaces found:
2014/02/20 16:18:19.059 EnumerateRecorders> 0 Content Recorder HardwareBaseId:
2014/02/20 16:18:19.059 EnumerateRecorders> HardwareId: 9763d26c-99e3-4e74-9beb-be8ebdd59e88
2014/02/20 16:18:19.137 EnumerateRecorders> count: 0 Device name: Silicondust HDHomeRun Tuner 101ADFBB-0, TuningSpace: ATSC
2014/02/20 16:18:19.137 EnumerateRecorders> 1 Content Recorder HardwareBaseId:
2014/02/20 16:18:19.137 EnumerateRecorders> HardwareId: e7b88aed-3381-44fd-b547-b4a5c6921d58
2014/02/20 16:18:19.137 EnumerateRecorders> count: 0 Device name: Silicondust HDHomeRun Tuner 101ADFBB-1, TuningSpace: ATSC
2014/02/20 16:18:19.137 EnumerateRecorders> done
2014/02/20 16:18:19.152 GetLineUpsAndChannels> started
2014/02/20 16:18:20.665 GetLineUpsAndChannels> Total LineUps: 1, Total Channels to be exported: 32
2014/02/20 16:18:20.665 GetLineUpsAndChannels> Channels found in database: 55
2014/02/20 16:18:20.665 GetLineUpsAndChannels> Ignored channels> Blocked in WMC: 16, No Service: 0, No Space: 0, OutOfRange: 7
2014/02/20 16:18:20.665 GetLineUpsAndChannels> Protected Channels> Encrypted: 0, DRM: 0
2014/02/20 16:18:20.665 GetLineUpsAndChannels> Renamed CallSigns: 0, Renumbered Channels: 0
2014/02/20 16:18:20.665 GetLineUpsAndChannels> done
2014/02/20 16:18:20.665 EPG> loading done
2014/02/20 16:18:21.617 StartRecordingLibraryWatcher> recording library watcher started
2014/02/20 16:18:22.912 RecService> EventScheduler started
2014/02/20 16:18:22.912 RecService> priming tuners
2014/02/20 16:18:22.912 PrimeTuners> tuning space: ATSC
2014/02/20 16:18:22.912 SetChannel> Tuner: Silicondust HDHomeRun Tuner 101ADFBB-1 / e7b88aed-3381-44fd-b547-b4a5c6921d58
2014/02/20 16:18:22.912 SetChannel> > Digital: True
2014/02/20 16:18:22.912 SetChannel> > Encrypted: False
2014/02/20 16:18:22.927 SetChannel> > RecorderInfo found: True
2014/02/20 16:18:22.927 SetChannel > busy: False, client:
2014/02/20 16:18:22.927 SetChannel> > tuner is available (taking tuner from ) => stopping search
2014/02/20 16:18:22.927 SetChannel> Recorder Content Protection: PROT_COPY_FREE
2014/02/20 16:18:23.863 SetChannel> Recorder acquired: True
2014/02/20 16:18:23.863 SetChannel> TuneRequest set
2014/02/20 16:18:23.863 RecService> priming tuners - done
2014/02/20 16:18:23.879 LoadGenreDict> 'GenreDict.xml' loaded OK
2014/02/20 16:18:23.879 CacheChannelIcons> Channel icons processed: 0
2014/02/20 16:18:23.879 RecService> starting recording service - done
2014/02/20 16:18:23.879 Local 'Recorded tv' path: F:\Recorded TV\
2014/02/20 16:18:23.879 Format: NTFS
2014/02/20 16:18:23.879 Network 'Recorded tv' path: smb://mediapc:@10.2.2.134/Recorded TV
2014/02/20 16:18:23.879 Additional watched 'Recorded TV' folders:
2014/02/20 16:18:23.879 > C:\Users\Public\Recorded TV
2014/02/20 16:18:23.879 > \\sor\mediacenter
2014/02/20 16:18:23.879 > G:\Recorded TV
2014/02/20 16:18:23.879 > \\s4\video\Media Center TV
2014/02/20 16:18:24.228 SocketServer> starting up SocketServer
2014/02/20 16:18:24.228 SocketServer> permission to access sockets granted
2014/02/20 16:18:24.238 SocketServer> socket object created
2014/02/20 16:18:24.238 SocketServer> started on port: 9080
2014/02/20 16:18:24.238 MaintenanceTimer> callback at 4:18 PM
2014/02/20 16:18:24.258 MaintenanceTimer> callback - complete
2014/02/20 16:19:56.694 Session Ending: Logoff - closing...
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #4
I think its related to the fact that the recording finished during the current session. I did make some changes there in the last rev and I probably screwed something up.

The log you posted above is a from a very old rev of swmc. You should just be able to get the current or last run log from the debug tab, or go to:
%programdata\vdsoftware\serverwmc\

advocate99,, do you have swmc set to remux all recordings?

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
(This post was last modified: 2014-04-18 19:47 by krustyreturns.)
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #5
The recordings won't play issue definitely only affects recordings that finish while XBMC is running. I leave mine running all the time and have seen this same problem at two different locations

In order that I can do more diagnostics, can you tell me if these changes you think may be involved are in the Add-On software or the server software?


No, I do not have SWMC remux all recordings.



(2014-04-18 19:44)krustyreturns Wrote:  I think its related to the fact that the recording finished during the current session. I did make some changes there in the last rev and I probably screwed something up.

The log you posted above is a from a very old rev of swmc. You should just be able to get the current or last run log from the debug tab, or go to:
%programdata\vdsoftware\serverwmc\

advocate99,, do you have swmc set to remux all recordings?

The reason that the logfile is old is that, somehow, after I upgraded ServerWMC, it lost the ability to overwrite the configuration and logfiles. I've just deleted the entire directory and allowed ServerWMC to rebuild and now the logfiles appear up to date. I'm going to have to wait for the failure to occur again and then I'll have a current logfile for you.

I can also revert back to 0.1.93 and test that. Do you believe that the potential bug is in the add-on or the ServerWMC software?
(This post was last modified: 2014-04-18 19:57 by advocate99.)
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #6
The changes all have to do with when a recording is played (in swmc the command is 'OpenRecordingStream'). Can't you trigger it just by requesting a recording now, wait for it to finish, then play the file? Then post a link to the swmc log when it fails. I assume it has to do with changes I made due to the active recording fixes in the last rev, but looking over the code I can't find a problem. So I really need a log.

does the path you listed in the original post look correct for your setup?

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #7
My experience so far is that if a new recording is added while I'm actively using XBMC, the file plays fine. It appears that the bug only manifests itself if the machine is idle for some period of time before the new recording is added.

However, I just identified this bug last night and have been mostly screwing around with the permissions on the shared folder on the WMC box. I've got recordings set-up to go all day, so what I'm going to do is leave the machine for a few hours and then return and see if I can trigger the bug. Once I do, I'll post the ServerWMC log file.

I've seen then problem on three different machines running XBMC. Two are connected to one WMC, and the third machine that had the problem is connected to a different WMC machine (1,000 miles away).

I don't think I've ever seen this issue prior to updating to the latest version of ServerWMC, and so that, combined with the fact that you made some changes, it leading me to believe that there's a bug. Smile


(2014-04-18 20:00)krustyreturns Wrote:  The changes all have to do with when a recording is played (in swmc the command is 'OpenRecordingStream'). Can't you trigger it just by requesting a recording now, wait for it to finish, then play the file? Then post a link to the swmc log when it fails. I assume it has to do with changes I made due to the active recording fixes in the last rev, but looking over the code I can't find a problem. So I really need a log.

does the path you listed in the original post look correct for your setup?

Yes, the path looks correct. And when I go to play the file later (after playing an older file successfully), the file plays using that very same path as well.

smb://mediapc:mediapc@10.2.2.80/Recorded TV/Dinosaur Train_KOPBDT_2014_04_18_08_30_00.wtv

(2014-04-18 20:00)krustyreturns Wrote:  does the path you listed in the original post look correct for your setup?
(This post was last modified: 2014-04-18 20:07 by advocate99.)
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #8
I think its probably a bug too. Are you auto moving recordings, after they complete, to a different folder?

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #9
No, I am not auto moving recordings.

I replicated the problem yet again. Here's the ServerWMC Log:

2014/04/18 10:41:58.928 ServerWMC started at 4/18/2014 10:41:58 AM
2014/04/18 10:41:58.928 Assembly version: 1.0.0.28, build: 1134
2014/04/18 10:41:58.928 Config file version: 57
2014/04/18 10:41:58.938 Click-once deployment: False
2014/04/18 10:41:58.938 Server MachineName: WMC
2014/04/18 10:41:58.938 OS: Windows 7 Service Pack 1 64-bit
2014/04/18 10:41:58.938 OS Version: 6.1.7601.65536
2014/04/18 10:42:00.668 Processor: Intel® Core™ i3 CPU 540 @ 3.07GHz
2014/04/18 10:42:00.678 Graphics: LogMeIn Mirror Driver
2014/04/18 10:42:00.678 -----------------------------------------
2014/04/18 10:42:00.678 Non-default Config Settings -------------
2014/04/18 10:42:00.688 --- RecordingExternalActionList:
2014/04/18 10:42:00.688 RecordingState: HasOccurred, Program: c:\path\dummyprogram.bat, Arguments: /FileName="%FileName%" /Channel=%ChannelID% /Title="%Title%")
2014/04/18 10:42:00.688 --- ClientRestrictionList:
2014/04/18 10:42:00.688 Client: DummyClient, RestrictChannels: RestrictToGroups, RestrictRecordings: Unrestricted, Groups: DummyGroup1,DummyGroup2
2014/04/18 10:42:00.688 -----------------------------------------
2014/04/18 10:42:00.698 MainWindow> Starting InitializeWorker
2014/04/18 10:42:00.718 RecService> Starting ------------------
2014/04/18 12:10:55.993 Finished request GetRecordings in 1.31s
(This post was last modified: 2014-04-18 22:51 by krustyreturns.)
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #10
Here's the XBMC Log with a failure:

12:20:20 T:140259019806528 NOTICE: DVDPlayer: Opening: smb://mediapc:mediapc@10.2.2.80/Recorded TV/Arthur_KOPBDT_2014_04_18_11_30_00.wtv
12:20:20 T:140259019806528 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
12:20:20 T:140259019806528 NOTICE: CXBMCRenderManager::ResetRenderBuffer - using 5 render buffers
12:20:20 T:140257785407232 NOTICE: Thread CDVDPlayer start, auto delete: false
12:20:20 T:140257785407232 NOTICE: Creating InputStream
12:20:20 T:140257785407232 ERROR: CDVDPlayer::OpenInputStream - error opening [smb://mediapc:mediapc@10.2.2.80/Recorded TV/Arthur_KOPBDT_2014_04_18_11_30_00.wtv]
12:20:20 T:140257785407232 NOTICE: CDVDPlayer::OnExit()
12:20:20 T:140257785407232 NOTICE: CDVDPlayer::OnExit() deleting input stream
12:20:20 T:140259019806528 NOTICE: CDVDPlayer::CloseFile()
12:20:20 T:140259019806528 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
12:20:20 T:140259019806528 NOTICE: DVDPlayer: waiting for threads to exit
12:20:20 T:140259019806528 NOTICE: DVDPlayer: finished waiting

And here's a success on the same file after I played an older file (20 seconds later):

12:20:44 T:140259019806528 NOTICE: DVDPlayer: finished waiting
12:20:47 T:140257794193152 NOTICE: Thread BackgroundLoader start, auto delete: false
12:20:48 T:140259019806528 NOTICE: DVDPlayer: Opening: smb://mediapc:mediapc@10.2.2.80/Recorded TV/Arthur_KOPBDT_2014_04_18_11_30_00.wtv
12:20:48 T:140259019806528 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
12:20:48 T:140259019806528 NOTICE: CXBMCRenderManager::ResetRenderBuffer - using 5 render buffers
12:20:48 T:140257794193152 NOTICE: Thread CDVDPlayer start, auto delete: false
12:20:48 T:140257794193152 NOTICE: Creating InputStream
12:20:48 T:140257794193152 NOTICE: Creating Demuxer
12:20:48 T:140257794193152 NOTICE: Opening video stream: 2 source: 256
12:20:48 T:140257794193152 NOTICE: Creating video codec with codec id: 2
12:20:48 T:140257794193152 NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: MPEG-2 video
12:20:48 T:140257794193152 NOTICE: Creating video thread
12:20:48 T:140258880255744 NOTICE: Thread CDVDPlayerVideo start, auto delete: false
12:20:48 T:140258880255744 NOTICE: running thread: video_thread
12:20:48 T:140257794193152 NOTICE: Opening audio stream: 0 source: 256
12:20:48 T:140257794193152 NOTICE: Finding audio codec for: 86019
12:20:48 T:140257794193152 NOTICE: Creating audio thread
12:20:48 T:140258211489536 NOTICE: Thread CDVDPlayerAudio start, auto delete: false
12:20:48 T:140258211489536 NOTICE: running thread: CDVDPlayerAudio::Process()
12:20:48 T:140257794193152 NOTICE: Opening teletext stream: 3 source: 256
12:20:48 T:140257794193152 NOTICE: Creating teletext data thread
12:20:48 T:140257777014528 NOTICE: Thread CDVDTeletextData start, auto delete: false
12:20:48 T:140257777014528 NOTICE: running thread: CDVDTeletextData
12:20:48 T:140258211489536 NOTICE: Creating audio stream (codec id: 86019, channels: 2, sample rate: 48000, pass-through)
12:20:48 T:140257768621824 NOTICE: Thread VAAPI VPP Thread start, auto delete: false
12:20:48 T:140258880255744 NOTICE: fps: 59.750000, pwidth: 1920, pheight: 1080, dwidth: 1920, dheight: 1080
12:20:48 T:140258880255744 WARNING: CRenderManager::Configure - timeout waiting for previous frame
12:20:48 T:140258880255744 NOTICE: Display resolution DESKTOP : 1920x1080 @ 60.00 - Full Screen (16)
12:20:48 T:140258880255744 NOTICE: CXBMCRenderManager::ResetRenderBuffer - using 2 render buffers
12:20:48 T:140259019806528 NOTICE: Using GL_TEXTURE_2D
12:20:48 T:140259019806528 NOTICE: GL: Using VAAPI render method
12:20:48 T:140259019806528 NOTICE: GL: NPOT texture support detected
12:20:48 T:140259019806528 NOTICE: GL: Using GL_ARB_pixel_buffer_object
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #11
FYI: you should post the logs on pastebin.com, and post a link to them here. The serverlog didn't have the 'openrecordingstream ' command that the xbmc log says it sent. But the serverlog ends at 12:10, and xbmc sent the command at 12:20, possible the server log got truncated in pasting it directly into the forum. Either post the entire serverlog on pastebin.com or check it yourself for a openrecordingstream command at around 12:20.

If the log isn't truncated, is it possible the server is asleep?

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #12
My ServerWMC logs never show openrecordingstream, even when I am able to watch a recorded show. Until now, I always assumed that XBMC handled the streaming directly from the shared folder.

Server is definitely NOT sleeping...


(2014-04-18 23:01)krustyreturns Wrote:  FYI: you should post the logs on pastebin.com, and post a link to them here. The serverlog didn't have the 'openrecordingstream ' command that the xbmc log says it sent. But the serverlog ends at 12:10, and xbmc sent the command at 12:20, possible the server log got truncated in pasting it directly into the forum. Either post the entire serverlog on pastebin.com or check it yourself for a openrecordingstream command at around 12:20.

If the log isn't truncated, is it possible the server is asleep?

My ServerWMC logs never show openrecordingstream, even when I am able to watch a recorded show. Until now, I always assumed that XBMC handled the streaming directly from the shared folder.

Server is definitely NOT sleeping...


(2014-04-18 23:01)krustyreturns Wrote:  FYI: you should post the logs on pastebin.com, and post a link to them here. The serverlog didn't have the 'openrecordingstream ' command that the xbmc log says it sent. But the serverlog ends at 12:10, and xbmc sent the command at 12:20, possible the server log got truncated in pasting it directly into the forum. Either post the entire serverlog on pastebin.com or check it yourself for a openrecordingstream command at around 12:20.

If the log isn't truncated, is it possible the server is asleep?
(This post was last modified: 2014-04-19 00:25 by advocate99.)
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #13
Well, OpenRecordingStream gets called when you try to play an in-progress recording, xbmc calls it because serverwmc doesn't provide the file path to in-progress wtv files. Serverwmc uses the OpenRecordingStream function to start the remux and gives xbmc the path to the output ts file.

So since OpenRecordingStream is not getting called when this bug occurs, it must be because you are asking it to play AFTER serverwmc has noticed that the program is done recording and sent the file path to the finished wtv file to xbmc. That also agrees with the error that xbmc is displaying, because it is showing an error finding a wtv file (as opposed to a ts file). So I don't get why it is failing if the file path is correct for your setup. Is the path that xbmc is reporting in the error correct?

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
(This post was last modified: 2014-04-19 01:35 by krustyreturns.)
find quote
advocate99 Offline
Moderator
Posts: 223
Joined: Jan 2014
Reputation: 10
Post: #14
Yes, the path is correct. I'm attempting to play a newly recorded program is that is finished recording..

(2014-04-19 01:33)krustyreturns Wrote:  Well, OpenRecordingStream gets called when you try to play an in-progress recording, xbmc calls it because serverwmc doesn't provide the file path to in-progress wtv files. Serverwmc uses the OpenRecordingStream function to start the remux and gives xbmc the path to the output ts file.

So since OpenRecordingStream is not getting called when this bug occurs, it must be because you are asking it to play AFTER serverwmc has noticed that the program is done recording and sent the file path to the finished wtv file to xbmc. That also agrees with the error that xbmc is displaying, because it is showing an error finding a wtv file (as opposed to a ts file). So I don't get why it is failing if the file path is correct for your setup. Is the path that xbmc is reporting in the error correct?
find quote
krustyreturns Offline
Moderator
Posts: 1,417
Joined: Aug 2012
Reputation: 47
Location: Springfield Heights, CA
Post: #15
This is a weird one for sure. Btw I have tried to reproduce here and can't. Next time you have time to work on this, in the config.xml file set
Debug_OutputHeaders to true, save and reload, then try to reproduce the problem and post the serverlog to pastebin. The server log will grow quickly like this, so don't leave it on when we are done.

Windows Media Center PVR addon (pvr.wmc) and server backend (ServerWMC)
http://bit.ly/ServerWMC
find quote
Post Reply