Versions Compared

Old Version 5

changes.mady.by.user Ashraf Bhanu Kothapeta

Saved on

compared with

New Version Current

changes.mady.by.user Narayanaswamy Ramaiyer

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.

...

Failures from outside of RDK

Reference & log pointers to indicate the failure in Broadcom.

  1. AAMP Playback Flow : AAMP Playback Code Flow
  2. Producing stack traces from google breakpad minidump manually :  Google Breakpad


General Tune Failures

Unrecoverable Failures - ( the playback may fail on this case )

...

S.No

AAMP Error Map Code

Media Error Code

Error Description

Failure on Tune Start

Failure on Mid Tune

Reason for failures

HLS

DASH

1AAMP_TUNE_MANIFEST_REQ_FAILED10AAMP: Manifest Download failed

String that will be logged
(*) AAMP: Manifest Download failed : Http Error Code
(*) AAMP: Manifest Download failed : Curl Error Code		XXIf manifest download failed and retry count exceedes MAX_MANIFEST_DOWNLOAD_RETRY(3)XX
2AAMP_TUNE_FRAGMENT_DOWNLOAD_FAILURE10AAMP: fragment download failures

String that will be logged
(*) AAMP: fragment download failures : Http Error Code
(*) AAMP: fragment download failures : Curl Error Code		XXIf fragment download failed and retry count exceedes MAX_SEG_DOWNLOAD_FAIL_COUNT(10)

(*) Failure with VOD/cDVR playback, the HTTP error code reflects actual CDN response interms of Curl or HTTP error values.

(*) Failure with Linear playback via FOG, the HTTP error code reflects FOG reported failure, which does not necessarily imply a CDN download failure.		XX
3AAMP_TUNE_CONTENT_NOT_FOUND20AAMP: Resource was not found at the URL(HTTP 404)XXIf the manifest / fragment download failed with HTTP 404 error, then this error will be logged.
May be the requested manifest / fragment might not be availble in the server.		XX
4AAMP_TUNE_LICENCE_TIMEOUT50AAMP: DRM License Request Timed outXXLicense requset to server got timed out.
X
5AAMP_TUNE_LICENCE_REQUEST_FAILED50AAMP: DRM License Request FailedXXLicense request failed with server returned error code.
HLS with AES DRM.
DASH with WV and PR.		XX
6AAMP_TUNE_FAILED_TO_GET_KEYID50AAMP: Failed to parse key id from PSSHXXFailed to parse key id from init data.
X
7AAMP_TUNE_FAILED_TO_GET_ACCESS_TOKEN50AAMP: Failed to get access token from Auth ServiceX
Failed to get access token from Auth Service;  Access token is required to get license for Comcast streams from MDS servers.
X
8AAMP_TUNE_CORRUPT_DRM_METADATA50AAMP: DRM Metadata error majorErrorX
Multiple times same Metadata is set to AVE-DRM session or a bad Metadata for a stream set.
DRM Major errorcode : 3314		X
9AAMP_TUNE_DRM_DECRYPT_FAILED50AAMP: DRM Decryption Failed for FragmentsXXIf fragment decryption and retry count exceedes MAX_SEG_DRM_DECRYPT_FAIL_COUNT(10) or more fragments.X
10AAMP_TUNE_CORRUPT_DRM_DATA51AAMP: DRM failure due to Corrupt DRM files
(or)
If 3322, 3328 : AAMP: DRM Failure possibly due to corrupt drm data; majorError
If 3307 : AAMP: DRM Failure possibly due to corrupt CertStore majorError		X
Class of AVE DRM library errors that suggest cached DRM files are corrupted.
(/opt/persistent/adobe - might be corrupted)
DRM Major errorcode : 3322, 3328, 3307
This should trigger automatic "self healing" for next tune.		X
11AAMP_TUNE_GST_PIPELINE_ERROR80GstPipeline Error:Decrypt Error
GstPipeline Error:Your GStreamer installation is missing a plug-in
GstPipeline Error:video decode error
GstPipeline Error:HDCP Authentication Failure		XXTriggered by GST_MESSAGE_ERROR, with human readable description extracted using gst_message_parse_error.
Check the logs for better understanding.		XX
12AAMP_TUNE_PLAYBACK_STALLED7600

