Page History

...

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

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.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 456003 arrisxg1v4 WPEWebProcess[16069]: Selected Period index 0, id 779632268[HHH]Widevine system ID found!
2019 Jun 18 13:08:44.459988 456023 arrisxg1v4 runAppManager.shWPEWebProcess[1552716069]: [AAMP_JS] Event() ctx=0x99fd80d0, type=13, jsCallback=0x993b9510
..._extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.455899 456034 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD_extractKeyIdFromPssh::StreamSelection 3674 > Media[video] Adaptation set[0] RepIdx[-1] TrackCnt[1]642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
...
2019 Jun 18 13:08:44.456114 456177 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3687 > Media[video] enabled[HHH]Comcast DRM Agnostic CENC system ID found!
2019 Jun 18 13:08:44.456146 456204 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3569 > Got the matching lang[en] AdapInx[1] RepIndx[0] AudioType[2]_extractWVContentMetadataFromPssh:669 content meta data length : 1692
2019 Jun 18 13:08:44.456161 456227 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3674 > Media[audio] Adaptation set[1] RepIdx[0] TrackCnt[2][HHH]Playready system ID found!
2019 Jun 18 13:08:44.456467 456263 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::UpdateTrackInfo:3940 Track 0 timeLineIndex 0 fragmentDescriptor.Number 2593398035[HHH]Widevine system ID found!
2019 Jun 18 13:08:44.456482 456281 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD_extractKeyIdFromPssh::UpdateTrackInfo:3940 Track 1 timeLineIndex 0 fragmentDescriptor.Number 2593398035

Checking and processing content protection from fragmentCollector thread

602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.455920 456292 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_extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
...
2019 Jun 18 13:08:44.455967 456303 arrisxg1v4 WPEWebProcess[16069]: [HHH]Playready system ID found!PrivateStreamAbstractionMPD::StreamSelection 3687 > Media[audio] enabled
2019 Jun 18 13:08:44.456003 456346 arrisxg1v4 WPEWebProcess[16069]: [HHH]Widevine system ID found!PrivateInstanceAAMP::SendEventAsync:797 event type 5
2019 Jun 18 13:08:44.456023 456368 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPsshPrivateInstanceAAMP:602 wv keyid: 0cc84940-1541-ef5d:SendEventAsync:797 event type 1

Prints indicating playback start position, mpd duration-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.456034 456513 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
...SkipFragments:1643 Enter : Type[0] timeLineIndex 0 fragmentRepeatCount 0 skipTime 13.000000
2019 Jun 18 13:08:44.456177 456538 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1710 [HHH]Comcast DRM Agnostic CENC system ID found!video] newPTS 40530.433711
2019 Jun 18 13:08:44.456204 456554 arrisxg1v4 WPEWebProcess[16069]: _extractWVContentMetadataFromPssh:669 content meta data length : 1692SkipFragments:1714 [video] mFirstPTS 0.000000 -> 40530.433711
2019 Jun 18 13:08:44.456227 456571 arrisxg1v4 WPEWebProcess[16069]: [HHH]Playready system ID found!SkipFragments:1768 Exit :Type[0] timeLineIndex 0 fragmentRepeatCount 6 fragmentDescriptor.Number 779651997 fragmentTime 12.012000
2019 Jun 18 13:08:44.456263 456590 arrisxg1v4 WPEWebProcess[16069]: SkipFragments:1643 Enter : Type[HHH]Widevine system ID found!1] timeLineIndex 0 fragmentRepeatCount 0 skipTime 13.000000
2019 Jun 18 13:08:44.456281 456626 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.456292 SkipFragments:1710 [audio] newPTS 40528.449911
2019 Jun 18 13:08:44.456641 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
...SkipFragments:1768 Exit :Type[1] timeLineIndex 5 fragmentRepeatCount 0 fragmentDescriptor.Number 779651996 fragmentTime 10.016000
2019 Jun 18 13:08:44.456303 456657 arrisxg1v4 WPEWebProcess[16069]: PrivateStreamAbstractionMPD::StreamSelection 3687 > Media[audio] enabledInit:2682 offsetFromStart(13.000000) seekPosition(12.012000)
2019 Jun 18 13:08:44.456346 458665 arrisxg1v4 WPEWebProcess[16069]: PrivateInstanceAAMP::SendEventAsync:797 event type 5aamp: sending metadata event and duration update 28.000000
...
2019 Jun 18 13:08:44.456368 458737 arrisxg1v4 WPEWebProcess[16069]: PrivateInstanceAAMP::SendEventAsync:797 event type 1Prints indicating playback start position, mpd duration
UpdateRefreshPlaylistInterval(): maxRefreshPlaylistIntervalSecs (4.032000)
2019 Jun 18 13:08:44.456513 458782 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
...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.458737 473503 arrisxg1v4 WPEWebProcess[16069]: UpdateRefreshPlaylistInterval(): maxRefreshPlaylistIntervalSecs (4.032000)Found Widevine encryption from manifest
2019 Jun 18 13:08:44.458782 473522 arrisxg1v4 WPEWebProcess[16069]: TuneHelper:3810 Updated seek_pos_seconds 12.012000

