You are viewing an old version of this page. View the current version.

Compare with Current View Page History

Version 1 Next »

String pattern to search in receiver log

If you are using Notepad++ then search the below regular expression on receiver log to get initial level of understanding what is the issue then look for the timestamp for further analysis

New flash video|Error downloading segment|onPlayStateChanged|DRM Init error|Network down|Segment took too long to download|BufferLevel |Error while parsing media file|onMediaWarning|Event onMediaFailed|onMediaError|onMediaError Event timed out: PLAYERREADY|\"handler\":2\,|type -|XRE_NR_STATUS|Skip 
onLoadFinished notification, load not finished yet|onXREReady|state load|aamp play to end|entering AAMPGstPlayer_EndOfStreamReached|GST_MESSAGE_EOS|onMediaEnded|AAMPGstPlayer_OnGstPtsErrorCb|EXT-X-DISCONTINUITY|discontinuous buffer|CURL error|BAD URL|Sending error AAMP|native rec|/lib/rdk/runXRE: 
line|RDKBROWSER_RENDER_PROCESS_CRASHED|IP_AAMP_TUNETIME|\"handler\":2\}|Failed to create PlayReady DRM Session|aamp rew to beginning|Could not match URL, not appending eac3|XMLHttpRequest cannot load|AAMPGstPlayerPipeline|drm_Decrypt failed|video tune failed|Power Old State|rdk_xre_sleep|XRE_NR_EXIT|got 
First |AAMPGstPlayer|MyFlashAccessAdapter|Segment doesn't starts with|HangDetector|EXT-X-CUE|onAd|aamp eas manifest detected|ScheduleRetune|Discard ES Type|aamp_tune|\[AAMP_JS\]|WebProcess is unresponsive|video tune aborted|video tune|aamp changing profile|x-reason|RetryHandler|Buffer is running low|Trying 
to dispose element|Pipeline is not in playing|NotifyEOS|acquireLicense failed|acquisition failure|eDRM_KEY_ACQUSITION_TIMEOUT|seq gap|aamp warn - bad index|notifying aamp discontinuity|stopping injection|EOS received|AAMPGstPlayer_OnGstBufferUnderflowCb|AAMPGstPlayer::Discontinuity|HTTP RESPONSE 
CODE|onAdComplete|onAdStart|onAdProgress|onAdBreakComplete|encrypted to clear|clear to encrypted|AAMPLogNetworkError|AAMPLogABRInfo|AAMPLogNetworkLatency|switching to|seek_pos_seconds|Playback has been stalled|Period ID changed from|_M_range_check|PTS error|CreateDRMSession|Invalid source buffer size 
specified|No decoder available for type|aamp_stop|setrate

Successful working case & Functional call flow with Log Snippets

Channel change request from User ( It can be CH-UP/DOWN (or) Direct Numeric Keys ) For example below on snippet

2019 Jun 18 13:08:43.683432 arrisxg1v4 Receiver[15906]:  Thread-16365 [ECM] - XREKeyPressLog Keyevent sent to server: {"source":2065,"params":{"virtualKeyCode":"CHANNEL_UP","alt":false,"meta":false,"shift":false,"elapsedMs":-1093195288,"rawCode":0,"tid":"1ca60ae4-00ba-4dd3-9293-9c48207edcdb","control":false,"keySource":"physical"},"handler":2065,"phase":"PREVIEW","event":350,"timestamp":1560863323681,"name":"onPreviewKeyDown"}

Stop() called for current channel from JSPP

2019 Jun 18 13:08:43.813992 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - callMethodInBrowser -> calling stop
2019 Jun 18 13:08:43.815749 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - AAMPVideoEnd CAAMPWebVideoItem::~CAAMPWebVideoItem exit
2019 Jun 18 13:08:43.815864 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - CAAMPReplyTimeout stop: name=PLAYERREADY timeout=20000
2019 Jun 18 13:08:43.850443 arrisxg1v4 runAppManager.sh[15527]: 190618-13:08:43.837500 [mod=RDKBROWSER2, lvl=INFO] [tid=15872] onConsoleLog:rdkbrowser.cpp:990 [ConsoleAPI:15]: AAMPPlayer: stop : 09:08:43 GMT-0400 (EDT)
2019 Jun 18 13:08:43.815944 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - CAAMPReplyTimeout stop: name=MANIFESTHEAD timeout=10000
2019 Jun 18 13:08:43.855262 arrisxg1v4 runAppManager.sh[15527]: [AAMP_JS] Event() ctx=0x99fd80d0, type=13, jsCallback=0x993b9510
2019 Jun 18 13:08:43.816008 arrisxg1v4 Receiver[15906]: Thread-15906 [AVE-Log] - ~AVELog: Enter