AAMP: Playback

has been stalled for more than

was stalled due to lack of new fragments

XXAAMP playback stalled because of the non-availability of sufficient fragments.XX

Crash & Hang Issue Analysis

Crash can happen in 2 types

  1. Hang come Crash
  2. Direct Crash

Before proceed to analyze the Crash, try to check the back trace for any know issue which has been observed earlier; also check for any AAMP side symbols are there in the Crash Portal back trace. If nothing is there 99% that is not AAMP side issue, assign to appropriate team and save your time.

You can search below strings in Back Trace to find whether we have any AAMP side symbols.

    1. Aamp - we mostly have our symbols associated with libaamp.so, receiver (for aampwebvideo) and libaampjsbindings.so for HLS/DASH playbacks.
    2. AesDec - in case if the playback goes through AesDec DRM for HLS.
    3. libAVEPlayer.so - in case if the playback goes through AVE DRM for HLS.
    4. fogcli- fog side crashes.

How to analyze/find Hang come Crash

First search for the below print in Receiver Log.

got error 'RDKBROWSER_RENDER_PROCESS_CRASHED': WebProcess is killed due to hang

Then check for the time stamp and map the log for that time, then search for the below prints in Receiver log.
(If you are using Notepad++ then search the below regular expression on receiver log)

WebProcess is unresponsive|RDKBROWSER_RENDER_PROCESS_CRASHED|aamp_tune:

Then find the place where the WebProcess is unresponsive comes with reply num=1(max=9), so this is the place where the hang really started. Then check the logs above to this point to understand the hang reason from where the hang is initiated.

Usually hang come crash always comes with the signal reason as SIGFPE (HANG) in Crash Portal.

Most of the time, we can see the crash signature and back trace along with symbol name and line number in Crash Portal, but if you could not find the function symbol name along with the line number on Crash Portal, then try to generate the back trace with the help of mini-dump and rootfs.tar.gz of corresponding build by following the below method. (For this you need Local Linux VM (or) Linux Desktop)

Link: Producing stack traces from google breakpad minidump manually
Google Breakpad

For core dump back trace generation: Will create a new page and add the link here..

How to analyze/find direct Crash

First search for the below print in Receiver Log.

got error 'RDKBROWSER_RENDER_PROCESS_CRASHED': WebProcess crashed

Then check for the time stamp and map the log for that time, then search for the below prints in Receiver log.
(If you are using Notepad++ then search the below regular expression on receiver log)

WebProcess is unresponsive|RDKBROWSER_RENDER_PROCESS_CRASHED|aamp_tune:

In the case of direct crash, there is no WebProcess is unresponsive will be triggered, instead the process will crash immediately with the string got error 'RDKBROWSER_RENDER_PROCESS_CRASHED': WebProcess crashed.

Usually direct crash comes with signal SIGSEGV in Crash portal.

For the direct crash, the crashed thread of mini dump or core dump will have the details of crashed symbol/function. If that is a memory corruption crash, then we may not able to see valid call stack, so that case is bit difficult analyze.

Thread Analysis

Look for crashed thread and aamp side function symbols available threads, some time aamp can be hold by other modules and that time aamp can met with hung (or) some times aamp itself met hang with its calls. For better understanding analyze the back trace along with the logs.

Useful Links

  1. Crash Portal : https://crashportal.stb.r53.xcal.tv/login/index
  2. Producing stack traces from google breakpad minidump manually : Google Breakpad

DASH Playback Analysis

...

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

Image Removed

HLS Playback Analysis

Successful working case & Functional call flow with Log Snippets

Stop() for previous after channel change