Creating Gstreamer pipeline

queueing protection event for keysystem: edef8ba9-79d6-4ace-a3c8-27dcd51d21ed initdata size: 91
2019 Jun 18 13:08:44.458801 473616 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Flush:2665 Pipeline is NULLcreateDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:44.458816 473638 arrisxg1v4 WPEWebProcess[16069]: TuneHelper : mFormat 2, mAudioFormat 2createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:44.458831 473655 arrisxg1v4 WPEWebProcess[16069]: SetVideoZoom :: ZoomMode 0, using_playersinkbin = 0, video_sink =(nil)keysystem is com.widevine.alpha
2019 Jun 18 13:08:44.458844 473671 arrisxg1v4 WPEWebProcess[16069]: SetVideoMute: muted 0, using_playersinkbin = 0, video_sink =(nil)_extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.458861 473684 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer_extractKeyIdFromPssh::setVolumeOrMuteUnMute() 2570 > volume = 1.000000, using_playersinkbin = 0, audio_sink = (nil)642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:44.458872 473702 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer::Configure 1874 > format 2 audioFormat 2createDrmSession:915 Selected slot 1 for keyId 0cc84940-1541-ef5d-cc5f-1f5317cb417e sessionType video
2019 Jun 18 13:08:44.458883 473737 arrisxg1v4 WPEWebProcess[16069]: AAMPOCDMSession : CreatePipeline(): Creating gstreamer pipeline: enter
2019 Jun 18 13:08:44.459115 473753 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayerPipeline buffering_enabled 1initAampDRMSession :: enter
2019 Jun 18 13:08:44.459129 473780 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayerinitAampDRMSession :: Configure 1898 > Closing stream 0 old format = 0, new format = 2exit
2019 Jun 18 13:08:44.459139 473795 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayerAAMPOCDMSession :: Configure 1898 > Closing stream 1 old format = 0, new format = 2exit
2019 Jun 18 13:08:44.459154 473814 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayergenerateAampDRMSession :: 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 clearedenter

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.472502 572607 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer: found_sourceSetting WideWine as preferred drm
2019 Jun 18 13:08:44.472526 575963 arrisxg1v4 WPEWebProcess[16069]: Found source for bin1

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

AAMPGstPlayer setting aamp instance for aampwidevinedecryptor2 decryptor

2019 Jun 18 13:08:44.473503 585576 arrisxg1v4 WPEWebProcess[16069]: Found Widevine encryption from manifest[ABRManager] getBandwidthOfProfile:525 No profiles
2019 Jun 18 13:08:44.473522 589276 arrisxg1v4 WPEWebProcess[16069]: queueing protection event for keysystem: edef8ba9-79d6-4ace-a3c8-27dcd51d21ed initdata size: 91Setting 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.473616 661895 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:44.473638 661933 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:44.473655 661954 arrisxg1v4 WPEWebProcess[16069]: keysystem is com.widevine.alpha
2019 Jun 18 13:08:44.473671 661978 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.473684 661994 arrisxg1v4 WPEWebProcess[16069]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:44.473702 662012 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:915 Selected slot 1 for keyId 876 Session created/inprogress with same 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

...

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.570249 745282 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}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.570280 745555 arrisxg1v4 WPEWebProcess[16069]: UpdateVideoEnd:T:6 br:213600 err:200 dur:0.000000 taTop:0.000000 ttTop:0.000000 tot:0.000000 n[HHH] Before calling SecClient_AcquireLicense-----------
2019 Jun 18 13:08:44.570660 745569 arrisxg1v4 WPEWebProcess[16069]: Sending segment event for mediaType[1]. start 40530433593750 stop 18446744073709551615 rate 1.000000 applied_rate 1.000000destinationURL is mds.ccp.xcal.tv
2019 Jun 18 13:08:44.585544 745582 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}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.586151 765810 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

AAMPGstPlayer Found --> brcmvideodecoder = 0xb232ee78
2019 Jun 18 13:08:44.570753 766483 arrisxg1v4 WPEWebProcessReceiver[16069]: AAMPGstPlayer_SendPendingEvents pushing protection event! mediatype: 115906]: Thread-15906 [XREApplication] - xre transaction complete: 1ca60ae4-00ba-4dd3-9293-9c48207edcdb,1088
2019 Jun 18 13:08:44.572607 768226 arrisxg1v4 WPEWebProcess[16069]: Setting WideWine as preferred drm: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:44.575963 768247 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer setting aamp instance for aampwidevinedecryptor2 decryptor: createDrmSession:838 [HHH]systemId is Widevine
2019 Jun 18 13:08:44.585576 768266 arrisxg1v4 WPEWebProcess[16069]: [ABRManager] getBandwidthOfProfile:525 No profileskeysystem is com.widevine.alpha
2019 Jun 18 13:08:44.589276 768290 arrisxg1v4 WPEWebProcess[16069]: Setting WideWine as preferred drm_extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:44.600250 768309 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer setting aamp instance for aampwidevinedecryptor3 decryptor: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:44.661895 768329 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed876 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:4445.661933 664064 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH]systemId is Widevine1220 acquireLicense SUCCESS! license request attempt 1; response code : sec_client 0
2019 Jun 18 13:08:4445.661954 665123 arrisxg1v4 WPEWebProcessrunAppManager.sh[16069]: keysystem is com.widevine.alpha15527]: 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:4445.661978 665434 arrisxg1v4 WPEWebProcessrunAppManager.sh[16069]: _extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 3615527]: span-duration=0.638453
2019 Jun 18 13:08:4445.661994 665673 arrisxg1v4 WPEWebProcessrunAppManager.sh[1606915527]: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417eSecClient-Status: 0, 0, 200, 0, e5de25f4-b903-42ee-a872-3f6b95a3b29f, 1560863324745, -101473692534903567
2019 Jun 18 13:08:4445.662012 665902 arrisxg1v4 WPEWebProcessrunAppManager.sh[1606915527]: 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

