Skip to main content

Clarification on tuning events

11 replies [Last post]
stopiwalla
Offline
Joined: 2010-05-25
Points: 0

I am noticing unusual behavior such that the stack times-out into alternate service content (drip feed) mode even after an apparent successful tune/decode recovery.
Here is what I am seeing:
1) Start WatchTv and it comes up fine on the 1st channel and decodes it fine.
2) According to one of the ATP tests, we need to physically disconnect the cable feed. We notice that the AV freezes. In about 10 secs, we put the feed back, but the AV does not resume.
3) We perform a channel change immediately after this, and the platform tuning takes palce fine with the AV decoding just ok.
4) After few more seconds on this decoding channel, the stack pushes the box into the alternate content (drip feed) mode - this should have never occured because we were presenting the AV just fine on this channel!
My questions are as follows:
1) Is the underlying RI implementation responsible for a tune-retry upon a signal loss (unlocked tuner condition)? Or is the stack responsible for it?
2) What is the sequence of events that the underlying RI platform implemetation needs to post to the stack when:
a) A successful tune takes place?
b) When the tuner is unlocked due to a signal loss?
c) When the tuner is unlocked due to new tune request?
3) What is the sequence of events/messages that the underlying RI platform implementation needs to post to the stack on a successful AV decoding session when:
a) The AV presentation starts?
b) The AV presentation stops on its own (due to stream deocding issues, etc)?
c) The AV presentation stops due to a channel change?
4) Is there an updated flow-diagram of these tuning & presenting sequences that can help clarify these scenarios?

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
stopiwalla
Offline
Joined: 2010-05-25
Points: 0

Refering to my original questions once again, i
In 2(b), after a TUNE_UNSYNC is sent out, when the underlying implementation attempts to retune/lock the tuner again, does t need to keep on sending out MPE_TUNER_STARTED and MPE_TUNER_UNSYNC until it obtains MPE_TUNER_SYNC?

In 3(b), if we notify MPE_FAILURE_UNKNOWN (or something):
1) Do we need to stop the respective decoding session internally?
2) When the tuner lock is received, do we restart the decoding session?
3) When the tuner lock is received, do we send out the MPE_CONTENT_PRESENTING once again for the respective decoding session?

scottdeboy
Offline
Joined: 2009-02-02
Points: 0

After TUNE_UNSYNC is sent, the platform should send TUNE_SYNC when tuner lock is reacquired - the platform does not need to repeatedly send events to the stack until tuner lock is re-acquired. TUNE_STARTED should only be sent in response to a tune request.
1. If FAILURE_UNKNOWN is received by the stack, the stack will stop the decode session and terminate the presentation. The stack will notify the apps via a PresentationTerminatedEvent and ControllerClosedEvent.
2. When TUNE_SYNC is received by the stack, the stack will attempt to re-initiate the decode session (the platform should not automatically restart the decode session)
3. MPE_CONTENT_PRESENTING should only be sent in response to a call to mpe_mediaDecode. The stack will call mpe_mediaDecode in response to receiving the TUNE_SYNC indication.

scottdeboy
Offline
Joined: 2009-02-02
Points: 0

When tuner sync state changes, the platform notifies the stack via MPE_TUNE_SYNC and MPE_TUNE_UNSYNC events sent to the event queue provided in the call to mpe_mediaTune. A platform should signal MPE_TUNE_UNSYNC some short amount of time after the cable is unplugged and MPE_TUNE_SYNC some amount of time after the cable is plugged back in. The stack will receive the events and attempt presentation or switch to alternative content as appropriate.

The stack will automatically switch to AlternativeContent if a TUNE_SYNC notification is -not- received before the timeout threshold after a call to mpe_mediaTune. The timeout is a configurable property (OCAP.networkinterface.timeout), which is set to 30 seconds in base.properties and should be configured according to your platform's worst-case tune delay - which is hopefully lower.

See mpeos_media.h for more information on the valid events and arguments to mpe_mediaDecode and mpe_mediaTune.

1. The stack waits for TUNE_SYNC and TUNE_UNSYNC notifications and attempts to present the service when in alternative content and a TUNE_SYNC notification is received. The platform must send these events as described above.

2a: MPE_TUNE_STARTED followed by MPE_TUNE_SYNC
2b: MPE_TUNE_UNSYNC
2c: a sync event is not necessary but the request to tune needs to result in a MPE_TUNE_STARTED event

3a: When a decode session is successfully started, the platform notifies the stack of the change via an MPE_CONTENT_PRESENTING event sent to the event queue provided in the call to mpe_mediaDecode.
3b: one of the other presentation failure events defined in mpeos_media.h (MPE_FAILURE_UNKNOWN)
3c: The stack will stop the decode session prior to issuing the new tune - no event is needed

4. There are diagrams which may be helpful, but may be somewhat out of date. See https://community.cablelabs.com/svn/OCAPRI/trunk/ri/RI_Stack/docs/design. The DVR folder contains a number of diagrams that may provide you with useful information - for example, https://community.cablelabs.com/svn/OCAPRI/trunk/ri/RI_Stack/docs/design...

Which release of the RI are you using? If necessary, feel free to provide an RI log demonstrating the issue with Java DEBUG verbosity enabled.

Thanks
Scott

stopiwalla
Offline
Joined: 2010-05-25
Points: 0