2019 Jun 18 22:25:19.266979 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - CAAMPWebVideoItem::checkVideoResource Setting m_pres null
2019 Jun 18 22:25:19.267144 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - CAAMPWebVideoItem::~CAAMPWebVideoItem enter
2019 Jun 18 22:25:19.267222 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - callMethodInBrowser -> calling stop
2019 Jun 18 22:25:19.276877 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - AAMPVideoEnd CAAMPWebVideoItem::~CAAMPWebVideoItem exit
2019 Jun 18 22:25:19.277054 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - CAAMPReplyTimeout stop: name=PLAYERREADY timeout=20000
2019 Jun 18 22:25:19.277110 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - CAAMPReplyTimeout stop: name=MANIFESTHEAD timeout=10000
2019 Jun 18 22:25:19.277161 pacexi5 Receiver[6007]: Thread-6007 [AVE-Log] - ~AVELog: Enter
2019 Jun 18 22:25:19.277290 pacexi5 Receiver[6007]: Thread-6007 [AVE-Log] - ~AVELog: Exit

AAMP Stopping previous playback

2019 Jun 18 22:25:19.403980 pacexi5 WPEWebProcess[6625]: aamp_stop PlayerState=8
...
2019 Jun 18 22:25:19.458400 pacexi5 WPEWebProcess[6625]: Stopping Playback at Position '194938'.
2019 Jun 18 22:25:19.463187 pacexi5 WPEWebProcess[6625]: sleep interrupted!
2019 Jun 18 22:25:19.464602 pacexi5 WPEWebProcess[6625]: sleep interrupted!
2019 Jun 18 22:25:19.464679 pacexi5 WPEWebProcess[6625]: downloads disabled
2019 Jun 18 22:25:19.464770 pacexi5 WPEWebProcess[6625]: RunFetchLoop:3817: fragment collector done. track muxed
2019 Jun 18 22:25:19.465206 pacexi5 WPEWebProcess[6625]: WaitForCachedFragmentAvailable muxed aborted
2019 Jun 18 22:25:19.465232 pacexi5 WPEWebProcess[6625]: fragment injector done. track muxed
2019 Jun 18 22:25:19.465971 pacexi5 WPEWebProcess[6625]: StopWaitForPlaylistRefresh:4890 track [muxed]
2019 Jun 18 22:25:19.465997 pacexi5 WPEWebProcess[6625]: [ReleaseAll]Releasing AveDrmManager of size=1
2019 Jun 18 22:25:19.481369 pacexi5 WPEWebProcess[6625]: StopWaitForPlaylistRefresh:4890 track [muxed]
2019 Jun 18 22:25:19.482242 pacexi5 WPEWebProcess[6625]: Exit StreamAbstractionAAMP::~StreamAbstractionAAMP
2019 Jun 18 22:25:19.482282 pacexi5 WPEWebProcess[6625]: entering AAMPGstPlayer_Stop keepLastFrame 0
2019 Jun 18 22:25:19.489224 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::Stop 2075 > Remove periodicProgressCallbackIdleTaskId 34
...
2019 Jun 18 22:25:19.650315 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::Stop: Pipeline state set to null
2019 Jun 18 22:25:19.650345 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::TearDownStream: mediaType 0
2019 Jun 18 22:25:19.651235 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::TearDownStream: exit mediaType = 0
2019 Jun 18 22:25:19.651251 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::TearDownStream: mediaType 1
2019 Jun 18 22:25:19.651923 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::TearDownStream: exit mediaType = 1
2019 Jun 18 22:25:19.652145 pacexi5 WPEWebProcess[6625]: DestroyPipeline(): Destroying gstreamer pipeline
2019 Jun 18 22:25:19.656995 pacexi5 WPEWebProcess[6625]: exiting AAMPGstPlayer_Stop

New tune request reaching AAMP

