HLS Playback Analysis

String pattern to search in receiver log

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

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

Successful working case & Functional call flow with Log Snippets

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

1613143701:288 : [AAMP-PLAYER]entering AAMPGstPlayer_Stop keepLastFrame 0
1613143701:288 : [AAMP-PLAYER]AAMPGstPlayer::Stop 2546 > Remove periodicProgressCallbackIdleTaskId 15
1613143701:288 : [AAMP-PLAYER]AAMPGstPlayer::DisconnectCallbacks: video_dec  0x708051c0 type_check 1
1613143701:290 : [AAMP-PLAYER]AAMPGstPlayerPipeline PLAYING -> PAUSED (pending NULL)
1613143701:458 : [AAMP-PLAYER]AAMPGstPlayerPipeline PAUSED -> READY (pending NULL)
1613143701:459 : [AAMP-PLAYER]AAMPGstPlayer::Stop: Pipeline state set to null
1613143701:461 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 0
1613143701:462 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 1
1613143701:462 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 2
1613143701:463 : [AAMP-PLAYER]DestroyPipeline(): Destroying gstreamer pipeline
1613143701:463 : [AAMP-PLAYER]exiting AAMPGstPlayer_Stop

New tune request reaching AAMP

http://devimages.apple.com/iphone/samples/bipbop/bipbopall.m3u8
1613142994:132 : [AAMP-PLAYER]PrivateInstanceAAMP::ConfigureDashParallelFragmentDownload:8112 DASH Paraller Frag DL Config [1]
1613142994:132 : [AAMP-PLAYER]PrivateInstanceAAMP::ConfigureRetuneForGSTInternalError:8168 GST Internal Stream Error Retune Config [1]
1613142994:132 : [AAMP-PLAYER]Enabling Westeros Sink
1613142994:132 : [AAMP-PLAYER]FOREGROUND PLAYER[0] aamp_tune: attempt: 1 format: HLS URL: http://devimages.apple.com/iphone/samples/bipbop/bipbopall.m3u8
1613142994:132 : [AAMP-PLAYER]TeardownStream:4530 mProgressReportFromProcessDiscontinuity:0 mDiscontinuityTuneOperationId:0 newTune:1

AAMP requesting Manifest

1613144318:975 : [AAMP-PLAYER]aamp url:3,9,3,http://devimages.apple.com/iphone/samples/bipbop/gear4/prog_index.m3u8

Manifest response

1613144319:842 : [AAMP-PLAYER]HttpRequestEnd: 3,9,200,0.8670,0.8675,0.0001,0.8671,0.0001,0.0001,0.0002,0.0000,7019,286,http://devimages.apple.com/iphone/samples/bipbop/gear4/prog_index.m3u8

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

1613142996:700 : [AAMP-PLAYER]Found source for video
1613142996:700 : [AAMP-PLAYER]GetGstCaps:443 Unknown format 11
1613142996:705 : [AAMP-PLAYER]bus_sync_handler: Received GST_MESSAGE_ASYNC_DONE message
1613142996:705 : [AAMP-PLAYER]AAMPGstPlayerPipeline READY -> PAUSED (pending VOID_PENDING)
1613142996:705 : [AAMP-PLAYER]TSProcessor[0x1207fa0]reset:2162 - reset video demux 0x11ff758
1613142996:705 : [AAMP-PLAYER]msg type: async-done
1613142996:705 : [AAMP-PLAYER]TSProcessor[0x1207fa0]reset:2168 - reset audio demux 0x12012b8
1613142996:706 : [AAMP-PLAYER]aamp url:0,0,0,http://devimages.apple.com/iphone/samples/bipbop/gear4/fileSequence0.ts

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.

1613144307:322 : [AAMP-PLAYER]CreatePipeline(): Creating gstreamer pipeline
1613144307:322 : [AAMP-PLAYER]AAMPGstPlayerPipeline buffering_enabled 1
1613144317:586 : [AAMP-PLAYER]PrivateInstanceAAMP::ConfigureDashParallelFragmentDownload:8112 DASH Paraller Frag DL Config [1]
1613144317:586 : [AAMP-PLAYER]PrivateInstanceAAMP::ConfigureRetuneForGSTInternalError:8168 GST Internal Stream Error Retune Config [1]
1613144317:586 : [AAMP-PLAYER]Enabling Westeros Sink
1613144317:587 : [AAMP-PLAYER]FOREGROUND PLAYER[0] aamp_tune: attempt: 1 format: HLS URL: http://devimages.apple.com/iphone/samples/bipbop/bipbopall.m3u8

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

1613144321:704 : [AAMP-PLAYER]AAMPGstPlayer_OnFirstVideoFrameCallback. got First Video Frame
1613144321:704 : [AAMP-PLAYER]FOREGROUND PLAYER[0] IP_AAMP_TUNETIME:4,0,1613144317587,4,1383,0,1388,868,0,0,0,0,0,0,0,0,0,0,2306,1644,0,737777,0,0,0,0,2256,0,0,0,0,0,0,0,3991,4117,2,10,1,0,0
1613144321:704 : [AAMP-PLAYER]AAMP=>XRE: 3895,7147870,0,1387,869,0,167,1383,868,1644,1694,0,1,1801000,0,7147870,7149257,7150126,7150126,7151820,7151987,10,1,0,-1763381592
1613144321:704 : [AAMP-PLAYER]AAMP=>XRE: 3895,7147870,0,1387,869,0,167,1383,868,1644,1694,0,1,1801000,0,7147870,7149257,7150126,7150126,7151820,7151987,10,1,0,-1763381592
1613144321:704 : [AAMP-PLAYER]Anomaly evt:2 msg:Tune attempt#1. VOD:HLS/Clear URL:http://devimages.apple.com/iphone/samples/bipbop/bipbopall.m3u8
1613144321:704 : [AAMP-PLAYER]PrivateInstanceAAMP::SendEventAsync:2592 event type  26
1613144321:704 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=26)
1613144321:704 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=14)(state=8)
1613144321:704 : [AAMP-PLAYER]AAMP_EVENT_STATE_CHANGED: 8
1613144321:704 : [AAMP-PLAYER]AAMP_EVENT_TUNED
1613144321:704 : [AAMP-PLAYER]aamp: - sent tune event on Tune Completion.