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

Compare with Current View Page History

« Previous Version 2 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

1613139308:106 : [AAMP-PLAYER]AAMPGstPlayer::Flush:3250 Pipeline state NULL, ret 1
1613139308:106 : [AAMP-PLAYER]AAMPGstPlayer::Flush:3253 Pipeline is not in playing/paused state, hence resetting it
1613139308:106 : [AAMP-PLAYER]entering AAMPGstPlayer_Stop keepLastFrame 1
1613139308:106 : [AAMP-PLAYER]AAMPGstPlayer::Stop: Pipeline state set to null
1613139308:106 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 0
1613139308:106 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 1
1613139308:106 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 2
1613139308:107 : [AAMP-PLAYER]DestroyPipeline(): Destroying gstreamer pipeline
1613139308:107 : [AAMP-PLAYER]exiting AAMPGstPlayer_Stop
1613139308:107 : [AAMP-PLAYER]SetVideoZoom :: ZoomMode 0, using_playersinkbin = 0, video_sink =(nil)
1613139308:107 : [AAMP-PLAYER]SetVideoMute: muted 0, using_playersinkbin = 0, video_sink =(nil)

New tune request reaching AAMP

http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/main.mpd
1613139307: 97 : [AAMP-PLAYER]PrivateInstanceAAMP::ConfigureDashParallelFragmentDownload:8112 DASH Paraller Frag DL Config [1]
1613139307: 97 : [AAMP-PLAYER]PrivateInstanceAAMP::ConfigureRetuneForGSTInternalError:8168 GST Internal Stream Error Retune Config [1]
1613139307: 97 : [AAMP-PLAYER]Enabling Westeros Sink
1613139307: 97 : [AAMP-PLAYER]FOREGROUND PLAYER[0] aamp_tune: attempt: 1 format: DASH URL: http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/main.mpd
1613139307: 97 : [AAMP-PLAYER]TeardownStream:4530 mProgressReportFromProcessDiscontinuity:0 mDiscontinuityTuneOperationId:0 newTune:1

AAMP requesting Manifest

1613139307:101 : [AAMP-PLAYER]aamp url:3,3,0,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/main.mpd

Manifest response

1613139307:603 : [AAMP-PLAYER]HttpRequestEnd: 3,3,200,0.5020,0.5011,0.2561,0.5005,0.0127,0.0000,0.2563,0.0000,10059,278,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/main.mpd

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

1613139308:149 : [AAMP-PLAYER]Found source for video
1613139308:150 : [AAMP-PLAYER]bus_sync_handler: Received GST_MESSAGE_ASYNC_DONE message
1613139308:151 : [AAMP-PLAYER]AAMPGstPlayerPipeline READY -> PAUSED (pending VOID_PENDING)
1613139308:151 : [AAMP-PLAYER]msg type: async-done
1613139308:151 : [AAMP-PLAYER]PrivateInstanceAAMP::SendEventAsync:2592 event type  14
1613139308:151 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=14)(state=4)
1613139308:151 : [AAMP-PLAYER]AAMP_EVENT_STATE_CHANGED: 4
1613139308:151 : [AAMP-PLAYER]aamp-cli> 
1613139308:151 : [AAMP-PLAYER]fragment injector started. track audio
1613139308:151 : [AAMP-PLAYER]fragment injector started. track video
1613139308:158 : [AAMP-PLAYER]aamp: ready to collect fragments. mpd 0x9d75f0
1613139308:158 : [AAMP-PLAYER]MPD has 1 periods current period index 0
1613139308:158 : [AAMP-PLAYER]PushNextFragment:1811 Type[1] update startTime to 0
1613139308:158 : [AAMP-PLAYER]aamp url:0,1,1,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/de_001.mp3
1613139308:158 : [AAMP-PLAYER]PushNextFragment:1811 Type[0] update startTime to 0
1613139308:158 : [AAMP-PLAYER]aamp url:0,0,0,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/480p_001.m4s

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