2019 Jun 18 22:25:20.189964 pacexi5 WPEWebProcess[6625]: Detected ContentType 3 (LINEAR_TV)
2019 Jun 18 22:25:20.189981 pacexi5 WPEWebProcess[6625]: mLiveOffset: 15
2019 Jun 18 22:25:20.190012 pacexi5 WPEWebProcess[6625]: aamp_tune: attempt: 1 format: HLS URL: http://127.0.0.1:9080/tsb?clientId=FOG_AAMP&recordedUrl=http%3A%2F%2Fcdn-ec-pan-002-03.linear-nat-ntlk-pil.xcr.comcast.net%2FMSNBC_HD_NAT_18292_0_8348966700753924163.m3u8%3Ftrred%3Dfalse&analyticsUrl=https%3A%2F%2Fanalytics.xcal.tv%2Fcomcast%2Ffog&money=%7B%22PARENT_ID%22%3A%221066361147828367%22%2C%22TRACE_ID%22%3A%226237bf1b-7b03-4c8c-952c-ce56467fd7fa%22%7D&ses=%7B%22PSI%22%3A%22da3b113e-e81b-4717-be55-f558abd0a251%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%228348966700753924163%22%7D%2C%22VSTRM%22%3A%7B%7D%7D&appName=STB-XI5&appVer=3.9s3&acId=7764333496681121343&devName=ipstb&devID=E8%3A82%3A5B%3A68%3A9D%3AB8&phyID=1895170694941655639

AAMP requesting Manifest

2019 Jun 18 22:25:20.205263 pacexi5 WPEWebProcess[6625]: aamp url: http://127.0.0.1:9080/tsb?clientId=FOG_AAMP&recordedUrl=http%3A%2F%2Fcdn-ec-pan-002-03.linear-nat-ntlk-pil.xcr.comcast.net%2FMSNBC_HD_NAT_18292_0_8348966700753924163.m3u8%3Ftrred%3Dfalse&analyticsUrl=https%3A%2F%2Fanalytics.xcal.tv%2Fcomcast%2Ffog&money=%7B%22PARENT_ID%22%3A%221066361147828367%22%2C%22TRACE_ID%22%3A%226237bf1b-7b03-4c8c-952c-ce56467fd7fa%22%7D&ses=%7B%22PSI%22%3A%22da3b113e-e81b-4717-be55-f558abd0a251%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%228348966700753924163%22%7D%2C%22VSTRM%22%3A%7B%7D%7D&appName=STB-XI5&appVer=3.9s3&acId=7764333496681121343&devName=ipstb&devID=E8%3A82%3A5B%3A68%3A9D%3AB8&phyID=1895170694941655639

Manifest response

2019 Jun 18 22:25:20.323691 pacexi5 WPEWebProcess[6625]: HttpRequestEnd: {"url":"http://127.0.0.1:9080/manifests/362601d6-bf6d-4ca0-9287-8c26c343fa14/manifest.m3u8","curlTime":0.1190,"times":{"total":0.1181,"connect":0.0009,"startTransfer":0.1175,"resolve":0.0002,"appConnect":0.0000,"preTransfer":0.0036,"redirect":0.1166,"dlSz":10384,"ulSz":1587},"responseCode":200}

Manifest parsing, and the below print indicates duration of the playback

2019 Jun 18 22:25:20.324113 pacexi5 WPEWebProcess[6625]: GetPlaylistURI updating aamp->language from en to "en"
2019 Jun 18 22:25:20.324135 pacexi5 WPEWebProcess[6625]: TrackState::FetchPlaylist [muxed] start
2019 Jun 18 22:25:20.324150 pacexi5 WPEWebProcess[6625]: aamp url: http://127.0.0.1:9080/manifests/362601d6-bf6d-4ca0-9287-8c26c343fa14/video1/manifest.m3u8
...
2019 Jun 18 22:25:20.440297 pacexi5 WPEWebProcess[6625]: UpdateVideoEnd:T:7 br:262144 err:200 dur:0.000000 taTop:0.000000 ttTop:0.000000 tot:0.000000 n
2019 Jun 18 22:25:20.440320 pacexi5 WPEWebProcess[6625]: TrackState::FetchPlaylist [muxed] end
2019 Jun 18 22:25:20.440354 pacexi5 WPEWebProcess[6625]: aamp: EXT-X-TARGETDURATION = 3.000000
2019 Jun 18 22:25:20.440538 pacexi5 WPEWebProcess[6625]: aamp_UpdateDuration(28.028000)

DRM Initialization and Key acquisition