AAMP stopping playback

2019 Jun 18 13:08:43.843209 arrisxg1v4 WPEWebProcess[16069]: sleep interrupted!
2019 Jun 18 13:08:43.843210 arrisxg1v4 WPEWebProcess[16069]: WaitForCachedFragmentAvailable video aborted
2019 Jun 18 13:08:43.843225 arrisxg1v4 WPEWebProcess[16069]: MPD fragment collector done
2019 Jun 18 13:08:43.843226 arrisxg1v4 WPEWebProcess[16069]: fragment injector done. track video
2019 Jun 18 13:08:43.844155 arrisxg1v4 WPEWebProcess[16069]: WaitForCachedFragmentAvailable audio aborted
2019 Jun 18 13:08:43.844177 arrisxg1v4 WPEWebProcess[16069]: fragment injector done. track audio
2019 Jun 18 13:08:43.844636 arrisxg1v4 WPEWebProcess[16069]: ClearProtectionEvent removing protection event!
2019 Jun 18 13:08:43.845792 arrisxg1v4 WPEWebProcess[16069]: entering AAMPGstPlayer_Stop keepLastFrame 0

....

2019 Jun 18 13:08:43.845807 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Stop 2111 > Remove periodicProgressCallbackIdleTaskId 36
2019 Jun 18 13:08:43.986792 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::stop: Pipeline state set to null
2019 Jun 18 13:08:43.986818 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::TearDownStream: mediaType 0
2019 Jun 18 13:08:43.987594 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::TearDownStream: exit mediaType = 0
2019 Jun 18 13:08:43.987612 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::TearDownStream: mediaType 1
2019 Jun 18 13:08:43.990211 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::TearDownStream: exit mediaType = 1
2019 Jun 18 13:08:43.990364 arrisxg1v4 WPEWebProcess[16069]: DestroyPipeline(): Destroying gstreamer pipeline
2019 Jun 18 13:08:43.990409 arrisxg1v4 WPEWebProcess[16069]: exiting AAMPGstPlayer_Stop
2019 Jun 18 13:08:43.990432 arrisxg1v4 WPEWebProcess[16069]: ClearPlaylistCache:6628 : cache size 0

New tune request reaching AAMP

2019 Jun 18 13:08:44.205349 arrisxg1v4 WPEWebProcess[16069]: Detected ContentType 3 (LINEAR_TV)
2019 Jun 18 13:08:44.205372 arrisxg1v4 WPEWebProcess[16069]: mLiveOffset: 15
2019 Jun 18 13:08:44.205445 arrisxg1v4 WPEWebProcess[16069]: aamp_tune: attempt: 1 format: DASH URL: http://127.0.0.1:9080/tsb?clientId=FOG_AAMP&recordedUrl=http%3A%2F%2Fodol-atsec-pan-08.linear-nat-pil.xcr.comcast.net%2FHBOLD_HD_NAT_17405_0_8320674223410413163.mpd%3Ftrred%3Dfalse&analyticsUrl=https%3A%2F%2Fanalytics.xcal.tv%2Fcomcast%2Ffog&money=%7B%22PARENT_ID%22%3A%22578595894704177%22%2C%22TRACE_ID%22%3A%22e5de25f4-b903-42ee-a872-3f6b95a3b29f%22%7D&ses=%7B%22PSI%22%3A%2279e2f978-e62a-4dec-a489-718c6354c9dd%22%2C%22PBI%22%3A2%7D&asset=%7B%22ID_TYPE%22%3A%22StreamId%22%2C%22CLASS%22%3A%22Linear%22%2C%22PLAYBACK_TYPE%22%3A%22FOG%22%2C%22INFO%22%3A%7B%7D%2C%22SECURITY%22%3A%22TRUE%22%2C%22RegulatoryClass%22%3A%22T6%22%2C%22IDS%22%3A%7B%22STRID%22%3A%228320674223410413163%22%7D%2C%22VSTRM%22%3A%7B%7D%7D&appName=STB-XG1V4&appVer=3.9s3&acId=9152925405816835684&devName=ipstb&devID=BC%3A64%3A4B%3A66%3A17%3AF8&phyID=6592514687820608349