SecClient-PerfTime: 0, 0.918269, 0.638453
2019 Jun 18 13:08:4446.586592 002655 arrisxg1v4 WPEWebProcess[16069]: aamp: ready to collect fragments. mpd 0x197d90processKey: Key Usable!
2019 Jun 18 13:08:4446.586611 004196 arrisxg1v4 WPEWebProcess[16069]: MPD has 1 periods current period index 0: createDrmSession:1329 Key Ready for video stream
2019 Jun 18 13:08:4446.586697 024009 arrisxg1v4 WPEWebProcessrunAppManager.sh[1606915527]: 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.mp4span-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:4446.675613 032575 arrisxg1v4 ReceiverrunAppManager.sh[1590615527]: Thread-15906 [AAMP-WEB] - Event onTuned({})span-duration=0.918269
2019 Jun 18 13:08:4446.675700 034516 arrisxg1v4 ReceiverrunAppManager.sh[1590615527]: Thread-15906 [AAMP-WEB] - CAAMPWebVideoItem::setVideoTuned_JS] Event() ctx=0x99fd80d0, type=22, jsCallback=0x993b94b0
2019 Jun 18 13:08:4446.675746 035152 arrisxg1v4 ReceiverrunAppManager.sh[15906]: Thread-15906 [VideoResource] - reportPlaying sending onStreamPlaying15527]: AAMP_JSListener_DRMMetadata code 0 Description accessAttributeStatus
2019 Jun 18 13:08:4446.692840 004226 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}
...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:4446.692989 031857 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

_extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:4446.745282 031868 arrisxg1v4 WPEWebProcess[16069]: generateAampDRMSession _extractKeyIdFromPssh:: sessionId : ksidE173EC32642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:4446.745336 031883 arrisxg1v4 WPEWebProcess[16069]: destination url is https://mds.ccp.xcal.tvcreateDrmSession: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:4446.745364 031928 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1045 [HHH]contentMetaData length=1692971 Found drm session READY with same keyID 0cc84940-1541-ef5d-cc5f-1f5317cb417e - Reusing drm session for audio
2019 Jun 18 13:08:4446.745424 032364 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1078 MDS server spcific conent metadata found in initdataIsSourceUHD viddec (0xb232ee78) --> says width 1920, height 1080
2019 Jun 18 13:08:4446.745480 039716 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:1108 access token is available821 systemId is edef8ba9-79d6-4ace-a3c8-27dcd51d21ed
2019 Jun 18 13:08:4446.745555 039739 arrisxg1v4 WPEWebProcess[16069]: createDrmSession:838 [HHH] Before calling SecClient_AcquireLicense-----------systemId is Widevine
2019 Jun 18 13:08:4446.745569 039753 arrisxg1v4 WPEWebProcess[16069]: destinationURL is mds.ccp.xcal.tvkeysystem is com.widevine.alpha
2019 Jun 18 13:08:4446.745582 039772 arrisxg1v4 WPEWebProcess[16069]: MoneyTrace[trace-id=e5de25f4-b903-42ee-a872-3f6b95a3b29f;parent-id=2473532010524596290;span-id=1560863324745]_extractKeyIdFromPssh:602 wv keyid: 0cc84940-1541-ef5d-cc5f-1f5317cb417e keyIdlen: 36
2019 Jun 18 13:08:4446.745594 039784 arrisxg1v4 WPEWebProcess[16069]: keySystem is com.widevine.alpha: _extractKeyIdFromPssh:642 KeyId : 0cc84940-1541-ef5d-cc5f-1f5317cb417e
2019 Jun 18 13:08:4446.765810 039801 arrisxg1v4 WPEWebProcess[16069]: AAMPGstPlayer Found --> brcmvideodecoder = 0xb232ee78createDrmSession: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:4446.766483 039839 arrisxg1v4 ReceiverWPEWebProcess[1590616069]: 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

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

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

517,

93

244,0,

280

517,

84

492,0,

487

1061,

247

489,0,

2107200

1400000,

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

...

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.