2019 Jun 18 22:25:20.440576 pacexi5 WPEWebProcess[6625]: TheDRMListener::TheDRMListener:117 AveDrm[0x193f40]Listner[0x22d818]Track[0]
2019 Jun 18 22:25:20.440598 pacexi5 WPEWebProcess[6625]: AveDrm::SetMetaData:365[0x193f40]Track[0] drmState:0
2019 Jun 18 22:25:20.440609 pacexi5 WPEWebProcess[6625]: SetMetadata:931: Created new AveDrmManager[763557531d09355a3331750aab7382daeea56725] .Track[0].Total Sz=1
2019 Jun 18 22:25:20.463579 pacexi5 runAppManager.sh[5611]: [MyFlashAccessAdapter][0x236c00] Constructor
2019 Jun 18 22:25:20.476126 pacexi5 runAppManager.sh[5611]: DRMManager_CreateDRMMetadata calling created source/DRMInterface.cpp
2019 Jun 18 22:25:20.481279 pacexi5 runAppManager.sh[5611]: [Initialize_Stage2][0x236c00]MyFlashAccessAdapter Initialize Stage 2 with encryption Algorithm: AES-CBC
2019 Jun 18 22:25:20.481679 pacexi5 runAppManager.sh[5611]: 33528 createDRMDecryptionContext_FromDrmMetadataEx calling new DRMCreateDecryptionSessionOperation DRMInterface.cpp
2019 Jun 18 22:25:20.481975 pacexi5 runAppManager.sh[5611]: machineID: NTczZWI2YTBjN2ExNDNiM2YzNzM4MmQ1ZWQ2MjBjOWI=
2019 Jun 18 22:25:20.488720 pacexi5 runAppManager.sh[5611]: 33528 OemGlobalStateStoreSPI::IOemGlobalStateStore::getDeviceInfo
2019 Jun 18 22:25:20.489057 pacexi5 runAppManager.sh[5611]: 33528 OemDeviceBindingSPI::getDeviceInfo Line 156
2019 Jun 18 22:25:20.489324 pacexi5 runAppManager.sh[5611]: [98B blob data]
2019 Jun 18 22:25:20.489630 pacexi5 runAppManager.sh[5611]: BRCM_RI_SecureStore_Read reading /opt/persistent/adobe/drm/deviceBinding.txt in size 8000
...
2019 Jun 18 22:25:20.459925 pacexi5 WPEWebProcess[6625]: AveDrm::AcquireKey:637[0x193f40] drmState:1 Track[0]

Player level tune initialization and Gstreamer pipeline creation for the playback.

2019 Jun 18 22:25:20.460253 pacexi5 WPEWebProcess[6625]: StreamAbstractionAAMP_HLS::Init : VideoTrack: format is 7 [avc1.]
2019 Jun 18 22:25:20.460266 pacexi5 WPEWebProcess[6625]: StreamAbstractionAAMP_HLS::Init : Audio format is 3 [mp4a.40.5]
2019 Jun 18 22:25:20.460276 pacexi5 WPEWebProcess[6625]: StreamAbstractionAAMP_HLS::Init : Configure video TS track demuxing demuxOp 3
2019 Jun 18 22:25:20.474715 pacexi5 WPEWebProcess[6625]: aamp: hls - sent tune event after indexing playlist
2019 Jun 18 22:25:20.474759 pacexi5 WPEWebProcess[6625]: aamp: after live adjust - V-target 13.000000 A-target 0.000000 offsetFromLive 15 offsetToLive 13 offsetVideo[13] offsetAudio[13] AtLivePoint[1]
...
2019 Jun 18 22:25:20.474794 pacexi5 WPEWebProcess[6625]: TuneHelper:3810 Updated seek_pos_seconds 13.000000
2019 Jun 18 22:25:20.474806 pacexi5 WPEWebProcess[6625]: TuneHelper : mFormat 7, mAudioFormat 3
2019 Jun 18 22:25:20.474821 pacexi5 WPEWebProcess[6625]: SetVideoZoom :: ZoomMode 0, using_playersinkbin = 0, video_sink =(nil)
2019 Jun 18 22:25:20.474832 pacexi5 WPEWebProcess[6625]: SetVideoMute: muted 0, using_playersinkbin = 0, video_sink =(nil)
2019 Jun 18 22:25:20.474848 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::setVolumeOrMuteUnMute() 2534 > volume = 1.000000, using_playersinkbin = 0, audio_sink = (nil)
2019 Jun 18 22:25:20.474861 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::Configure 1838 > format 7 audioFormat 3
2019 Jun 18 22:25:20.474871 pacexi5 WPEWebProcess[6625]: CreatePipeline(): Creating gstreamer pipeline
2019 Jun 18 22:25:20.475303 pacexi5 WPEWebProcess[6625]: AAMPGstPlayerPipeline buffering_enabled 1
2019 Jun 18 22:25:20.475319 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::Configure 1862 > Closing stream 0 old format = 0, new format = 7
2019 Jun 18 22:25:20.475329 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::Configure 1862 > Closing stream 1 old format = 0, new format = 3
2019 Jun 18 22:25:20.475339 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::TearDownStream: exit mediaType = 0
2019 Jun 18 22:25:20.475347 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer_SetupStream - using playbin
2019 Jun 18 22:25:20.485140 pacexi5 WPEWebProcess[6625]: playbin flags1: 0x617
2019 Jun 18 22:25:20.485330 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer::TearDownStream: exit mediaType = 1
2019 Jun 18 22:25:20.485341 pacexi5 WPEWebProcess[6625]: AAMPGstPlayer_SetupStream - using playbin