AAMP requesting Manifest

2019 Jun 18 13:08:44.232833 arrisxg1v4 WPEWebProcess[16069]: aamp url: http://127.0.0.1:9080/tsb?clientId=FOG_AAMP&recordedUrl=http%3A%2F%2Fodol-atsec-pan-08.linear-nat-pil.xcr.comcast.net%2FHBOLD_HD_NAT_17405_0_8320674223410413163.mpd%3Ftrred%3Dfalse&analyticsUrl=https%3A%2F%2Fanalytics.xcal.tv%2Fcomcast%2Ffog&money=%7B%22PARENT_ID%22%3A%22578595894704177%22%2C%22TRACE_ID%22%3A%22e5de25f4-b903-42ee-a872-3f6b95a3b29f%22%7D&ses=%7B%22PSI%22%3A%2279e2f978-e62a-4dec-a489-718c6354c9dd%22%2C%22PBI%22%3A2%7D&asset=%7B%22ID_TYPE%22%3A%22StreamId%22%2C%22CLASS%22%3A%22Linear%22%2C%22PLAYBACK_TYPE%22%3A%22FOG%22%2C%22INFO%22%3A%7B%7D%2C%22SECURITY%22%3A%22TRUE%22%2C%22RegulatoryClass%22%3A%22T6%22%2C%22IDS%22%3A%7B%22STRID%22%3A%228320674223410413163%22%7D%2C%22VSTRM%22%3A%7B%7D%7D&appName=STB-XG1V4&appVer=3.9s3&acId=9152925405816835684&devName=ipstb&devID=BC%3A64%3A4B%3A66%3A17%3AF8&phyID=6592514687820608349

Manifest response

2019 Jun 18 13:08:44.452633 arrisxg1v4 WPEWebProcess[16069]: HttpRequestEnd: {"url":"http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/manifest.mpd","curlTime":0.2200,"times":{"total":0.2196,"connect":0.0008,"startTransfer":0.2189,"resolve":0.0002,"appConnect":0.0000,"preTransfer":0.0012,"redirect":0.1645,"dlSz":31640,"ulSz":1581},"responseCode":200}

Manifest parsing, prints indicate which period/adapatationSet/representation selected for playback

2019 Jun 18 13:08:44.455654 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::Init:2496 - MPD minupdateduration val 4 seconds
2019 Jun 18 13:08:44.455737 arrisxg1v4 WPEWebProcess[16069]: Init:2530 - Updated duration 28 seconds
2019 Jun 18 13:08:44.455757 arrisxg1v4 WPEWebProcess[16069]: currentPeriodIdx 0/1
2019 Jun 18 13:08:44.455789 arrisxg1v4 WPEWebProcess[16069]: Init:2621 duration 28.000000 durationMs 28.000000 mCurrentPeriodIdx 0 currentPeriodStart 0.000000 offsetFromStart 13.000000
2019 Jun 18 13:08:44.455807 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::Init:2639 - liveAdjust - Updated offSetFromStart[13.000000] duration [28.000000] currentPeriodStart[0.000000] MaxPeriodIdx[0]
2019 Jun 18 13:08:44.459152 arrisxg1v4 runAppManager.sh[15527]: 190618-13:08:44.457504 [mod=RDKBROWSER2, lvl=INFO] [tid=15872] onConsoleLog:rdkbrowser.cpp:990 [ConsoleAPI:15]: AAMPPlayerEvents: [AAMP_JS_EVENT] onStatusChanged status: 2 : 09:08:44 GMT-0400 (EDT)
2019 Jun 18 13:08:44.455835 arrisxg1v4 WPEWebProcess[16069]: Selected Period index 0, id 779632268
2019 Jun 18 13:08:44.459988 arrisxg1v4 runAppManager.sh[15527]: [AAMP_JS] Event() ctx=0x99fd80d0, type=13, jsCallback=0x993b9510
...
2019 Jun 18 13:08:44.455899 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3674 > Media[video] Adaptation set[0] RepIdx[-1] TrackCnt[1]
2019 Jun 18 13:08:44.456114 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3687 > Media[video] enabled
2019 Jun 18 13:08:44.456146 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3569 > Got the matching lang[en] AdapInx[1] RepIndx[0] AudioType[2]
2019 Jun 18 13:08:44.456161 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3674 > Media[audio] Adaptation set[1] RepIdx[0] TrackCnt[2]
2019 Jun 18 13:08:44.456467 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::UpdateTrackInfo:3940 Track 0 timeLineIndex 0 fragmentDescriptor.Number 2593398035
2019 Jun 18 13:08:44.456482 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::UpdateTrackInfo:3940 Track 1 timeLineIndex 0 fragmentDescriptor.Number 2593398035

