Live Packager (livepkgr) looping issue when source streams are switched

Hi folks,

We are running AMS 5.0.14.

We noticed that when streams are switched, frequently, this will cause Live Packager application to output old segments.  Within our organization, we call this incident a "Live Packager looping issue".  When this occurs, the video seems to play old segments in a loop.  This requires that Live Packager be manually restarted.  After the restart, things work fine.  As everyone is moving away from Flash we are depending on Live Packager more everyday as a result we are seeing more and more of these issues.

I have researched the logs that we output and have identified a few key items that I need help with to pin-point the cause of this issue.  In the log snippets that follow, the actual stream switched at 11:27:42:

Live Packager Logs:

2018-02-20 11:27:44 28061 (s)2641173 f4f:hls - NetStream.Play.InsufficientBW -

2018-02-20 11:28:36 28061 (s)2641173 f4f:hls - NetStream.Record.NoAccess -

2018-02-20 11:28:36 28061 (s)2641173 f4f:hls - NetStream.Record.Stop -

AMS Server Logs:

2018-02-20 11:27:42 28061 (w)2611179 Warning from libf4f.so: [Utils] [hls] [hls] AMS F4F recording received timestamps with absolute time flowing backward lastTime held was 16022 and the most recent arrived was 12270. This message is being ignored - recording will continue.  (there are a lot of these)

...

2018-02-20 11:28:36 28061 (e)2611178 Error from libf4f.so: [Fragmenter] [hls] First message in fragment is not a key frame

. -

2018-02-20 11:28:36 28061 (e)2611178 Error from libf4f.so: [Utils] [hls] Error when pushing messages to Fragmenter : 5407 First video sample in the fragment is not a key frame

. -

2018-02-20 11:28:36 28061 (e)2611178 Error from libf4f.so: f4fAdaptor::record failed. Error: First video sample in the fragment is not a key frame. -

2018-02-20 11:28:36 28061 (e)2611082 Failed to record hls. -

After the above in the logs, we typically notice that .F4F file stops growing and Live Packager "loops" over old fragments.  Manually restarting Live Packager usually fixes this issue.

Has anyone seen this?

Is this something we can do on our side to correct other than manually restarting the Live Packager?

I, believe, Live Packager support stream switching, is this correct?

Some more supporting details (more logs from our Live Packager application)

#Date: 2018-02-20

#Fields: date time x-pid x-status x-ctx x-comment

2018-02-20 11:27:06 28061 (i)2611173 Application level recording configuration: General[flags: 0, keyframe interval: 0, max size: -1, max length: -1, io buffer size: 0], Fragment[frag duration: 4000, seg duration: 0, duration precision: 100.000000, allowed drift: 1000, frame rate: 0.000000, frames per interval: 0, intervals per frag: 1, frame precision: 1, disk management duration: 0.000000, disk management with gap: false, max sample descriptors: 3], ContentProtection[enabled=false(overridable)] -

2018-02-20 11:27:06 28061 (i)2611173 Application level Protected RTMP configuration: ContentProtection[enabled=false] -

2018-02-20 11:27:06 28061 (s)2641173 Application name: livepkgr/fd202cad-f82f-db34-6b25-a62d0c5aa68e -

2018-02-20 11:27:06 28061 (s)2641173 Server: Adobe Media Server Custom Edition-Linux/5.0.14 -

2018-02-20 11:27:06 28061 (s)2641173 This is MAIN.ASC -

2018-02-20 11:27:06 28061 (s)2641173 Config setting for clear stream on app unload:undefined -

2018-02-20 11:27:06 28061 (s)2641173 onPublish : hls -

2018-02-20 11:27:06 28061 (s)2641173 queryString[adbe-live-event=hls&adbe-record-mode=record&adbe-http-streaming-ver=1.0] stream[hls] -

2018-02-20 11:27:06 28061 (s)2641173 streamObj properties: -

2018-02-20 11:27:06 28061 (s)2641173 streamObj name:hls -

2018-02-20 11:27:06 28061 (s)2641173 streamObj bufferTime:0 -

2018-02-20 11:27:06 28061 (s)2641173 streamObj type:flv -

2018-02-20 11:27:06 28061 (s)2641173 streamObj publishQueryString:adbe-live-event=hls&adbe-record-mode=record&adbe-http-streaming-ver=1.0 -

2018-02-20 11:27:06 28061 (s)2641173 streamObj maxQueueDelay:500 -

2018-02-20 11:27:06 28061 (s)2641173 streamObj maxQueueSize:4096 -

2018-02-20 11:27:06 28061 (s)2641173 streamObj time:0 -

2018-02-20 11:27:06 28061 (s)2641173 streamObj generateCCInfo:false -

2018-02-20 11:27:06 28061 (s)2641173 streamObj publishing:true -

2018-02-20 11:27:06 28061 (s)2641173 streamObj receiveAudio:true -

2018-02-20 11:27:06 28061 (s)2641173 streamObj trace:function (msg) {

    trace(this.type + ":" + this.name + " - " + msg);

} -

2018-02-20 11:27:06 28061 (s)2641173 s bufferTime:0 -

2018-02-20 11:27:06 28061 (s)2641173 s properties: -

2018-02-20 11:27:06 28061 (s)2641173 streamObj receiveVideo:true -

2018-02-20 11:27:06 28061 (s)2641173 streamObj syncWrite:false -

2018-02-20 11:27:06 28061 (s)2641173 s name:hls -

2018-02-20 11:27:06 28061 (s)2641173 s type:f4f -

2018-02-20 11:27:06 28061 (s)2641173 streamObj liveEvent: -

2018-02-20 11:27:06 28061 (s)2641173 s time:0 -

2018-02-20 11:27:06 28061 (s)2641173 s maxQueueDelay:500 -

2018-02-20 11:27:06 28061 (s)2641173 s syncWrite:false -

2018-02-20 11:27:06 28061 (s)2641173 s publishQueryString: -

2018-02-20 11:27:06 28061 (s)2641173 s liveEvent: -

2018-02-20 11:27:06 28061 (s)2641173 s receiveAudio:true -

2018-02-20 11:27:06 28061 (s)2641173 s receiveVideo:true -

2018-02-20 11:27:06 28061 (s)2641173 s maxQueueSize:4096 -

2018-02-20 11:27:06 28061 (s)2641173 s generateCCInfo:false -

2018-02-20 11:27:06 28061 (s)2641173 Stream name is: hls and live event is: hls -

2018-02-20 11:27:06 28061 (s)2641173 s trace:function (msg) {

    trace(this.type + ":" + this.name + " - " + msg);

} -

2018-02-20 11:27:06 28061 (s)2641173 Calling play on: hls -

2018-02-20 11:27:06 28061 (s)2641173 FCPublish: streamName hls -

2018-02-20 11:27:06 28061 (s)2641173 f4f:hls - NetStream.Data.Start -

2018-02-20 11:27:06 28061 (s)2641173 f4f:hls - NetStream.Publish.Start -

2018-02-20 11:27:06 28061 (s)2641173 f4f:hls - NetStream.Play.Reset -

2018-02-20 11:27:06 28061 (s)2641173 f4f:hls - NetStream.Record.Start -

2018-02-20 11:27:44 28061 (s)2641173 f4f:hls - NetStream.Play.InsufficientBW -

2018-02-20 11:28:36 28061 (s)2641173 f4f:hls - NetStream.Record.NoAccess -

2018-02-20 11:28:36 28061 (s)2641173 f4f:hls - NetStream.Record.Stop -

Message was edited by: Alex Paransky Clarified the "looping" issue and a manual work around that works.