Fragment request start point and fragment decryption; pipeline state change to playing after decrypted data sent to gstreamer.

2019 Jun 18 22:25:20.538816 pacexi5 WPEWebProcess[6625]: FetchFragment:1494: muxed
2019 Jun 18 22:25:20.538950 pacexi5 WPEWebProcess[6625]: aamp url: http://127.0.0.1:9080/manifests/362601d6-bf6d-4ca0-9287-8c26c343fa14/video1/bandwidth-2224800-track-muxed-repid-root_audio_video1-tc-0-frag-779669337.ts
...
2019 Jun 18 22:25:20.688877 pacexi5 WPEWebProcess[6625]: AAMPGstPlayerPipeline NULL -> READY (pending PAUSED)
2019 Jun 18 22:25:21.353778 pacexi5 WPEWebProcess[6625]: TrackState::[SetDrmContext][muxed] Enter mCMSha1Hash [(nil)] mDrmMetaDataIndexPosition 0
2019 Jun 18 22:25:21.353794 pacexi5 WPEWebProcess[6625]: GetAveDrm:1079:[0] Returned only available Drm Instance
2019 Jun 18 22:25:21.353806 pacexi5 WPEWebProcess[6625]: SetDrmContext:1897:[muxed] Initiating Key Request as Key is not available for index [0]
2019 Jun 18 22:25:21.353818 pacexi5 WPEWebProcess[6625]: InitiateDRMKeyAcquisition:1856:[muxed]Request DRM Key immediately for indexPosn[0]
2019 Jun 18 22:25:21.353849 pacexi5 WPEWebProcess[6625]: AveDrm::Decrypt:474[0x193f40] waiting for key acquisition to complete,wait time:12000
2019 Jun 18 22:25:21.359066 pacexi5 Receiver[6007]: Thread-6007 [XREApplication] - onWriteLocalObjectComplete
2019 Jun 18 22:25:21.381172 pacexi5 Receiver[6007]: Thread-6007 [XREApplication] - onWriteLocalObjectComplete
2019 Jun 18 22:25:21.385209 pacexi5 Receiver[6007]: Thread-6007 [VideoResource] - got traceId '6237bf1b-7b03-4c8c-952c-ce56467fd7fa'
2019 Jun 18 22:25:21.385313 pacexi5 Receiver[6007]: Thread-6007 [VideoResource] - [LINEAR_TV] NEW RAW url: http://ccr.linear-nat-pil-red.xcr.comcast.net/MSNBC_HD_NAT_18292_0_8348966700753924163.m3u8
2019 Jun 18 22:25:21.389877 pacexi5 Receiver[6007]: Thread-6007 [XREApplication] - __PLOG__ Overcard hidden SerTime=1560896721254 threadId=4200848 recTime=1560896721389
2019 Jun 18 22:25:21.422637 pacexi5 Receiver[6007]: Thread-6007 [XREApplication] - onReadLocalObjectComplete
2019 Jun 18 22:25:23.666291 pacexi5 runAppManager.sh[5611]: [SetDecryptInfo][0x236c00] MyFlashAccessAdapter
2019 Jun 18 22:25:23.666724 pacexi5 runAppManager.sh[5611]: 33528 HttpRequestTransferEnd https://bet.ccp.xcal.tv/flashaccess/license/v6
2019 Jun 18 22:25:23.666995 pacexi5 runAppManager.sh[5611]: 33528 HttpRequest after ConfigureAndPerformCurlRequest33528 HttpRequestEnd https://bet.ccp.xcal.tv/flashaccess/license/v6 TOTAL=2.37749 times={total=2.37718 connect=0.224836 startTransfer=0.498429 resolve=0.128993 appConnect=0.496993 preTransfer=0.498413 redirect=0 dlSz=4780 dlSpd=2010b/s ulSz=16384 ulSpd=1962b/s} responseCode=200
2019 Jun 18 22:25:23.667244 pacexi5 runAppManager.sh[5611]: BRCM_RI_SecureStore_Write writing /opt/persistent/adobe/drm/sss/SFM581F0Zk0P8rndN7DRz_HguWw=/serverData size 80
2019 Jun 18 22:25:23.667508 pacexi5 runAppManager.sh[5611]: [121B blob data]
2019 Jun 18 22:25:23.667754 pacexi5 runAppManager.sh[5611]: 190618-22:25:23.665736 [mod=RDKBROWSER2, lvl=WARN] [tid=8213] aveLogCallback:AVESupport.cpp:237 AVE-Lib DRM_Common_AllocKeySlot count=1
2019 Jun 18 22:25:23.728267 pacexi5 WPEWebProcess[6625]: DRMListener::NotifyDRMStatus:281[0x193f40]aamp:***drmState:1
2019 Jun 18 22:25:23.729152 pacexi5 WPEWebProcess[6625]: DRMListener::SignalKeyAcquired:142[0x193f40][0]drmState:1 moving to KeyAcquired.callbackID[42]
...
2019 Jun 18 22:25:24.064616 pacexi5 WPEWebProcess[6625]: AAMPGstPlayerPipeline READY -> PAUSED (pending VOID_PENDING)
2019 Jun 18 22:25:24.149873 pacexi5 WPEWebProcess[6625]: AAMPGstPlayerPipeline PAUSED -> PLAYING (pending VOID_PENDING)