Checking and processing content protection from fragmentCollector thread

2019 Jun 18 13:08:44.455920 arrisxg1v4 WPEWebProcess[16069]: [HHH]Comcast DRM Agnostic CENC system ID found!
2019 Jun 18 13:08:44.455947 arrisxg1v4 WPEWebProcess[16069]: _extractWVContentMetadataFromPssh:669 content meta data length : 1692
2019 Jun 18 13:08:44.455967 arrisxg1v4 WPEWebProcess[16069]: [HHH]Playready system ID found!
2019 Jun 18 13:08:44.456003 arrisxg1v4 WPEWebProcess[16069]: [HHH]Widevine system ID found!
2019 Jun 18 13:08:44.456023 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.456034 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
...
2019 Jun 18 13:08:44.456177 arrisxg1v4 WPEWebProcess[16069]: [HHH]Comcast DRM Agnostic CENC system ID found!
2019 Jun 18 13:08:44.456204 arrisxg1v4 WPEWebProcess[16069]: _extractWVContentMetadataFromPssh:669 content meta data length : 1692
2019 Jun 18 13:08:44.456227 arrisxg1v4 WPEWebProcess[16069]: [HHH]Playready system ID found!
2019 Jun 18 13:08:44.456263 arrisxg1v4 WPEWebProcess[16069]: [HHH]Widevine system ID found!
2019 Jun 18 13:08:44.456281 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.456292 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
...
2019 Jun 18 13:08:44.456303 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3687 > Media[audio] enabled
2019 Jun 18 13:08:44.456346 arrisxg1v4 WPEWebProcess[16069]: PrivateInstanceAAMP::SendEventAsync:797 event type 5
2019 Jun 18 13:08:44.456368 arrisxg1v4 WPEWebProcess[16069]: PrivateInstanceAAMP::SendEventAsync:797 event type 1

Prints indicating playback start position, mpd duration
2019 Jun 18 13:08:44.456513 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1643 Enter : Type[0] timeLineIndex 0 fragmentRepeatCount 0 skipTime 13.000000
2019 Jun 18 13:08:44.456538 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1710 [video] newPTS 40530.433711
2019 Jun 18 13:08:44.456554 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1714 [video] mFirstPTS 0.000000 -> 40530.433711
2019 Jun 18 13:08:44.456571 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1768 Exit :Type[0] timeLineIndex 0 fragmentRepeatCount 6 fragmentDescriptor.Number 779651997 fragmentTime 12.012000
2019 Jun 18 13:08:44.456590 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1643 Enter : Type[1] timeLineIndex 0 fragmentRepeatCount 0 skipTime 13.000000
2019 Jun 18 13:08:44.456626 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1710 [audio] newPTS 40528.449911
2019 Jun 18 13:08:44.456641 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1768 Exit :Type[1] timeLineIndex 5 fragmentRepeatCount 0 fragmentDescriptor.Number 779651996 fragmentTime 10.016000
2019 Jun 18 13:08:44.456657 arrisxg1v4 WPEWebProcess[16069]: Init:2682 offsetFromStart(13.000000) seekPosition(12.012000)
2019 Jun 18 13:08:44.458665 arrisxg1v4 WPEWebProcess[16069]: aamp: sending metadata event and duration update 28.000000
...
2019 Jun 18 13:08:44.458737 arrisxg1v4 WPEWebProcess[16069]: UpdateRefreshPlaylistInterval(): maxRefreshPlaylistIntervalSecs (4.032000)
2019 Jun 18 13:08:44.458782 arrisxg1v4 WPEWebProcess[16069]: TuneHelper:3810 Updated seek_pos_seconds 12.012000

