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 -|<Operator reference UI App>_NR_STATUS|Skip
onLoadFinished notification, load not finished yet|on<Operator reference UI App>Ready|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/run<Operator reference UI App>:
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_<Operator reference UI App>_sleep|<Operator reference UI App>_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
[AAMP-PLAYER] aamp-cli> stop 1615821315:601 : [AAMP-PLAYER]PLAYER[0] aamp_stop PlayerState=8 1615821315:602 : [AAMP-PLAYER]FOREGROUND PLAYER[0] Stopping Playback at Position '18885'. 1615821315:602 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=14)(state=0) 1615821315:602 : [AAMP-PLAYER]AAMP_EVENT_STATE_CHANGED: 0 1615821315:602 : [AAMP-PLAYER]PrivateInstanceAAMP::BlockUntilGstreamerWantsData interrupted. mDownloadsEnabled:0 mTrackInjectionBlocked:0 1615821315:602 : [AAMP-PLAYER]WaitForCachedFragmentAvailable muxed aborted 1615821315:602 : [AAMP-PLAYER]fragment injector done. track muxed 1615821315:602 : [AAMP-PLAYER]RunFetchLoop:5473: fragment collector done. track muxed 1615821315:602 : [AAMP-PLAYER]StopWaitForPlaylistRefresh:7118 track [muxed] 1615821315:602 : [AAMP-PLAYER]StopWaitForPlaylistRefresh:7118 track [muxed] 1615821315:603 : [AAMP-PLAYER]TeardownStream:4580 mProgressReportFromProcessDiscontinuity:0 mDiscontinuityTuneOperationId:0 newTune:1 1615821315:603 : [AAMP-PLAYER]StopWaitForPlaylistRefresh:7118 track [muxed] 1615821315:603 : [AAMP-PLAYER]StopWaitForPlaylistRefresh:7118 track [muxed] 1615821315:604 : [AAMP-PLAYER]entering AAMPGstPlayer_Stop keepLastFrame 0 1615821315:605 : [AAMP-PLAYER]AAMPGstPlayer::Stop 2703 > Remove periodicProgressCallbackIdleTaskId 12 1615821315:605 : [AAMP-PLAYER]AAMPGstPlayer::DisconnectCallbacks: video_dec 0x724079c8 type_check 1 1615821315:623 : [AAMP-PLAYER]AAMPGstPlayerPipeline PLAYING -> PAUSED (pending NULL) 1615821315:670 : [AAMP-PLAYER]AAMPGstPlayerPipeline PAUSED -> READY (pending NULL) 1615821315:672 : [AAMP-PLAYER]AAMPGstPlayer::Stop: Pipeline state set to null 1615821315:673 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 0 1615821315:675 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 1 1615821315:675 : [AAMP-PLAYER]AAMPGstPlayer::TearDownStream: exit mediaType = 2 1615821315:675 : [AAMP-PLAYER]DestroyPipeline(): Destroying gstreamer pipeline 1615821315:676 : [AAMP-PLAYER]exiting AAMPGstPlayer_Stop
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
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
1620191772:173 : [AAMP-PLAYER]createDrmSession:916 StreamType :0 keySystem is com.widevine.alpha 1620191772:173 : [AAMP-PLAYER]getDrmSession:1033 Selected slot 0 for keyId 0x7368616B615F63656332663634616137383930613131 1620191772:173 : [AAMP-PLAYER]AAMPOCDMSessionAdapter :: enter 1620191772:173 : [AAMP-PLAYER]initAampDRMSystem :: enter Trying to open an OCDM connection @ /tmp/ocdm 1620191772:175 : [AAMP-PLAYER]initAampDRMSystem :: exit EDID Num of Resolution .......9 1620191772:197 : [AAMP-PLAYER]SetResolution:253 Resolution : width 1920 height:1080 1620191772:197 : [AAMP-PLAYER]SetHDMIStatus : detected HDCP version 1.4 1620191772:197 : [AAMP-PLAYER]AAMPOCDMSessionAdapter :: exit 1620191772:197 : [AAMP-PLAYER]getDrmSession:1113 Created new DrmSession for DrmSystemId com.widevine.alpha 1620191772:197 : [AAMP-PLAYER]generateAampDRMSession:91: at 0xaed94e20, with 0xaed94da0, (nil) Essos Info: ../../git/essos/essos-resmgr.cpp:1997 audio decoder 0 assigned to pid 21264 PID = 21264, inited = 0 1620191772:300 : [AAMP-PLAYER]parsePssh:76 WV Version: 0, Keyid indicator byte not found using default logic 1620191772:402 : [AAMP-PLAYER]processOCDMChallenge:145: at 0xaed94e20, with 0xaed94da0, (nil) 1620191772:402 : [AAMP-PLAYER]processOCDMChallenge challenge = 0:Type 1620191772:402 : [AAMP-PLAYER]processOCDMChallenge destUrl = http://widevine-proxy.appspot.com/proxy 1620191772:403 : [AAMP-PLAYER]acquireLicense:1184 Request to generate license challenge to the aampDRMSession(CDM) 1620191772:403 : [AAMP-PLAYER]aampGenerateKeyRequest:198: at 0xaed94e20, with 0xaed94da0, 0xaed9bd20 1620191772:403 : [AAMP-PLAYER]destination url is http://widevine-proxy.appspot.com/proxy 1620191772:403 : [AAMP-PLAYER]acquireLicense:1261 Request License from the Drm Server http://widevine-proxy.appspot.com/proxy 1620191772:403 : [AAMP-PLAYER]getLicense:666 Sending license request to server : http://widevine-proxy.appspot.com/proxy 1620191773:713 : [AAMP-PLAYER]HttpRequestEnd: 0,0,200,1.6630,1.6626,0.0001,1.4487,0.0001,0.0001,0.0002,0.0000,177868,324,https://storage.googleapis.com/shaka-demo-assets/angel-one-widevine-hls/v-0240p-0400k-libx264-s2.mp4 1620191773:713 : [AAMP-PLAYER]GetDesiredProfileBasedOnCache currBW:2193558 NwBW=3500779 currProf:3 desiredProf:3 1620191774:214 : [AAMP-PLAYER]GetDesiredProfileBasedOnCache currBW:2193558 NwBW=3500779 currProf:3 desiredProf:3 1620191774:214 : [AAMP-PLAYER]GetDesiredProfileOnSteadyState buffer:8.000000 currProf:3 nwBW:3500779 1620191774:214 : [AAMP-PLAYER]Setting Video timeout to :10000 8.000000 1620191774:214 : [AAMP-PLAYER]Setting Audio timeout to :10000 8.000000 1620191774:714 : [AAMP-PLAYER]GetDesiredProfileBasedOnCache currBW:2193558 NwBW=3500779 currProf:3 desiredProf:3 1620191774:714 : [AAMP-PLAYER]GetDesiredProfileOnSteadyState buffer:8.000000 currProf:3 nwBW:3500779 1620191774:714 : [AAMP-PLAYER]Setting Video timeout to :10000 8.000000 1620191774:714 : [AAMP-PLAYER]Setting Audio timeout to :10000 8.000000 1620191775:136 : [AAMP-PLAYER]getLicense:766 DRM Session Manager Received license data from server; Curl total time = 2.7 1620191775:136 : [AAMP-PLAYER]getLicense:767 acquireLicense SUCCESS! license request attempt 1; response code : http 200 1620191775:136 : [AAMP-PLAYER]HttpRequestEnd: 1,0,200,2.7330,2.7330,1.5653,1.9726,1.5114,0.0000,1.5654,0.0000,1237,155,http://widevine-proxy.appspot.com/proxy 1620191775:137 : [AAMP-PLAYER]handleLicenseResponse:1347 license acquisition completed
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.
1620191769:864 : [AAMP-PLAYER]fragment injector started. track video 1620191769:864 : [AAMP-PLAYER]TrackState::FetchInitFragment:6836 first encrypted init-fragment is NULL! fragmentEncrypted-0 1620191769:864 : [AAMP-PLAYER]TrackState::FetchInitFragmentHelper:6996 init-fragment = https://storage.googleapis.com/shaka-demo-assets/angel-one-widevine-hls/v-0240p-0400k-libx264-init.mp4 1620191769:864 : [AAMP-PLAYER]aamp url:2,6,0,0.000000,https://storage.googleapis.com/shaka-demo-assets/angel-one-widevine-hls/v-0240p-0400k-libx264-init.mp4 1620191769:864 : [AAMP-PLAYER]PrivateInstanceAAMP::SendEventAsync:2651 event type 14 [AAMPCLI] type 'help' for list of available commands [AAMPCLI] aamp-cli> 1620191769:864 : [AAMP-PLAYER]fragment injector started. track audio 1620191769:864 : [AAMP-PLAYER][AAMP_JS] SendEventSync(type=14)(state=4) ... 1620191775:238 : [AAMP-PLAYER]AAMPGstPlayerPipeline READY -> PAUSED (pending VOID_PENDING) 1620191775:239 : [AAMP-PLAYER]msg type: async-done westeros-sink: source change event (aamp-cli:21264): GLib-GObject-WARNING **: g_object_get_valist: object class 'GstWesterosSink' has no property named 'buffered_bytes' westeros-sink: frame size 320x240 (aamp-cli:21264): GLib-GObject-WARNING **: g_object_get_valist: object class 'GstWesterosSink' has no property named 'buffered_bytes' sent session info: type 1 sessionId 0 to video server (aamp-cli:21264): GLib-GObject-WARNING **: g_object_get_valist: object class 'GstWesterosSink' has no property named 'buffered_bytes' 1620191775:270 : [AAMP-PLAYER]buffering_timeout: Set pipeline state to PLAYING - buffering_timeout_cnt 99 bytes 0 frames 24 1620191775:282 : [AAMP-PLAYER]bus_sync_handler: Received GST_MESSAGE_ASYNC_DONE message 1620191775:284 : [AAMP-PLAYER]msg type: async-done 1620191775:286 : [AAMP-PLAYER]AAMPGstPlayerPipeline PAUSED -> PLAYING (pending VOID_PENDING)
To confirm send segment data during tune ( mediaType[0] : Video / mediaType[1] : Audio )
1620191772:150 : [AAMP-PLAYER]Sending segment event for mediaType[0]. start 0 stop 18446744073709551615 rate 1.000000 applied_rate 1.000000 1620191772:151 : [AAMP-PLAYER]IsoBmffProcessor::pushInitSegment() 332 Push init fragment 1620191772:153 : [AAMP-PLAYER]Setting PlayReady as preferred drm gst_qtdemux_handle_sink_event:2320 - aamp_override - enabled = 0, player = 1, rate 1.000000 1620191772:153 : [AAMP-PLAYER]Sending segment event for mediaType[1]. start 0 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=><Operator reference UI App>: 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=><Operator reference UI App>: 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.