To confirm send segment data during tune ( mediaType[0] : Video / mediaType[1] : Audio )

2019 Jun 18 22:25:23.765015 pacexi5 WPEWebProcess[6625]: Sending segment event for mediaType[0]. start 500000000 stop 18446744073709551615 rate 1.000000 applied_rate 1.000000
2019 Jun 18 22:25:23.779102 pacexi5 WPEWebProcess[6625]: Sending segment event for mediaType[1]. start 505355555 stop 18446744073709551615 rate 1.000000 applied_rate 1.000000

Finally tune succeeded and tune time print will have the statistics

2019 Jun 18 22:25:24.018072 pacexi5 Receiver[6007]: Thread-6007 [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/MSNBC_HD_NAT_18292_0_8348966700753924163.m3u8 DurationMs:28000
2019 Jun 18 22:25:24.018150 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - IP_TUNETIME:3,4.4,4.3
...
2019 Jun 18 22:25:24.018204 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - IP_EX_TUNETIME:3,4.479,4.338,0.825,0.134,0.116,3.289,0.114,0.001,0.000,0.000,0.914,3.288,1,0.119,1,0.116,1,0.815,1,12,0,1,0,0,28,1,0.000,2,1
2019 Jun 18 22:25:24.018367 pacexi5 Receiver[6007]: Thread-6007 [AAMP-WEB] - New flash video is playing. Duration=28000
2019 Jun 18 22:25:24.018401 pacexi5 Receiver[6007]: Thread-6007 [ECM] - New flash video is playing. Duration=28000 hasTSB=1
2019 Jun 18 22:25:24.018469 pacexi5 Receiver[6007]: Thread-6007 [VideoResource] - event=onVideoInfo

...