The following problem only occurs with 2 TUNERS defined in the mpeenv.ini. There is no request for tuning from this channel change from the stack. Can you please help me point in the right direction why this is so?
-------------------------------
~ # 000101-01:18:57 >>> WatchTV: KEY: VK_CHANNEL_UP
000101-01:18:57 4697484 [AWT-EventQueue-0] INFO selection.ServiceContextImpl - stop: (id ae71a8b6, PRESENTING, delegate: DVRBroadcastServiceContextDelegate - service: org.cablelabs.impl.serv)
000101-01:18:57 4697486 [System-1] INFO selection.ServiceContextImpl - stop called in PRESENTING_PENDING or PRESENTING: (id ae71a8b6, PRESENTING, delegate: DVRBroadcastServiceContextDelegate)
000101-01:18:57 4697487 [System-1] INFO selection.ServiceContextImpl - setting state to STOP_PENDING: (id ae71a8b6, PRESENTING, delegate: DVRBroadcastServiceContextDelegate - service: org.ca)
000101-01:18:57 4697488 [System-1] INFO selection.DVRBroadcastServiceContextDelegate - stopPresenting: DVRBroadcastServiceContextDelegate - service: org.cablelabs.impl.service.javatv.service]
000101-01:18:57 4697489 [System-1] INFO selection.DVRBroadcastServiceContextDelegate - setting currentState to NOT_PRESENTING
000101-01:18:57 4697489 [System-1] DEBUG selection.DVRBroadcastServiceContextDelegate - stopPresentingWithReason - type: javax.tv.service.selection.PresentationTerminatedEvent, reason: 5
000101-01:18:57 4697491 [System-1] INFO player.AbstractServicePlayer - removePresentationModeListener: org.cablelabs.impl.service.javatv.selection.DVRBroadcastServiceContextDelegate$Presenta5
000101-01:18:57 4697492 [System-1] DEBUG selection.ServiceContextImpl - playerStopping - player: TSBServiceMediaHandler@ff79375d
000101-01:18:57 4697493 [System-1] INFO player.AbstractPlayer - stop() [Started, Presenting]
000101-01:18:57 4697494 [System-1] DEBUG player.AbstractPlayer - stop(StopEvent) - event: javax.media.StopByRequestEvent[source=TSBServiceMediaHandler@ff79375d,previous=Started,current=Prefet]
000101-01:18:57 4697495 [System-1] DEBUG player.ClockImpl - stop() - clock mediaTime updated to: 64571000000
000101-01:18:57 4697495 [System-1] DEBUG presentation.AbstractPresentation - stop()
000101-01:18:57 4697496 [System-1] INFO presentation.TSBServicePresentation - doStop - cleaning up condition monitor from: AbstractServicePresentation: 4b9f5a2
000101-01:18:57 4697499 [System-1] DEBUG presentation.NetworkConditionMonitor - cleanup: Network condition monitor - initialized: true, session: BroadcastSession - networkInterface:org.cablel1
000101-01:18:57 4697844 [System-1] DEBUG presentation.TSBServicePresentation - deactivateAlarms
000101-01:18:57 4697845 [System-1] INFO presentation.AbstractServicePresentation - doStop - current state: STATE_NORMAL_CONTENT_SESSION_STARTED
000101-01:18:57 4697849 [System-1] INFO presentation.AbstractServicePresentation - updateState - from: STATE_NORMAL_CONTENT_SESSION_STARTED to STATE_PRESENTATION_STOPPED
000101-01:18:57 4697854 [System-1] INFO presentation.AbstractServicePresentation - stopping currentSession and setting to null: BroadcastSession - networkInterface:org.cablelabs.impl.davic.ne
000101-01:18:57 4697854 [System-1] INFO presOperational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
000101-01:18:57 4697858 [System-1] INFO session.BroadcastSession - stop: BroadcastSession - networkInterface:org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@24c4bac8, decodehandle: e
000101-01:18:57 4697860 [System-1] DEBUG mpe.MediaAPIImpl - stopBroadcastDecode(sessionHandle=0x2adac3b4)
MAINLINE: <<<MPEOS_MEDIA >>> TODO - implement decode sessions (mds: 0x2adac3b4)
MAINLINE: <<<MPEOS_MEDIA >>> TODO - implement decode sessions mds->videoDevice: 0x2ad8485c
<000101-01:18:57><media/mpeos_stream.c:845>mpeos_mediaStop(): <<< MPEOS_MEDIA >>> mpeos_mediaStop(videoDevice 0x2ad8485c) ENTER
<000101-01:18:57><media/mpeos_stream.c:846>mpeos_mediaStop(): <<< MPEOS_MEDIA >>> mpeos_mediaStop videoDevice 0x2ad8485c.
<000101-01:18:57><media/mpeos_stream.c:562>getDecoder(): <<< MPEOS_MEDIA >>> getDecoder(videoDev 0x2ad8485c) ENTER
<000101-01:18:57><media/mpeos_stream.c:867>mpeos_mediaStop(): <<< MPEOS_MEDIA >>> decoder->brcm.streamHandle 0x8cefb8 exists ... close the streams ...
<000101-01:18:57><media/mpeos_decode_stream.c:545>mpeos_stream_p_stop_consumers(): Stopping all consumers
<000101-01:18:57><media/mpeos_decode.c:886>mpeos_decode_stop(): <<< MPEOS_MEDIA >>> mpeos_decode_stop()
<000101-01:18:57><media/mpeos_decode.c:927>mpeos_decode_stop(): <<< MPEOS_MEDIA >>> Stop MPEOS VIDEO decoder 0x2ad8b4b4 ....
<000101-01:18:57><media/mpeos_decode_video.c:289>mpeos_decode_stop_video(): <<< MPEOS_MEDIA >>> mpeos_decode_stop_video(): stop_video 0x2ad8b4b4
<000101-01:18:57><media/mpeos_decode.c:1601>mpeos_decode_unset_sync_channel(): <<< MPEOS_MEDIA >>> mpeos_decode_unset_sync_channel(): Unset sync channel decode 0x2adabff0 video
<000101-01:18:57><media/mpeos_decode.c:934>mpeos_decode_stop(): <<< MPEOS_MEDIA >>> Stop MPEOS AUDIO decoder 0x2ad8b4dc ....
<000101-01:18:57><media/mpeos_decode_audio.c:800>mpeos_decode_stop_audio(): <<< MPEOS_MEDIA >>> stop_audio 0x2ad8b4dc
<000101-01:18:57><media/mpeos_decode.c:1601>mpeos_decode_unset_sync_channel(): <<< MPEOS_MEDIA >>> mpeos_decode_unset_sync_channel(): Unset sync channel decode 0x2adabff0 pcm passthrough
<000101-01:18:57><media/mpeos_decode_audio.c:1976>mpeos_display_p_enable_audio(): <<< MPEOS_MEDIA >>> setting audio decode 0x2adabff0 enable state to 0
<000101-01:18:57><media/mpeos_decode_audio.c:1315>mpeos_decode_p_enable_audio(): <<< MPEOS_MEDIA >>> Checking decode 0x2adabff0 started 1 audio 0x2ad8b4dc
<000101-01:18:57><media/mpeos_decode_audio.c:1976>mpeos_display_p_enable_audio(): <<< MPEOS_MEDIA >>> setting audio decode 0x2adabff0 enable state to 1
<000101-01:18:57><media/mpeos_decode_audio.c:1315>mpeos_decode_p_enable_audio(): <<< MPEOS_MEDIA >>> Checking decode 0x2adabff0 started 1 audio 0x2ad8b4dc
<000101-01:18:57><media/mpeos_decode.c:941>mpeos_decode_stop(): <<< MPEOS_MEDIA >>> Stop MPEOS PCR pid channel 0xf117beb8 ....
[ 4437.937000] *** 01:18:40.228 xpt: ***************************************************************************************
[ 4437.937000] *** 01:18:40.228 xpt: * WARNING: The max bitrate for the all-pass parser band has been increased to 81 Mbps.
[ 4437.937000] *** 01:18:40.229 xpt: * Check your usage mode.Software will decrease this when all pass mode is disabled.
[ 4437.938000] *** 01:18:40.229 xpt: ***************************************************************************************
<000101-01:18:57><media/mpeos_decode_stream.c:162>mpeos_stream_close(): <<< MPEOS_MEDIA >>> Free LIVE stream 0x8cefb8 ....
<000101-01:18:57><media/mpeos_decode.c:886>mpeos_decode_stop(): <<< MPEOS_MEDIA >>> mpeos_decode_stop()
<000101-01:18:57><media/mpeos_decode.c:918>mpeos_decode_stop(): <<< MPEOS_MEDIA >>> mpeos_decode_stop(): decoder already stopped!
<000101-01:18:57><media/mpeos_stream.c:137>blankVideo(): <<< MPEOS_MEDIA >>> blankVideo(decoder_ptr 0x2adac4bc, blank TRUE) ENTER
Rodney wonders ------ Surely this function, blankVideo, is not implemented! media/mpeos_stream.c:139
<000101-01:18:57><media/mpeos_stream.c:674>mediaSetMuteState(): <<< MPEOS_MEDIA >>> mediaSetMuteState(mute true) ENTER
================================= media/mpeos_stream.c:677 Log that we are using this global!
000101-01:18:57 4698056 [System-1] INFO session.BroadcastSession - stopped decode: BroadcastSession - networkInterface:org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@24c4bac8, decoe
000101-01:18:58 4698392 [System-1] INFO session.BroadcastSession - stopped decrypt: BroadcastSession - networkInterface:org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@24c4bac8, dece
000101-01:18:58 4698393 [System-1] DEBUG presentation.AbstractServicePresentation - stop - sessionStarted flag set to false
000101-01:18:58 4698393 [ED-Normal] DEBUG pod.POD - POD_EVENT_POD_RESOURCE_AVAILABLE event...
000101-01:18:58 4698408 [System-1] DEBUG player.AbstractPlayer - changing state from Started to Prefetched
000101-01:18:58 4698440 [System-1] DEBUG player.AbstractPlayer - postEvent(javax.media.StopByRequestEvent[source=TSBServiceMediaHandler@ff79375d,previous=Started,current=Prefetched,target=Pre]
000101-01:18:58 4698441 [System-1] DEBUG player.AbstractPlayer - deallocate() [Prefetched]
000101-01:18:58 4698441 [System-1] DEBUG player.AbstractPlayer - changing state from Prefetched to Realized
000101-01:18:58 4698441 [System-1] DEBUG player.AbstractPlayer - releaseResources(Realized)
000101-01:18:58 4698442 [System-1] DEBUG player.AbstractVideoPlayer - doReleasePrefetchedResources()
000101-01:18:58 4698442 [System-1] DEBUG player.AbstractVideoPlayer - video device was not null - relinquishing video device
000101-01:18:58 4698443 [System-1] DEBUG ui.HScreenDevice - releaseDevice - callerContext: AppContext@-953063857[636029]
000101-01:18:58 4698443 [System-1] DEBUG ui.HScreenDevice - callerContext is current owner - releasing device
000101-01:18:58 4698444 [System-1] DEBUG ui.HScreenDevice - take - current owner: org.cablelabs.impl.manager.ResourceManager$Client@249bce4e, new owner: null
000101-01:18:58 4698444 [System-1] DEBUG ui.HScreenDevice - owner null or matches - ok to set owner to new owner
000101-01:18:58 4698444 [System-1] DEBUG player.AbstractVideoPlayer - video device relinquished
000101-01:18:58 4698445 [System-1] DEBUG player.AbstractPlayer - getMediaTime - presentation was null or returned a null mediatime - returning mediatime from player clock: 64.571s (6457100000)
000101-01:18:58 4698446 [System-1] DEBUG player.AbstractPlayer - postEvent(javax.media.DeallocateEvent[source=TSBServiceMediaHandler@ff79375d,previous=Prefetched,current=Realized,target=Reali]
000101-01:18:58 4698448 [System-1] DEBUG player.AbstractPlayer - close() [Realized]
000101-01:18:58 4698449 [System-1] DEBUG player.AbstractPlayer - postEvent(javax.media.ControllerClosedEvent[source=TSBServiceMediaHandler@ff79375d]) [Realized]
000101-01:18:58 4698449 [System-1] DEBUG player.AbstractPlayer - releaseAllResources
000101-01:18:58 4698449 [System-1] DEBUG player.AbstractVideoPlayer - doReleaseAllResources
000101-01:18:58 4698450 [System-1] DEBUG player.AbstractPlayer - releaseResources(Unrealized)
000101-01:18:58 4698451 [System-1] DEBUG player.AbstractVideoPlayer - doReleasePrefetchedResources()
000101-01:18:58 4698452 [System-1] DEBUG player.AbstractServicePlayer - doReleaseRealizedResources
000101-01:18:58 4698452 [System-1] DEBUG user.UserPreferenceManager - getInstance()
000101-01:18:58 4698453 [System-1] DEBUG user.UserPreferenceManager - removeUserPreferenceChangeListener(class org.cablelabs.impl.media.player.AbstractServicePlayer$UserPreferenceChangeListen)
000101-01:18:58 4698453 [System-1] DEBUG user.UserPreferenceManager - removeUserPreferenceChangeListener(class org.cablelabs.impl.media.player.AbstractServicePlayer$UserPreferenceChangeListen)
000101-01:18:58 4698454 [System-1] DEBUG player.AbstractPlayer - disconnecting from datasource
000101-01:18:58 4698455 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateForRemovedUses: Removing use(s) LIVEPLAYBACK for client TSWC 0x20407d42:[nlist 1,ru org.cablelabs.im]
000101-01:18:58 4698789 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateForRemovedUses: current state is READY_TO_BUFFER, and no buffering uses remaining.
000101-01:18:58 4698789 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateForRemovedUses: current state is READY_TO_BUFFER/TUNESUCCESS and no tuner uses remaining.
000101-01:18:58 4698791 [System-1] DEBUG timer.TimerMgrJava2 - scheduleTimerSpec: org.cablelabs.impl.manager.timer.TimerMgrJava2$TVTimerImpl$1@d0d3cffc, spec: TVTS 0x90049120: [time=9466895430
000101-01:18:58 4698792 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: scheduleTimerSpec spec: TVTS 0x90049120: [time=946689543670, absolute=true, repeat=false, regular=true, li]
000101-01:18:58 4698792 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: startTimer: death timer scheduled
000101-01:18:58 4698794 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateNIResourceUsages: Current NI resource usages: [org.cablelabs.impl.service.ServiceContextResourceUsag]
000101-01:18:58 4698795 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: Removed client: TSWC 0x20407d42:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResourc]
000101-01:18:58 4698796 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: Prior constraints: TSC:[uses NO USES,res NI,mind 0,desd 0,maxd MAX_VAL]
000101-01:18:58 4698797 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: New constraints: TSC:[uses NO USES,res NI,mind 0,desd 0,maxd MAX_VAL]
000101-01:18:58 4698798 [System-1] DEBUG player.AbstractPlayer - releaseAllResources complete
000101-01:18:58 4698798 [System-1] DEBUG selection.DVRBroadcastServiceContextDelegate - releasePresentingResources
000101-01:18:58 4698800 [System-1] DEBUG selection.DVRBroadcastServiceContextDelegate - releasePresentingResources - releasing timeshiftwindowclient: TSWC 0x9e489bfc:[nlist 1,ru org.cablelabs]
000101-01:18:58 4698800 [System-1] WARN timer.TimerMgrJava2 - deschedule called with an unscheduled spec: TVTS 0x2439c394: [time=1000, absolute=false, repeat=false, regular=true]
000101-01:18:58 4698802 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateForRemovedUses: Removing use(s) NO USES for client TSWC 0x9e489bfc:[nlist 1,ru org.cablelabs.impl.se]
000101-01:18:59 4699136 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateForRemovedUses: current state is READY_TO_BUFFER, and no buffering uses remaining.
000101-01:18:59 4699137 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateForRemovedUses: current state is READY_TO_BUFFER/TUNESUCCESS and no tuner uses remaining.
000101-01:18:59 4699163 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateNIResourceUsages: Current NI resource usages: [org.cablelabs.impl.service.ServiceContextResourceUsag]
000101-01:18:59 4699165 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: updateNIResourceUsages: Removing ResourceUsage org.cablelabs.impl.service.ServiceContextResourceUsageImpl@n
000101-01:18:59 4699166 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: Removed client: TSWC 0x9e489bfc:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResourc]
000101-01:18:59 4699167 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: Prior constraints: TSC:[uses NO USES,res NO USES,mind 0,desd 0,maxd MAX_VAL]
000101-01:18:59 4699167 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: New constraints: TSC:[uses NO USES,res NO USES,mind 0,desd 0,maxd MAX_VAL]
000101-01:18:59 4699168 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: removeClient: Last client removed
000101-01:18:59 4699168 [System-1] DEBUG recording.RecordingManagerImpl - removeDisableBufferingListener: org.cablelabs.impl.service.javatv.selection.DVRBroadcastServiceContextDelegate$Disabl0
000101-01:18:59 4699169 [System-1] INFO selection.ServiceContextImpl - delegate callback - notPresenting - class javax.tv.service.selection.PresentationTerminatedEvent, reason: 5: (id ae71a8)
000101-01:18:59 4699170 [System-1] INFO selection.ServiceContextImpl - notPresenting called in STOP_PENDING: (id ae71a8b6, USER_STOP_PENDING, delegate: DVRBroadcastServiceContextDelegate - s)
000101-01:18:59 4699171 [System-1] INFO selection.ServiceContextImpl - setting state to NOT_PRESENTING: (id ae71a8b6, USER_STOP_PENDING, delegate: DVRBroadcastServiceContextDelegate - servic)
000101-01:18:59 4699171 [System-1] INFO selection.ServiceContextImpl - posting event type: javax.tv.service.selection.PresentationTerminatedEvent, reason 5: (id ae71a8b6, NOT_PRESENTING, del)
000101-01:18:59 4699173 [System-1] DEBUG selection.ServiceContextImpl - postEvent called with javax.tv.service.selection.PresentationTerminatedEvent[source=org.cablelabs.impl.service.javatv.s)
000101-01:18:59 4699174 [System-1] DEBUG application.DemandExecQueue - ensureThread() called for ContextDemandExecQueue@-1473535826[AppContext@-953063857[636029]]
000101-01:18:59 >>> WatchTV: ****************************************************************************************
000101-01:18:59 >>> WatchTV: Presentation stopped with javax.tv.service.selection.PresentationTerminatedEvent[source=org.cablelabs.impl.service.javatv.selection.DVRServiceContextImpl@ae71a8b6]
000101-01:18:59 >>> WatchTV: ****************************************************************************************
000101-01:18:59 >>> WatchTV: *** ERROR *** Tune may have failed.
000101-01:18:59 >>> WatchTV: ****************************************************************************************
000101-01:18:59 >>> WatchTV: Selecting service:
org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=ServiceImpl8736656, locator=ocap://f=0xa8cce40.0x5.m=0x10, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$Ser]
000101-01:18:59 >>> WatchTV: ****************************************************************************************
000101-01:18:59 4699529 [AWT-EventQueue-0] INFO selection.ServiceContextImpl - select service (NOT_PRESENTING) - org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=Servi)
000101-01:18:59 4699531 [AWT-EventQueue-0] DEBUG selection.RecordedServiceContextDelegate - canPresent: org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=ServiceImpl8736e
000101-01:18:59 4699548 [AWT-EventQueue-0] DEBUG selection.AbstractServiceContextDelegate - canPresent: org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=ServiceImpl8736e
000101-01:18:59 4699549 [AWT-EventQueue-0] DEBUG selection.DVRServiceContextImpl - delegate to use is a TimeShiftProperties - update with current settings: (id ae71a8b6, NOT_PRESENTING, deleg)
000101-01:18:59 4699550 [AWT-EventQueue-0] DEBUG selection.DVRBroadcastServiceContextDelegate - setLastServiceBufferedPreference: false
000101-01:18:59 4699550 [AWT-EventQueue-0] DEBUG selection.DVRBroadcastServiceContextDelegate - stopLastChannelBuffering
000101-01:18:59 4699599 [System-1] DEBUG selection.ServiceContextImpl - doSelect (NOT_PRESENTING) - org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=ServiceImpl8736656,)
000101-01:18:59 >>> WatchTV: Selected service:
org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=ServiceImpl8736656, locator=ocap://f=0xa8cce40.0x5.m=0x10, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$Ser]
000101-01:18:59 4699600 [System-1] INFO selection.ServiceContextImpl - select called in NOT PRESENTING: (id ae71a8b6, NOT_PRESENTING, delegate: DVRBroadcastServiceContextDelegate - service: )
000101-01:18:59 4699612 [System-1] INFO selection.ServiceContextImpl - setting state to PRESENTING_PENDING: (id ae71a8b6, NOT_PRESENTING, delegate: DVRBroadcastServiceContextDelegate - servi)
000101-01:18:59 4699613 [AWT-EventQueue-0] WARN timer.TimerMgrJava2 - deschedule called with an unscheduled spec: TVTS 0x96032426: [time=3000, absolute=false, repeat=false, regular=true, lis]
000101-01:18:59 4699619 [System-1] INFO selection.ServiceContextImpl - calling delegate.present: (id ae71a8b6, PRESENTING_PENDING, delegate: DVRBroadcastServiceContextDelegate - service: nul)
000101-01:18:59 4699633 [AWT-EventQueue-0] DEBUG timer.TimerMgrJava2 - scheduleTimerSpec: org.cablelabs.impl.manager.timer.TimerMgrJava2$TVTimerImpl$1@7f4f7253, spec: TVTS 0x27fbdc97: [time=30
000101-01:18:59 4699648 [System-1] DEBUG selection.ServiceContextImpl - present using delegate DVRBroadcastServiceContextDelegate - service: null: (id ae71a8b6, PRESENTING_PENDING, delegate: )
000101-01:18:59 4699660 [System-1] INFO selection.DVRBroadcastServiceContextDelegate - present - new service: org.cablelabs.impl.service.javatv.service.ServiceImpl@53a2761d[uniqueID=ServiceIl
000101-01:18:59 4699679 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByDuration(Service ocap://f=0xa8cce40.0x5.m=0x10,minD 0,maxD 0,uses NI,ru org.cablelabs.impl.service.ServiceCon)
000101-01:18:59 4700015 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByEvaluation(Service ocap://f=0xa8cce40.0x5.m=0x10,uses NI,ru org.cablelabs.impl.service.ServiceContextResource)
000101-01:18:59 4700017 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByEvaluation: considering TSW 0x6a4dfa80:[service ServiceImpl8736656 (ocap://f=0xa8cce40.0x5.m=0x10) ,state NOT]
000101-01:18:59 4700019 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByEvaluation: considering TSW 0x3ce60fd6:[service ServiceImpl8735864 (ocap://f=0xa8cce40.0x2.m=0x10) ,state IDL]
000101-01:18:59 4700020 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByEvaluation: considering TSW 0xeaadc700:[service ServiceImpl8736112 (ocap://f=0xa8cce40.0x3.m=0x10) ,state IDL]
000101-01:18:59 4700021 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByEvaluation: considering TSW 0xe5eeea0f:[service ServiceImpl8736384 (ocap://f=0xa8cce40.0x4.m=0x10) ,state REA]
000101-01:18:59 4700054 [System-1] DEBUG timeshift.TimeShiftManagerImpl - getTSWByDuration.durationEvaluator: Found active TSW for use: TSW 0x6a4dfa80:[service ServiceImpl8736656 (ocap://f=0x]
000101-01:18:59 4700055 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0x6a4dfa80: addClient: Prior constraints: TSC:[uses NO USES,res NO USES,mind 0,desd 0,maxd MAX_VAL]
000101-01:18:59 4700056 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0x6a4dfa80: addClient: New constraints: TSC:[uses NO USES,res NI,mind 0,desd 0,maxd MAX_VAL]
000101-01:18:59 4700058 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0x6a4dfa80: addClient: Created client: TSWC 0xf5751c97:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResourceUs]
000101-01:18:59 4700060 [System-1] INFO selection.DVRBroadcastServiceContextDelegate - using timeshiftWindowClient: TSWC 0xf5751c97:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResou]
000101-01:18:59 4700060 [System-1] INFO selection.DVRBroadcastServiceContextDelegate - setting currentState to PRESENTING_PENDING
000101-01:18:59 4700061 [System-1] DEBUG recording.RecordingManagerImpl - addDisableBufferingListener: org.cablelabs.impl.service.javatv.selection.DVRBroadcastServiceContextDelegate$DisableBu0
000101-01:18:59 4700062 [System-1] DEBUG selection.DVRBroadcastServiceContextDelegate - present - got TSW in state NOT_READY_TO_BUFFER (5)
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
000101-01:19:02 4702526 [pool-28] DEBUG application.DemandExecQueue - ContextDemandExecQueue finished...
000101-01:19:03 4703651 [Thread-2] DEBUG application.AppManager - getAppsDatabase returning global db due to privileged caller (or null): true
000101-01:19:03 4703659 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs - filter: org.cablelabs.impl.manager.snmp.SnmpAppsDatabaseMonitor@b20e0f88, known ids: [636027, 14000, 636029, 1]
000101-01:19:03 4703661 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=636029,names=[eng:WatchTV],code=2,bound=true,visibility=3,priority=230,baseDir=/usr/lo]
000101-01:19:03 4703663 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=636027,names=[eng:IDGSettingsApp],code=1,bound=true,visibility=0,priority=240,baseDir=]
000101-01:19:03 4703666 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=16028,names=[eng:Simple Watch TV],code=2,bound=true,visibility=3,priority=220,baseDir=]
000101-01:19:03 4703668 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=16026,names=[eng:Config (NFS)],code=2,bound=true,visibility=3,priority=220,baseDir=/us]
000101-01:19:03 4703672 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=16025,names=[eng:DVR Sample (NFS)],code=2,bound=true,visibility=3,priority=254,baseDir]
000101-01:19:03 4703675 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=14000,names=[eng:Launcher],code=1,bound=true,visibility=3,priority=220,baseDir=/usr/lo]
000101-01:19:03 4703676 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs: size 6
000101-01:19:03 4703677 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs - filter: org.cablelabs.impl.manager.snmp.SnmpAppsDatabaseMonitor@b20e0f88, known ids: []
000101-01:19:03 4703677 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs: size 0
000101-01:19:03 4703678 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-01:19:03 4703678 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-01:19:03 4703678 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
000101-01:19:03 4703786 [TimerThread-0] INFO timeshift.TimeShiftWindow - TSW 0xe5eeea0f: releaseUnusedResources: current state: READY_TO_BUFFER
000101-01:19:03 4704012 [TimerThread-0] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: releaseUnusedResources: No tuner uses remaining. Releasing tuner.
000101-01:19:03 4704011 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-01:19:03 4704012 [TimerThread-0] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: releaseTuner: UNREGISTERING NetworkInterfaceCallback
000101-01:19:03 4704014 [TimerThread-0] DEBUG timeshift.TimeShiftWindow - TSW 0xe5eeea0f: releaseTuner: RELEASING NetworkInterface (1)
000101-01:19:03 4704048 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-01:19:03 4704049 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-01:19:03 4704049 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-01:19:03 4704050 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-01:19:03 4704051 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-01:19:03 4704051 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-01:19:03 4704054 [TimerThread-0] DEBUG tuning.NetworkInterfaceImpl - Reservation::take() Enter - owner: org.cablelabs.impl.manager.ResourceManager$Client@cf3f8f3f newOwner: null
000101-01:19:03 4704055 [TimerThread-0] DEBUG tuning.NetworkInterfaceImpl - state = TUNED_SYNC newstate = RELEASED
000101-01:19:03 4704055 [TimerThread-0] INFO timeshift.TimeShiftWindow - TSW 0xe5eeea0f: setStateAndNotify(): Changed from state READY_TO_BUFFER to IDLE

stopiwalla
Offline
Joined: 2010-05-25
Points: 0

I am using RI stack 1.1.4-Rel-C and a modified/customized version of the WatchTV app. I have modified our MPEOS code to notify the tunign events STARTEd, SYNC, and UNSYNC as described earlier by you. Having two tuners, the stack ends up asking for alternate tuners everytime we channel change. I wonder why?
In any case, once I am tuned and AV is showing fine, I pull the cable feed, and send out the UNSYNC event. Stack puts up the Alternate Service Content via drip feed as expected; internally I monitor for tune SYNC and send out when obtained. Everything is still fine so far. I channel change, things resume fine.
Now, I try the above test again, except when the Alternate Service content is up, I try to perform a channel change and then put the feed back. I notice that I just get alternate service content and no video despite the fact that the tuners (2 of them) have relocked to their original parameters just fine, and the notifications given out to the stack just as above. I am not sure why I am getting into this situation. I am posting the logs for it here so that you may see if there is something out of line.
Thanks.
Look for "TunerQ 0x54" to see the notifications being sent from the RI to the Stack. The last two TUNE_SYNC should have brought down the dripfeed and started teh AV decoding. But that does not happen.
>>>>>>>>>>
# <000101-00:49:52><media/mpeos_tune.c:153>tuner_workerThread(): TUNER 1 worker thread requesting retune.
<000101-00:49:52><media/mpeos_tune.c:695>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget(tuner 0x2ad913c0) ENTER
<000101-00:49:52><media/mpeos_tune.c:701>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget calling tuneTargetQAM tuner 1 qamMode 16
<000101-00:49:52><media/mpeos_tune.c:726>tuneTargetQAM(): <<< MPEOS_TUNE >>> tuneTargetQAM(tuner 0x2ad913c0) tuner->tunerId 1 ENTER
000101-00:49:52 <<< MPEOS_TUNE >>> mpeos_tuner_tune_qam(): QAM freq 177000000, symbol rate 5360537
<000101-00:49:52><media/mpeos_tune.c:833>callbackTuneNotification(): <<< MPEOS_TUNE >>> callbackTuneNotification tunerId 1
<000101-00:49:52><media/mpeos_tune.c:153>tuner_workerThread(): TUNER 2 worker thread requesting retune.
<000101-00:49:52><media/mpeos_tune.c:695>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget(tuner 0x2ad91424) ENTER
<000101-00:49:52><media/mpeos_tune.c:701>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget calling tuneTargetQAM tuner 2 qamMode 16
<000101-00:49:52><media/mpeos_tune.c:726>tuneTargetQAM(): <<< MPEOS_TUNE >>> tuneTargetQAM(tuner 0x2ad91424) tuner->tunerId 2 ENTER
000101-00:49:52 <<< MPEOS_TUNE >>> mpeos_tuner_tune_qam(): QAM freq 177000000, symbol rate 5360537
<000101-00:49:52><media/mpeos_tune.c:583>processTuneEvent(): Tuner=1 job=13 lastCmd=TUNER_UNSYNC (2)
<000101-00:49:52><media/mpeos_tune.c:587>processTuneEvent(): cur_state=MPE_MEDIA_TUNER_STATE_UNLOCKED (4) new_cmd=TUNER_UNSYNC (2)
<000101-00:49:52><media/mpeos_tune.c:550>tuner_workerRetry(): Tuner 1, send Request to retune job#=13
<000101-00:49:52><media/mpeos_tune.c:134>tuner_workerThread(): TUNER worker thread received msg 0xBAADFEED
<000101-00:49:52><media/mpeos_tune.c:148>tuner_workerThread(): TUNER 1 worker thread received retune for Job 13, current job=13
<000101-00:49:52><media/mpeos_tune.c:833>callbackTuneNotification(): <<< MPEOS_TUNE >>> callbackTuneNotification tunerId 2
<000101-00:49:52><media/mpeos_tune.c:583>processTuneEvent(): Tuner=2 job=1 lastCmd=TUNER_UNSYNC (2)
<000101-00:49:52><media/mpeos_tune.c:587>processTuneEvent(): cur_state=MPE_MEDIA_TUNER_STATE_UNLOCKED (4) new_cmd=TUNER_UNSYNC (2)
<000101-00:49:52><media/mpeos_tune.c:550>tuner_workerRetry(): Tuner 2, send Request to retune job#=1
<000101-00:49:52><media/mpeos_tune.c:134>tuner_workerThread(): TUNER worker thread received msg 0xBAADFEED
<000101-00:49:52><media/mpeos_tune.c:148>tuner_workerThread(): TUNER 2 worker thread received retune for Job 1, current job=1
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
HandleSetDsgMode:: Already in Operational Mode 0. Ignoring this Set_DSG_mode!
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
HandleSetDsgMode:: Already in Operational Mode 0. Ignoring this Set_DSG_mode!
<000101-00:49:57><media/mpeos_tune.c:153>tuner_workerThread(): TUNER 1 worker thread requesting retune.
<000101-00:49:57><media/mpeos_tune.c:695>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget(tuner 0x2ad913c0) ENTER
<000101-00:49:57><media/mpeos_tune.c:701>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget calling tuneTargetQAM tuner 1 qamMode 16
<000101-00:49:57><media/mpeos_tune.c:726>tuneTargetQAM(): <<< MPEOS_TUNE >>> tuneTargetQAM(tuner 0x2ad913c0) tuner->tunerId 1 ENTER
000101-00:49:57 <<< MPEOS_TUNE >>> mpeos_tuner_tune_qam(): QAM freq 177000000, symbol rate 5360537
<000101-00:49:57><media/mpeos_tune.c:153>tuner_workerThread(): TUNER 2 worker thread requesting retune.
<000101-00:49:57><media/mpeos_tune.c:695>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget(tuner 0x2ad91424) ENTER
<000101-00:49:57><media/mpeos_tune.c:701>tuneTarget(): <<< MPEOS_TUNE >>> tuneTarget calling tuneTargetQAM tuner 2 qamMode 16
<000101-00:49:57><media/mpeos_tune.c:726>tuneTargetQAM(): <<< MPEOS_TUNE >>> tuneTargetQAM(tuner 0x2ad91424) tuner->tunerId 2 ENTER
000101-00:49:57 <<< MPEOS_TUNE >>> mpeos_tuner_tune_qam(): QAM freq 177000000, symbol rate 5360537
<000101-00:49:58><media/mpeos_tune.c:833>callbackTuneNotification(): <<< MPEOS_TUNE >>> callbackTuneNotification tunerId 1
<000101-00:49:58><media/mpeos_tune.c:583>processTuneEvent(): Tuner=1 job=13 lastCmd=TUNER_UNSYNC (2)
<000101-00:49:58><media/mpeos_tune.c:587>processTuneEvent(): cur_state=MPE_MEDIA_TUNER_STATE_UNLOCKED (4) new_cmd=TUNER_SYNC (1)
<000101-00:49:58><media/mpeos_media.c:769>NotifyTuneEventToRegisteredQueues(): Tuner 0x1, Evt: TUNE_SYNC (0x2), TunerQ 0x54, Act 0x8CF520)
<000101-00:49:58><media/mpeos_media.c:786>NotifyTuneEventToRegisteredQueues(): Tuner 0x1, Evt: TUNE_SYNC (0x2), ClientQ 0x55, Act 0x8CF520)
<000101-00:49:58><media/mpeos_media.c:786>NotifyTuneEventToRegisteredQueues(): Tuner 0x1, Evt: TUNE_SYNC (0x2), ClientQ 0x57, Act 0x8CF520)
<000101-00:49:58><media/mpeos_tune.c:455>mpeos_mediaGetTunerInfo(): <<< MPEOS_TUNE >>> mpeos_mediaGetTunerInfo( tunerId 1, tuneParams_ptr 0x37087f60) ENTER
<000101-00:49:58><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 1) ENTER
000101-00:49:58 2962374 [System-1] DEBUG tuning.NetworkInterfaceImpl - TUNE_SYNCED
<000101-00:49:58><media/mpeos_tune.c:455>mpeos_mediaGetTunerInfo(): <<< MPEOS_TUNE >>> mpeos_mediaGetTunerInfo( tunerId 1, tuneParams_ptr 0x37077e58) ENTER
<000101-00:49:58><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 1) ENTER
000101-00:49:58 2962378 [System-1] DEBUG tuning.NetworkInterfaceImpl - Invalid transaction or state: RESERVED
000101-00:49:58 2962380 [System-1] INFO application.AppExecQueue - Exception in AppExecQueue
000101-00:49:58 java.lang.IllegalStateException: Invalid transaction or state
at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$NIStateMachine.handleTuneSynced(Unknown Source)
at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TuneRequest$1.run(Unknown Source)
at org.cablelabs.impl.manager.application.WorkerTask.run(Compiled Method)(Unknown Source)
at org.cablelabs.impl.manager.application.AppExecQueue$1.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
at java.lang.Thread.startup(Unknown Source)
<000101-00:49:58><media/mpeos_tune.c:833>callbackTuneNotification(): <<< MPEOS_TUNE >>> callbackTuneNotification tunerId 2
<000101-00:49:58><media/mpeos_tune.c:583>processTuneEvent(): Tuner=2 job=1 lastCmd=TUNER_UNSYNC (2)
<000101-00:49:58><media/mpeos_tune.c:587>processTuneEvent(): cur_state=MPE_MEDIA_TUNER_STATE_UNLOCKED (4) new_cmd=TUNER_SYNC (1)
<000101-00:49:58><media/mpeos_media.c:769>NotifyTuneEventToRegisteredQueues(): Tuner 0x2, Evt: TUNE_SYNC (0x2), TunerQ 0x54, Act 0x8B0158)
<000101-00:49:58><media/mpeos_media.c:786>NotifyTuneEventToRegisteredQueues(): Tuner 0x2, Evt: TUNE_SYNC (0x2), ClientQ 0x55, Act 0x8B0158)
<000101-00:49:58><media/mpeos_media.c:786>NotifyTuneEventToRegisteredQueues(): Tuner 0x2, Evt: TUNE_SYNC (0x2), ClientQ 0x57, Act 0x8B0158)
<000101-00:49:58><media/mpeos_tune.c:455>mpeos_mediaGetTunerInfo(): <<< MPEOS_TUNE >>> mpeos_mediaGetTunerInfo( tunerId 2, tuneParams_ptr 0x37087f60) ENTER
<000101-00:49:58><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 2) ENTER
<000101-00:49:58><media/mpeos_tune.c:455>mpeos_mediaGetTunerInfo(): <<< MPEOS_TUNE >>> mpeos_mediaGetTunerInfo( tunerId 2, tuneParams_ptr 0x37077ea8) ENTER
<000101-00:49:58><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 2) ENTER
000101-00:49:58 2962593 [System-1] DEBUG tuning.NetworkInterfaceImpl - TUNE_SYNCED
000101-00:49:58 2962594 [System-1] DEBUG tuning.NetworkInterfaceImpl - Cancelling timer
000101-00:49:58 2962595 [System-1] WARN timer.TimerMgrJava2 - deschedule called with an unscheduled spec: TVTS 0xac52dc4c: [time=30000, absolute=false, repeat=false, regular=true, listener=o]
000101-00:49:58 2962595 [System-1] DEBUG tuning.NetworkInterfaceImpl - state = TUNED_UNSYNC newstate = TUNED_SYNC
000101-00:49:58 2962597 [System-1] DEBUG tuning.NetworkInterfaceImpl - Invoking callback notifySyncAcquired(1 org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TransportStreamAdapter@8)
000101-00:49:58 2962599 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: notifySyncAcquired (NI org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@7088efdc,ti 0x903b751a)
000101-00:49:58 2962600 [System-1] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: ableToBuffer: TRUE
000101-00:49:58 2962600 [System-1] INFO timeshift.TimeShiftWindow - TSW 0xd925547b: setStateAndNotify(): Changed from state NOT_READY_TO_BUFFER to READY_TO_BUFFER
<000101-00:49:59><media/mpeos_tune.c:873>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 1) ENTER
<000101-00:49:59><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 1) ENTER
<000101-00:49:59><media/mpeos_tune.c:881>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 1) RETURNING tuner->brcm.band 0x2adac298
[ 2699.413000] *** 00:49:44.409 xpt: ***************************************************************************************
[ 2699.413000] *** 00:49:44.409 xpt: * WARNING: The max bitrate for the all-pass parser band has been increased to 81 Mbps.
[ 2699.413000] *** 00:49:44.409 xpt: * Check your usage mode.Software will decrease this when all pass mode is disabled.
[ 2699.413000] *** 00:49:44.409 xpt: ***************************************************************************************
000101-00:49:59 2963079 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() received event code: 300b, eventData1(SI handle):0x6b4cb8, eventData2: 2
000101-00:49:59 2963080 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() processing PAT event 0x300b type: 2
000101-00:49:59 2963080 [ED-Normal] DEBUG service.SIDatabaseImpl - makePAT::tsHandle 7031992
000101-00:49:59 2963081 [pool-14] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f processSIChangedEvent size: 0
000101-00:49:59 2963082 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() received event code: 300c, eventData1(SI handle):0x69f9e8, eventData2: 2
000101-00:49:59 2963083 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() processing PMT event 0x300c type: 2
000101-00:49:59 2963103 [ED-Normal] DEBUG service.SIDatabaseImpl - makePMT::serviceHandle 6945256
000101-00:49:59 2963101 [pool-29] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3fprocessPATChangeEvent pat: org.cablelabs.impl.ocap.si.ProgramAssociationTa]
000101-00:49:59 2963117 [pool-25] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f processServiceDetailsChangedEvent size: 0
000101-00:49:59 2963136 [pool-25] INFO presentation.NetworkConditionMonitor - received PMT change notification - type: REMOVE
000101-00:49:59 2963138 [pool-25] INFO presentation.NetworkConditionMonitor - PMT removed
000101-00:49:59 2963138 [pool-25] DEBUG application.DemandExecQueue - ensureThread() called for ContextDemandExecQueue@1116065708[SystemContext@1283098960]
000101-00:49:59 2963139 [pool-25] DEBUG signalling.DavicSignallingMgr$AitMonitor - PMT change detected for ocap://f=0xa8cce40.0x4 org.cablelabs.impl.ocap.si.SIChangeEventImpl[source=org.cable]
000101-00:49:59 2963140 [pool-25] DEBUG signalling.DavicSignallingMgr$AitMonitor - stream was null
000101-00:49:59 2963151 [pool-25] DEBUG signalling.DavicSignallingMgr$AitMonitor - No AIT signaled on ocap://f=0xa8cce40.0x4.m=0x10; not filtering.
000101-00:49:59 2963158 [pool-4] INFO presentation.TSBServicePresentation - network condition event: NetworkConditionEvent.PMT_REMOVED, session: BroadcastSession - networkInterface:org.cable)
000101-00:49:59 2963159 [pool-4] INFO presentation.TSBServicePresentation - pmt removed - triggering switchToAlternativeContent
000101-00:49:59 2963159 [pool-4] DEBUG presentation.TSBServicePresentation - detachForLiveUse
000101-00:49:59 2963160 [pool-4] DEBUG presentation.TSBServicePresentation - already detached for live use
000101-00:49:59 2963160 [pool-4] DEBUG presentation.AbstractServicePresentation - switchToAlternativeContent - reason: 102, current state: STATE_ALTERNATIVE_CONTENT_SESSION_STARTED
000101-00:49:59 2963160 [pool-4] INFO presentation.AbstractServicePresentation - notifying alternative content - reason: 102
000101-00:49:59 2963161 [pool-4] INFO selection.DVRBroadcastServiceContextDelegate - presentationModeListener received alternativeContent notification - reason: 102
000101-00:49:59 2963161 [pool-4] INFO selection.DVRBroadcastServiceContextDelegate - setting currentState to PRESENTING
000101-00:49:59 2963163 [pool-4] INFO selection.ServiceContextImpl - delegate callback - presenting - reason 102: (id c4cfdfa4, PRESENTING, delegate: DVRBroadcastServiceContextDelegate - se)
000101-00:49:59 2963164 [pool-4] INFO selection.ServiceContextImpl - Received presenting in PRESENTING state - reason 102: (id c4cfdfa4, PRESENTING, delegate: DVRBroadcastServiceContextDeleg)
000101-00:49:59 2963498 [pool-4] INFO selection.ServiceContextImpl - posting AlternativeContentErrorEvent - reason 102: (id c4cfdfa4, PRESENTING, delegate: DVRBroadcastServiceContextDelegate)
000101-00:49:59 2963500 [pool-4] DEBUG selection.ServiceContextImpl - postEvent called with AlternativeContentErrorEvent[102]: (id c4cfdfa4, PRESENTING, delegate: DVRBroadcastServiceContextDe)
000101-00:49:59 2963501 [pool-4] DEBUG application.DemandExecQueue - ensureThread() called for ContextDemandExecQueue@-639226057[AppContext@968021681[636029]]
000101-00:49:59 2963501 [pool-4] DEBUG presentation.TSBServicePresentation - switchToAlternativeContent - reason: 102, live: true
000101-00:49:59 2963501 [pool-4] DEBUG presentation.TSBServicePresentation - deactivateAlarms
000101-00:49:59 >>> WatchTV: ****************************************************************************************
000101-00:49:59 >>> WatchTV: Selection succeeded with AlternativeContentErrorEvent[102]
000101-00:49:59 >>> WatchTV: Selection took 330.813 seconds with org.cablelabs.impl.service.javatv.selection.DVRServiceContextImpl@c4cfdfa4, PRESENTING, delegate: DVRBroadcastServiceContextDe]
000101-00:49:59 >>> WatchTV: ****************************************************************************************
000101-00:49:59 2963514 [pool-21] WARN timer.TimerMgrJava2 - deschedule called with an unscheduled spec: TVTS 0xcdc4a42d: [time=3000, absolute=false, repeat=false, regular=true, listener=org]
000101-00:49:59 2963541 [pool-21] DEBUG timer.TimerMgrJava2 - scheduleTimerSpec: org.cablelabs.impl.manager.timer.TimerMgrJava2$TVTimerImpl$1@fd026d51, spec: TVTS 0xdb4f673b: [time=3000, abso0
<000101-00:50:00><media/mpeos_tune.c:873>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 2) ENTER
<000101-00:50:00><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 2) ENTER
<000101-00:50:00><media/mpeos_tune.c:881>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 2) RETURNING tuner->brcm.band 0x2adac2a4
[ 2700.117000] *** 00:49:45.113 xpt: ***************************************************************************************
[ 2700.117000] *** 00:49:45.113 xpt: * WARNING: The max bitrate for the all-pass parser band has been increased to 81 Mbps.
[ 2700.117000] *** 00:49:45.113 xpt: * Check your usage mode.Software will decrease this when all pass mode is disabled.
[ 2700.117000] *** 00:49:45.113 xpt: ***************************************************************************************
000101-00:50:00 2964257 [pool-4] DEBUG application.DemandExecQueue - ContextDemandExecQueue finished...
<000101-00:50:01><media/mpeos_tune.c:873>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 2) ENTER
<000101-00:50:01><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 2) ENTER
<000101-00:50:01><media/mpeos_tune.c:881>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 2) RETURNING tuner->brcm.band 0x2adac2a4
[ 2701.827000] *** 00:49:46.822 xpt: ***************************************************************************************
[ 2701.827000] *** 00:49:46.822 xpt: * WARNING: The max bitrate for the all-pass parser band has been increased to 81 Mbps.
[ 2701.827000] *** 00:49:46.822 xpt: * Check your usage mode.Software will decrease this when all pass mode is disabled.
[ 2701.827000] *** 00:49:46.822 xpt: ***************************************************************************************
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
HandleSetDsgMode:: Already in Operational Mode 0. Ignoring this Set_DSG_mode!
000101-00:50:02 2966544 [pool-21] DEBUG application.DemandExecQueue - ContextDemandExecQueue finished...
000101-00:50:03 2966661 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() received event code: 300a, eventData1(SI handle):0x6a3bd0, eventData2: 2
000101-00:50:03 2966662 [ED-Normal] DEBUG service.SIDatabaseImpl - Received SI_EVENT_SERVICE_COMPONENT_UPDATE
000101-00:50:03 2966662 [ED-Normal] DEBUG service.SIDatabaseImpl - eventData1: 6962128
000101-00:50:03 2966662 [ED-Normal] DEBUG service.SIDatabaseImpl - eventData2: 2
000101-00:50:03 2966664 [ED-Normal] DEBUG service.SIDatabaseImpl - SI_CHANGE_TYPE_REMOVE received
000101-00:50:03 2966689 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() received event code: 300a, eventData1(SI handle):0x6a3c18, eventData2: 2
000101-00:50:03 2966717 [ED-Normal] DEBUG service.SIDatabaseImpl - Received SI_EVENT_SERVICE_COMPONENT_UPDATE
000101-00:50:03 2966718 [ED-Normal] DEBUG service.SIDatabaseImpl - eventData1: 6962200
000101-00:50:03 2966718 [ED-Normal] DEBUG service.SIDatabaseImpl - eventData2: 2
000101-00:50:03 2966719 [ED-Normal] DEBUG service.SIDatabaseImpl - SI_CHANGE_TYPE_REMOVE received
000101-00:50:03 2966725 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() received event code: 3006, eventData1(SI handle):0x69f7d8, eventData2: 1
000101-00:50:03 2966726 [ED-Normal] DEBUG service.SIDatabaseImpl - asyncEvent() processing PMT event 0x3006 type: 1
000101-00:50:03 2966727 [pool-28] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f processServiceDetailsChangedEvent size: 0
000101-00:50:03 2966728 [ED-Normal] DEBUG service.SIDatabaseImpl - makePMT::serviceHandle 6944728
000101-00:50:03 2967007 [pool-18] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Added object to PMT cache: org.cablelabs.impl.ocap.si.ProgramMapTableImpl0
000101-00:50:03 2967009 [pool-13] INFO timeshift.TimeShiftWindow - TSW 0xd925547b: notifyChange(org.cablelabs.impl.ocap.si.SIChangeEventImpl[source=org.cablelabs.impl.manager.service.SIDatab)
000101-00:50:03 2967011 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Enqueued request org.cablelabs.impl.manager.service.SIRequestServiceDetai]
000101-00:50:03 2967014 [pool-3] DEBUG service.SIRequestServiceDetails - @d92abb5 Attempting delivery
000101-00:50:03 2967073 [pool-11] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3fprocessServiceComponentChangeEvent javax.tv.service.navigation.ServiceComp]
000101-00:50:03 2967085 [pool-3] DEBUG service.SIRequestImpl - @d92abb5 Retrieval succeeded with [ org.cablelabs.impl.service.javatv.navigation.ServiceDetailsImpl@81471931[uniqueID=ServiceDet]
000101-00:50:03 2967087 [pool-7] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3fprocessServiceComponentChangeEvent javax.tv.service.navigation.ServiceCompo]
000101-00:50:03 2967110 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f retrieveServiceComponents() called with org.cablelabs.impl.service.javatvg
000101-00:50:03 2967132 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Enqueued request org.cablelabs.impl.manager.service.SIRequestServiceCompo]
000101-00:50:03 2967147 [pool-17] DEBUG service.SIRequestServiceComponents - @51b37309 Attempting delivery
000101-00:50:03 2967161 [pool-17] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Added object to service component cache: org.cablelabs.impl.service.javat]
000101-00:50:03 2967166 [pool-17] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Added object to service component cache: org.cablelabs.impl.service.javat]
000101-00:50:03 2967500 [pool-17] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:03 2967501 [pool-17] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:03 2967501 [pool-17] DEBUG user.UserPreferenceManager - getPod()
<000101-00:50:03><media/mpeos_tune.c:873>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 2) ENTER
<000101-00:50:03><media/mpeos_tune.c:666>getTuner(): <<< MPEOS_TUNE >>> getTuner(tunerId 2) ENTER
<000101-00:50:03><media/mpeos_tune.c:881>mpeos_getBand(): <<< MPEOS_TUNE >>> mpeos_getBand(tunerId 2) RETURNING tuner->brcm.band 0x2adac2a4
[ 2703.859000] *** 00:49:48.855 xpt: ***************************************************************************************
[ 2703.859000] *** 00:49:48.855 xpt: * WARNING: The max bitrate for the all-pass parser band has been increased to 81 Mbps.
[ 2703.859000] *** 00:49:48.855 xpt: * Check your usage mode.Software will decrease this when all pass mode is disabled.
[ 2703.859000] *** 00:49:48.855 xpt: ***************************************************************************************
000101-00:50:03 2967506 [pool-17] DEBUG service.SIRequestImpl - @51b37309 Retrieval succeeded with [ org.cablelabs.impl.service.javatv.navigation.ServiceComponentImpl@1a91f48e[uniqueID=Servic]
000101-00:50:03 2967509 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Enqueued request org.cablelabs.impl.manager.service.SIRequestServiceDetai]
000101-00:50:03 2967510 [pool-26] DEBUG service.SIRequestServiceDetails - @be956506 Attempting delivery
000101-00:50:03 2967512 [pool-26] DEBUG service.SIRequestImpl - @be956506 Retrieval succeeded with [ org.cablelabs.impl.service.javatv.navigation.ServiceDetailsImpl@9b1b932b[uniqueID=ServiceD]
000101-00:50:03 2967514 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Entry added PidMapEntry:[streamType 0x1,srcElemType 0x2,srcPID 0x981,recElemType 0x0,recPI]
000101-00:50:04 2967851 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Entry added PidMapEntry:[streamType 0x2,srcElemType 0x81,srcPID 0x980,recElemType 0x0,recP]
000101-00:50:04 2967855 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Entry added PidMapEntry:[streamType 0x6,srcElemType 0x0,srcPID 0x981,recElemType 0x0,recPI]
000101-00:50:04 2967856 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Enqueued request org.cablelabs.impl.manager.service.SIRequestServiceDetai]
000101-00:50:04 2967858 [pool-24] DEBUG service.SIRequestServiceDetails - @db5af763 Attempting delivery
000101-00:50:04 2967860 [pool-24] DEBUG service.SIRequestImpl - @db5af763 Retrieval succeeded with [ org.cablelabs.impl.service.javatv.navigation.ServiceDetailsImpl@9827bc28[uniqueID=ServiceD]
000101-00:50:04 2967861 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f retrieveProgramAssociationTable() called with ocap://f=0xa8cce40.0x2.m=0x0
000101-00:50:04 2967863 [pool-13] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Enqueued request org.cablelabs.impl.manager.service.SIRequestPAT@2b20b1a[]
000101-00:50:04 2967863 [pool-19] DEBUG service.SIRequestPAT - @2b20b1a Attempting delivery
000101-00:50:04 2967864 [pool-19] DEBUG service.SIDatabaseImpl - makePAT::tsHandle 7031992
000101-00:50:04 2967865 [pool-19] DEBUG service.SICacheImpl - org.cablelabs.impl.manager.service.SICacheImpl@a7d0be3f Added object to PAT cache: org.cablelabs.impl.ocap.si.ProgramAssociationT5
000101-00:50:04 2967866 [pool-19] DEBUG service.SIRequestImpl - @2b20b1a Retrieval succeeded with [ org.cablelabs.impl.ocap.si.ProgramAssociationTableImpl@8ff6ecd5 ]
000101-00:50:04 2967867 [pool-19] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: PATRequestor::notifySuccess called
000101-00:50:04 2967868 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[0]: 3
000101-00:50:04 2967868 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[1]: 1
000101-00:50:04 2967868 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[2]: 8
000101-00:50:04 2967869 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[3]: 6
000101-00:50:04 2967871 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[4]: 7
000101-00:50:04 2968205 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[5]: 5
000101-00:50:04 2968205 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[6]: 4
000101-00:50:04 2968206 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Program[7]: 2
000101-00:50:04 2968206 [pool-13] DEBUG timeshift.TimeShiftWindow - TSW 0xd925547b: loadPidMapTable: Entry added PidMapEntry:[streamType 0x7,srcElemType 0x0,srcPID 0x37,recElemType 0x0,recPID]
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
HandleSetDsgMode:: Already in Operational Mode 0. Ignoring this Set_DSG_mode!
000101-00:50:06 2970414 [Thread-2] DEBUG application.AppManager - getAppsDatabase returning global db due to privileged caller (or null): true
000101-00:50:06 2970415 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs - filter: org.cablelabs.impl.manager.snmp.SnmpAppsDatabaseMonitor@1affbdb4, known ids: [636027, 14000, 636029, 1]
000101-00:50:06 2970417 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=636029,names=[eng:WatchTV],code=2,bound=true,visibility=3,priority=230,baseDir=/usr/lo]
000101-00:50:06 2970419 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=636027,names=[eng:IDGSettingsApp],code=1,bound=true,visibility=0,priority=240,baseDir=]
000101-00:50:06 2970423 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=16028,names=[eng:Simple Watch TV],code=2,bound=true,visibility=3,priority=220,baseDir=]
000101-00:50:06 2970425 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=16026,names=[eng:Config (NFS)],code=2,bound=true,visibility=3,priority=220,baseDir=/us]
000101-00:50:06 2970427 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=16025,names=[eng:DVR Sample (NFS)],code=2,bound=true,visibility=3,priority=254,baseDir]
000101-00:50:06 2970430 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs adding entry: AppEntry[id=14000,names=[eng:Launcher],code=1,bound=true,visibility=3,priority=220,baseDir=/usr/lo]
000101-00:50:06 2970430 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs: size 6
000101-00:50:06 2970431 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs - filter: org.cablelabs.impl.manager.snmp.SnmpAppsDatabaseMonitor@1affbdb4, known ids: []
000101-00:50:06 2970431 [Thread-2] DEBUG application.AppDomainImpl - getAppIDs: size 0
000101-00:50:06 2970432 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:06 2970432 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-00:50:07 2970766 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:07 2970766 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-00:50:07 2970767 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:07 2970768 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-00:50:07 2970768 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:07 2970768 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-00:50:07 2970769 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:07 2970771 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-00:50:07 2970771 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:07 2970772 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-00:50:07 2970772 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:07 2970773 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-00:50:07 2970773 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:07 2970773 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-00:50:07 2970774 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:07 2970774 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-00:50:07 2970775 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:07 2970775 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
000101-00:50:07 2970775 [Thread-2] DEBUG user.UserPreferenceManager - getInstance()
000101-00:50:07 2970776 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language, Facility)
000101-00:50:07 2970777 [Thread-2] DEBUG user.UserPreferenceManager - read(Preference User Language)
000101-00:50:07 2970777 [Thread-2] DEBUG user.UserPreferenceManager - getPod()
!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0
HandleSetDsgMode:: Already in Operational Mode 0. Ignoring this Set_DSG_mode!
### 00:49:49.084 MPOD_EXT_CHAN: extended channel flow req rejected with error 3
<000101-00:50:08><mpod/mpeos_pod_extended_channel.c:289>flowReqFailedCb(): #####> ERROR <#####Flow type B_MPOD_EXT_FLOW_IP_U not handled