Creating Gstreamer pipeline

2019 Jun 18 13:08:44.458801 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Flush:2665 Pipeline is NULL
2019 Jun 18 13:08:44.458816 arrisxg1v4 WPEWebProcess[16069]: TuneHelper : mFormat 2, mAudioFormat 2
2019 Jun 18 13:08:44.458831 arrisxg1v4 WPEWebProcess[16069]: SetVideoZoom :: ZoomMode 0, using_playersinkbin = 0, video_sink =(nil)
2019 Jun 18 13:08:44.458844 arrisxg1v4 WPEWebProcess[16069]: SetVideoMute: muted 0, using_playersinkbin = 0, video_sink =(nil)
2019 Jun 18 13:08:44.458861 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::setVolumeOrMuteUnMute() 2570 > volume = 1.000000, using_playersinkbin = 0, audio_sink = (nil)
2019 Jun 18 13:08:44.458872 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Configure 1874 > format 2 audioFormat 2
2019 Jun 18 13:08:44.458883 arrisxg1v4 WPEWebProcess[16069]: CreatePipeline(): Creating gstreamer pipeline
2019 Jun 18 13:08:44.459115 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayerPipeline buffering_enabled 1
2019 Jun 18 13:08:44.459129 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Configure 1898 > Closing stream 0 old format = 0, new format = 2
2019 Jun 18 13:08:44.459139 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Configure 1898 > Closing stream 1 old format = 0, new format = 2
2019 Jun 18 13:08:44.459154 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::TearDownStream: exit mediaType = 0
2019 Jun 18 13:08:44.459166 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer_SetupStream - using playbin
2019 Jun 18 13:08:44.459982 arrisxg1v4 WPEWebProcess[16069]: playbin flags1: 0x617
2019 Jun 18 13:08:44.460132 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::TearDownStream: exit mediaType = 1
2019 Jun 18 13:08:44.460143 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer_SetupStream - using playbin
2019 Jun 18 13:08:44.460643 arrisxg1v4 WPEWebProcess[16069]: playbin flags1: 0x617
2019 Jun 18 13:08:44.462684 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer: found_source
2019 Jun 18 13:08:44.462700 arrisxg1v4 WPEWebProcess[16069]: Found source for bin2
2019 Jun 18 13:08:44.470870 arrisxg1v4 Receiver[15906]: Thread-16346 [XREWebSocketConnection] - heartbeat warning cleared
2019 Jun 18 13:08:44.472502 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer: found_source
2019 Jun 18 13:08:44.472526 arrisxg1v4 WPEWebProcess[16069]: Found source for bin1

DRM session creation "keysystem is" indicates which DRM is selected

2019 Jun 18 13:08:44.473503 arrisxg1v4 WPEWebProcess[16069]: Found Widevine encryption from manifest
2019 Jun 18 13:08:44.473522 arrisxg1v4 WPEWebProcess[16069]: queueing protection event for keysystem: edef8ba9-79d6-4ace-a3c8-27dcd51d21ed initdata size: 91
2019 Jun 18 13:08:44.473616 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:44.473638 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:44.473655 arrisxg1v4 WPEWebProcess[16069]: keysystem is com.widevine.alpha
2019 Jun 18 13:08:44.473671 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.473684 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:44.473702 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:915 Selected slot 1 for keyId 0cc84940-1541-ef5d-cc5f-1f5317cb417e sessionType video
2019 Jun 18 13:08:44.473737 arrisxg1v4 WPEWebProcess[16069]: AAMPOCDMSession :: enter
2019 Jun 18 13:08:44.473753 arrisxg1v4 WPEWebProcess[16069]: initAampDRMSession :: enter
2019 Jun 18 13:08:44.473780 arrisxg1v4 WPEWebProcess[16069]: initAampDRMSession :: exit
2019 Jun 18 13:08:44.473795 arrisxg1v4 WPEWebProcess[16069]: AAMPOCDMSession :: exit
2019 Jun 18 13:08:44.473814 arrisxg1v4 WPEWebProcess[16069]: generateAampDRMSession :: enter

FragmentCollector downloading and injecting init headers