1613139308:107 : [AAMP-PLAYER]CreatePipeline(): Creating gstreamer pipeline
1613139308:107 : [AAMP-PLAYER]AAMPGstPlayerPipeline buffering_enabled 1
1613139308:107 : [AAMP-PLAYER]AAMPGstPlayer::Configure 2363 > Closing stream 0 old format = 0, new format = 2
1613139308:107 : [AAMP-PLAYER]AAMPGstPlayer::Configure 2363 > Closing stream 1 old format = 0, new format = 2
1613139308:107 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 0
1613139308:107 : [AAMP-PLAYER]AAMPGstPlayer_SetupStream - using playbin
1613139308:116 : [AAMP-PLAYER]AAMPGstPlayer_SetupStream - using westerossink
1613139308:127 : [AAMP-PLAYER]playbin flags1: 0x617
1613139308:127 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 1
1613139308:127 : [AAMP-PLAYER]AAMPGstPlayer_SetupStream - using playbin
1613139308:128 : [AAMP-PLAYER]playbin flags1: 0x617
1613139308:128 : [AAMP-PLAYER]AAMPGstPlayerPipeline NULL -> READY (pending PAUSED)

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

1613139307:613 : [AAMP-PLAYER]PrivateStreamAbstractionMPD::Init:4281 - fetch initialization fragments
1613139307:614 : [AAMP-PLAYER]aamp url:2,7,1,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/de_init.m4s
1613139307:614 : [AAMP-PLAYER]aamp url:2,6,0,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/480p_init.m4s
1613139307:858 : [AAMP-PLAYER]HttpRequestEnd: 2,6,200,0.2440,0.2442,0.0002,0.2441,0.0002,0.0002,0.0003,0.0000,811,288,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/480p_init.m4s
1613139308:106 : [AAMP-PLAYER]HttpRequestEnd: 2,7,200,0.4920,0.4918,0.2455,0.4916,0.0001,0.0000,0.2457,0.0000,741,286,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/de_init.m4s

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

1613139308:151 : [AAMP-PLAYER]fragment injector started. track audio
1613139308:151 : [AAMP-PLAYER]fragment injector started. track video
1613139308:158 : [AAMP-PLAYER]aamp: ready to collect fragments. mpd 0x9d75f0
1613139308:158 : [AAMP-PLAYER]MPD has 1 periods current period index 0
1613139308:158 : [AAMP-PLAYER]PushNextFragment:1811 Type[1] update startTime to 0
1613139308:158 : [AAMP-PLAYER]aamp url:0,1,1,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/de_001.mp3
1613139308:158 : [AAMP-PLAYER]PushNextFragment:1811 Type[0] update startTime to 0
1613139308:158 : [AAMP-PLAYER]aamp url:0,0,0,http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/dash/480p_001.m4s

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

1613139308:681 : [AAMP-PLAYER]msg type: async-done
1613139308:685 : [AAMP-PLAYER]AAMPGstPlayer_OnFirstVideoFrameCallback. got First Video Frame
1613139308:685 : [AAMP-PLAYER]FOREGROUND PLAYER[0] IP_AAMP_TUNETIME:4,0,1613139307097,4,502,0,0,0,0,0,0,0,517,244,0,517,492,0,1061,489,0,1400000,1061,492,0,0,0,0,0,0,0,0,0,0,1105,1588,2,20,1,0,0
1613139308:685 : [AAMP-PLAYER]AAMP=>XRE: 2219,2137380,0,506,0,0,35,502,0,1717,1047,0,1,900000,0,2137380,2137886,2137886,2137886,2138933,2138968,20,1,1,-1768394611
1613139308:685 : [AAMP-PLAYER]AAMP=>XRE: 2219,2137380,0,506,0,0,35,502,0,1717,1047,0,1,900000,0,2137380,2137886,2137886,2137886,2138933,2138968,20,1,1,-1768394611
1613139308:685 : [AAMP-PLAYER]Anomaly evt:2 msg:Tune attempt#1. VOD:DASH/Clear URL:http://cpetestutility.stb.r53.xcal.tv/VideoTestStream/main.mpd
1613139308:685 : [AAMP-PLAYER]PrivateInstanceAAMP::SendEventAsync:2592 event type  26
1613139308:685 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=26)
1613139308:685 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=14)(state=8)
1613139308:685 : [AAMP-PLAYER]AAMP_EVENT_STATE_CHANGED: 8
1613139308:685 : [AAMP-PLAYER]AAMP_EVENT_TUNED
1613139308:685 : [AAMP-PLAYER]aamp: - sent tune event on Tune Completion.



  • 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.