!!! Received Set_DSG_mode from CableCard !!!
Operational Mode (OOB=0, DSG=1, DSG1way=2 DSGAdvMode=3) = 0

scottdeboy
Offline
Joined: 2009-02-02
Points: 0

The log contains an IllegalStateException triggered by the TUNE_SYNC indication - I'll look closer at your log and review the NI state machine and follow up,
000101-00:49:58 2962380 [System-1] INFO application.AppExecQueue - Exception in AppExecQueue
000101-00:49:58 java.lang.IllegalStateException: Invalid transaction or state
at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$NIStateMachine.handleTuneSynced(Unknown Source)
at org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl$TuneRequest$1.run(Unknown Source)
at org.cablelabs.impl.manager.application.WorkerTask.run(Compiled Method)(Unknown Source)
at org.cablelabs.impl.manager.application.AppExecQueue$1.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
at java.lang.Thread.startup(Unknown Source)
The log fragment also shows the stack received a PMT_REMOVED indication while already in AlternativeContent:
From the log:
00101-00:49:59 2963139 [pool-25] DEBUG signalling.DavicSignallingMgr$AitMonitor - PMT change detected for ocap://f=0xa8cce40.0x4 org.cablelabs.impl.ocap.si.SIChangeEventImpl[source=org.cable]
000101-00:49:59 2963140 [pool-25] DEBUG signalling.DavicSignallingMgr$AitMonitor - stream was null
000101-00:49:59 2963151 [pool-25] DEBUG signalling.DavicSignallingMgr$AitMonitor - No AIT signaled on ocap://f=0xa8cce40.0x4.m=0x10; not filtering.
000101-00:49:59 2963158 [pool-4] INFO presentation.TSBServicePresentation - network condition event: NetworkConditionEvent.PMT_REMOVED, session: BroadcastSession - networkInterface:org.cable)
000101-00:49:59 2963159 [pool-4] INFO presentation.TSBServicePresentation - pmt removed - triggering switchToAlternativeContent
000101-00:49:59 2963159 [pool-4] DEBUG presentation.TSBServicePresentation - detachForLiveUse
000101-00:49:59 2963160 [pool-4] DEBUG presentation.TSBServicePresentation - already detached for live use
000101-00:49:59 2963160 [pool-4] DEBUG presentation.AbstractServicePresentation - switchToAlternativeContent - reason: 102, current state: STATE_ALTERNATIVE_CONTENT_SESSION_STARTED