2019 Jun 18 13:08:44.485592 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::FetcherLoop:4523 - fetch initialization fragments
2019 Jun 18 13:08:44.485754 arrisxg1v4 WPEWebProcess[16069]: aamp url: http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/779632268-4/HBOLD_HD_NAT_17405_0_8320674223410413163-eac3/track-audio-repid-root_audio104-tc-0-enc-cenc-header.mp4
2019 Jun 18 13:08:44.493282 arrisxg1v4 WPEWebProcess[16069]: aamp url: http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/abr/779632268-2/Bandwidth-2107200-init.seg
2019 Jun 18 13:08:44.570249 arrisxg1v4 WPEWebProcess[16069]: HttpRequestEnd: {"url":"http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/779632268-4/HBOLD_HD_NAT_17405_0_8320674223410413163-eac3/track-audio-repid-root_audio104-tc-0-enc-cenc-header.mp4","curlTime":0.0840,"times":{"total":0.0843,"connect":0.0004,"startTransfer":0.0842,"resolve":0.0001,"appConnect":0.0000,"preTransfer":0.0006,"redirect":0.0000,"dlSz":6967,"ulSz":399},"responseCode":200}
2019 Jun 18 13:08:44.570280 arrisxg1v4 WPEWebProcess[16069]: UpdateVideoEnd:T:6 br:213600 err:200 dur:0.000000 taTop:0.000000 ttTop:0.000000 tot:0.000000 n
2019 Jun 18 13:08:44.570660 arrisxg1v4 WPEWebProcess[16069]: Sending segment event for mediaType[1]. start 40530433593750 stop 18446744073709551615 rate 1.000000 applied_rate 1.000000
2019 Jun 18 13:08:44.585544 arrisxg1v4 WPEWebProcess[16069]: HttpRequestEnd: {"url":"http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/abr/779632268-2/Bandwidth-2107200-init.seg","curlTime":0.0930,"times":{"total":0.0921,"connect":0.0007,"startTransfer":0.0888,"resolve":0.0004,"appConnect":0.0000,"preTransfer":0.0074,"redirect":0.0000,"dlSz":7062,"ulSz":327},"responseCode":200}
2019 Jun 18 13:08:44.586151 arrisxg1v4 WPEWebProcess[16069]: Sending segment event for mediaType[0]. start 40530433593750 stop 18446744073709551615 rate 1.000000 applied_rate 1.000000

Gstreamer layer detects encryption for Audio and Video and suitable Decryptor plugin and initialized

2019 Jun 18 13:08:44.570753 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer_SendPendingEvents pushing protection event! mediatype: 1
2019 Jun 18 13:08:44.572607 arrisxg1v4 WPEWebProcess[16069]: Setting WideWine as preferred drm
2019 Jun 18 13:08:44.575963 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer setting aamp instance for aampwidevinedecryptor2 decryptor

2019 Jun 18 13:08:44.585576 arrisxg1v4 WPEWebProcess[16069]: [ABRManager] getBandwidthOfProfile:525 No profiles
2019 Jun 18 13:08:44.589276 arrisxg1v4 WPEWebProcess[16069]: Setting WideWine as preferred drm
2019 Jun 18 13:08:44.600250 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer setting aamp instance for aampwidevinedecryptor3 decryptor
2019 Jun 18 13:08:44.661895 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:44.661933 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:44.661954 arrisxg1v4 WPEWebProcess[16069]: keysystem is com.widevine.alpha
2019 Jun 18 13:08:44.661978 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.661994 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:44.662012 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:876 Session created/inprogress with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e at slot 1, can reuse same for audio

FragmentCollector proceeds with fragment download/injection