stopiwalla
Offline
Joined: 2010-05-25
Points: 0

Thanks for pointing this out Scott.
I looked at the the NetworkInterfaceImpl.java and noticed how the handleTuneSynced() is addressed in TUNED_UNSYNC state, which is what works for me with the above mentioned changes to the MPEOS wrt the proper tuning events. Thus, when I am on a channel and decoding fine, I am in TUNED_SYNC state. Then when the cable feed is unplugged, it goes into TUNED_UNSYNC state and when I plug the cable back, and inform with the SYNC event, the decoding starts perfectly well (with the AlternateContentService in between while there is lost lock).
Now, if I repeat the above on a newly tuned channel which is decoding fine; I unhook the cable, I get the alternate content service, and it is in TUNED_UNSYNC state. Then if I channel change, the tuner status goes into RESERVED state --> TUNING --> TUNE_UNSYNC. In a few seconds a timeout occurs in the tuning state machine, which puts the tuner into RESERVED status again. Now if the cable feed is plugged back in, the alternate service content never goes away until I tune to another channel and everything is fine.
I tried handling the RESERVED state the same way that the TUNE_UNSYNC is handled in the handleTuneSynced() and the problem is solved!
Thus, my question once again to you:
1) Is the above fix a legal fix for the JAVA side of the stack?
2) If not, then what is a proper fix for it?

cpratt
Offline
Joined: 2008-12-18
Points: 0

I believe the proper fix is to not put the NI into RESERVED when the timer expires - but that will need to be examined from the NetworkInterfaceController angle to see if it causes any issues.
Please file an IT bug for this issue and we should be able to resolve it.
Thx!

stopiwalla
Offline
Joined: 2010-05-25
Points: 0

Thanks Craig. I have opened IT # 302 describing the above possible defect + fix.
ocap-ri.dev.java.net/issues/show_bug.cgi

stopiwalla
Offline
Joined: 2010-05-25
Points: 0

Thanks for the reply and clarification, Scott.
Does the MPE_CONTENT_PRESENTING event need to include which tuner this event is for esp., since there are two tuners on the box or it is only to notify the decoding session?

scottdeboy
Offline
Joined: 2009-02-02
Points: 0

The MPE_CONTENT_PRESENTING indication doesn't need to include which tuner the event is for - it is sent for for broadcast and non-broadcast service presentation (non-ongoing recorded service presentation as well as remote service presentation).
The stack registers a listener on the networkinterface used by the decoder if a networkinterface is used by the decoder, and sync and unsync events received via the network interface edlistener will result in a transition to altcontent & recovery.
One additional piece of information:
AlternativeContent is presented using drip feed with a black frame. The AlternativecontentErrorEvent is posted in response to receiving an MPE_STILL_FRAME_DECODED event in response to the call to mediaDripFeedRenderFrame. If mediaDripFeedRenderFrame does not sent an MPE_STILL_FRAME_DECODED event, the stack will not transition to AlternativeContent.
Scott