2019 Jun 18 13:08:44.586592 arrisxg1v4 WPEWebProcess[16069]: aamp: ready to collect fragments. mpd 0x197d90
2019 Jun 18 13:08:44.586611 arrisxg1v4 WPEWebProcess[16069]: MPD has 1 periods current period index 0
2019 Jun 18 13:08:44.586697 arrisxg1v4 WPEWebProcess[16069]: aamp url: http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/779632268-4/HBOLD_HD_NAT_17405_0_8320674223410413163-eac3/track-audio-repid-root_audio104-tc-0-enc-cenc-frag-779651996.mp4
2019 Jun 18 13:08:44.675613 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - Event onTuned({})
2019 Jun 18 13:08:44.675700 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - CAAMPWebVideoItem::setVideoTuned
2019 Jun 18 13:08:44.675746 arrisxg1v4 Receiver[15906]: Thread-15906 [VideoResource] - reportPlaying sending onStreamPlaying
2019 Jun 18 13:08:44.692840 arrisxg1v4 WPEWebProcess[16069]: HttpRequestEnd: {"url":"http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/779632268-4/HBOLD_HD_NAT_17405_0_8320674223410413163-eac3/track-audio-repid-root_audio104-tc-0-enc-cenc-frag-779651996.mp4","curlTime":0.1060,"times":{"total":0.1060,"connect":0.0055,"startTransfer":0.0823,"resolve":0.0052,"appConnect":0.0000,"preTransfer":0.0057,"redirect":0.0000,"dlSz":49087,"ulSz":407},"responseCode":200}
...
2019 Jun 18 13:08:44.692989 arrisxg1v4 WPEWebProcess[16069]: aamp url: http://127.0.0.1:9080/manifests/fd006adb-316c-4aaf-a30c-bf532ef350ec/abr/779632268-2/779651997.seg

DRM license request in progress

2019 Jun 18 13:08:44.745282 arrisxg1v4 WPEWebProcess[16069]: generateAampDRMSession :: sessionId : ksidE173EC32
2019 Jun 18 13:08:44.745336 arrisxg1v4 WPEWebProcess[16069]: destination url is https://mds.ccp.xcal.tv
2019 Jun 18 13:08:44.745364 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1045 [HHH]contentMetaData length=1692
2019 Jun 18 13:08:44.745424 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1078 MDS server spcific conent metadata found in initdata
2019 Jun 18 13:08:44.745480 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1108 access token is available
2019 Jun 18 13:08:44.745555 arrisxg1v4 WPEWebProcess[16069]: [HHH] Before calling SecClient_AcquireLicense-----------
2019 Jun 18 13:08:44.745569 arrisxg1v4 WPEWebProcess[16069]: destinationURL is mds.ccp.xcal.tv
2019 Jun 18 13:08:44.745582 arrisxg1v4 WPEWebProcess[16069]: MoneyTrace[trace-id=e5de25f4-b903-42ee-a872-3f6b95a3b29f;parent-id=2473532010524596290;span-id=1560863324745]
2019 Jun 18 13:08:44.745594 arrisxg1v4 WPEWebProcess[16069]: keySystem is com.widevine.alpha
2019 Jun 18 13:08:44.765810 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer Found --> brcmvideodecoder = 0xb232ee78
2019 Jun 18 13:08:44.766483 arrisxg1v4 Receiver[15906]: Thread-15906 [XREApplication] - xre transaction complete: 1ca60ae4-00ba-4dd3-9293-9c48207edcdb,1088
2019 Jun 18 13:08:44.768226 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:44.768247 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:44.768266 arrisxg1v4 WPEWebProcess[16069]: keysystem is com.widevine.alpha
2019 Jun 18 13:08:44.768290 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.768309 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:44.768329 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:876 Session created/inprogress with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e at slot 1, can reuse same for video

License acquisition success

2019 Jun 18 13:08:45.664064 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1220 acquireLicense SUCCESS! license request attempt 1; response code : sec_client 0
2019 Jun 18 13:08:45.665123 arrisxg1v4 runAppManager.sh[15527]: set generic heap 1, secure heap 2span-name=snd-msg trace-id=e5de25f4-b903-42ee-a872-3f6b95a3b29f;parent-id=-101473692534903567;span-id=-7616813685635720481 span-success=true start-time=Tue Jun 18 13:08:45 2019
2019 Jun 18 13:08:45.665434 arrisxg1v4 runAppManager.sh[15527]: span-duration=0.638453
2019 Jun 18 13:08:45.665673 arrisxg1v4 runAppManager.sh[15527]: SecClient-Status: 0, 0, 200, 0, e5de25f4-b903-42ee-a872-3f6b95a3b29f, 1560863324745, -101473692534903567
2019 Jun 18 13:08:45.665902 arrisxg1v4 runAppManager.sh[15527]: SecClient-PerfTime: 0, 0.918269, 0.638453
2019 Jun 18 13:08:46.002655 arrisxg1v4 WPEWebProcess[16069]: processKey: Key Usable!
2019 Jun 18 13:08:46.004196 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1329 Key Ready for video stream
2019 Jun 18 13:08:46.024009 arrisxg1v4 runAppManager.sh[15527]: span-name=acq-lic trace-id=e5de25f4-b903-42ee-a872-3f6b95a3b29f;parent-id=1560863324745;span-id=-101473692534903567 span-success=true start-time=Tue Jun 18 13:08:44 2019
2019 Jun 18 13:08:46.032575 arrisxg1v4 runAppManager.sh[15527]: span-duration=0.918269
2019 Jun 18 13:08:46.034516 arrisxg1v4 runAppManager.sh[15527]: [AAMP_JS] Event() ctx=0x99fd80d0, type=22, jsCallback=0x993b94b0
2019 Jun 18 13:08:46.035152 arrisxg1v4 runAppManager.sh[15527]: AAMP_JSListener_DRMMetadata code 0 Description accessAttributeStatus
2019 Jun 18 13:08:46.004226 arrisxg1v4 WPEWebProcess[16069]: Sending DRMMetaData
2019 Jun 18 13:08:46.004263 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:971 Found drm session READY with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e - Reusing drm session for audio
2019 Jun 18 13:08:46.006478 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:971 Found drm session READY with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e - Reusing drm session for video
2019 Jun 18 13:08:46.031797 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:46.031819 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:46.031835 arrisxg1v4 WPEWebProcess[16069]: keysystem is com.widevine.alpha
2019 Jun 18 13:08:46.031857 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:46.031868 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:46.031883 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:876 Session created/inprogress with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e at slot 1, can reuse same for audio
2019 Jun 18 13:08:46.031928 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:971 Found drm session READY with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e - Reusing drm session for audio
2019 Jun 18 13:08:46.032364 arrisxg1v4 WPEWebProcess[16069]: IsSourceUHD viddec (0xb232ee78) --> says width 1920, height 1080
2019 Jun 18 13:08:46.039716 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:46.039739 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:46.039753 arrisxg1v4 WPEWebProcess[16069]: keysystem is com.widevine.alpha
2019 Jun 18 13:08:46.039772 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:46.039784 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:46.039801 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:876 Session created/inprogress with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e at slot 1, can reuse same for video
2019 Jun 18 13:08:46.039839 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:971 Found drm session READY with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e - Reusing drm session for video

Finally tune succeeded and tune time print will have the statistics

2019 Jun 18 13:08:46.114091 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer_OnVideoFirstFrameBrcmVidDecoder. got First Video Frame
2019 Jun 18 13:08:46.115016 arrisxg1v4 WPEWebProcess[16069]: IP_AAMP_TUNETIME:4,0,1560863324205,27,220,0,0,0,0,0,0,0,287,93,0,280,84,0,487,247,0,2107200,381,106,0,0,268,1532,0,271,918,340,75,74,364,1909,3,21,0
2019 Jun 18 13:08:46.182019 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - IP_EX_CONTENT_URL:http://127.0.0.1:9080/tsb?clientId=FOG_AAMP&recordedUrl=http://ccr.linear-nat-pil-red.xcr.comcast.net/HBOLD_HD_NAT_17405_0_8320674223410413163.m3u8 DurationMs:28000
2019 Jun 18 13:08:46.182093 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - IP_TUNETIME:3,2.2,1.7

2019 Jun 18 13:08:46.182139 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - IP_EX_TUNETIME:3,2.246,1.668,0.336,0.247,0.000,1.553,0.109,0.001,0.000,0.000,0.487,1.532,1,0.220,1,0.000,1,0.530,1,21,0,1,0,0,28,1,0.000,2,1
2019 Jun 18 13:08:46.182644 arrisxg1v4 Receiver[15906]: Thread-15906 [AAMP-WEB] - New flash video is playing. Duration=28000
2019 Jun 18 13:08:46.182691 arrisxg1v4 Receiver[15906]: Thread-15906 [ECM] - New flash video is playing. Duration=28000 hasTSB=1

Actual receiver log for the above snippets

  • No labels

DISCLAIMER: Please note that the use of the RDK Wiki is subject to its Privacy Policy & Terms of Use. In addition, this Wiki may be accessed by all RDK licensees and their contractors.