livesync: synchronization broken when receiving early buffer after segment update

I found another segment problem (cf #450 (closed)).
After running for a while, uriplaylistbin upstream switches to the next media item, sending a new segment and resetting buffer pts. But as the first buffer is too early, this new segment is never forwarded downstream. As a result downstream (audiobuffersplit) got invalid running-time and livesync code waiting on code is broken.
I'm also not sure why it set the duration of the first buffer to 0.5 sec?
Here are the logs:
0:03:04.426598717 537298 0x555b03cca060 TRACE               livesync imp.rs:723:gstlivesync::livesync::imp::LiveSync::sink_event:<10-0-encoder-audio-audio-livesync> Queueing Event { ptr: 0x7f3af8002d60, type: "segment", seqnum: Seqnum(3639), structure: Some(GstEventSegment { segment: (GstSegment) ((GstSegment*) 0x7f3b04001cb0) }) }
0:03:04.426622773 537298 0x555b03cca060 TRACE               livesync imp.rs:812:gstlivesync::livesync::imp::LiveSync::sink_chain:<10-0-encoder-audio-audio-livesync> Incoming Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.019999999, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] }
0:03:04.427553475 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 24:22:02.542633419
0:03:04.449580743 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Ok(Ok) -21957975
0:03:04.449608195 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Buffer(Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.023532454, dts: --:--:--.---------, duration: 0:00:00.000708333, size: 272, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(0x0), metas: [] }, OnTime))
0:03:04.449628353 537298 0x555b03d07060 TRACE               livesync imp.rs:1192:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Pushing Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.023532454, dts: --:--:--.---------, duration: 0:00:00.000708333, size: 272, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(0x0), metas: [] }
0:03:04.449639273 537298 0x555b03d07060 LOG         audiobuffersplit gstaudiobuffersplit.c:715:gst_audio_buffer_split_sink_chain:<10-0-encoder-audio-audiobuffersplit> Processing buffer at running time 24:22:01.542633419 with timestamp 0:03:00.023532454 with duration 0:00:00.000708333 (34 samples)
0:03:04.449640716 537298 0x555b03cca060 TRACE               livesync imp.rs:936:gstlivesync::livesync::imp::LiveSync::sink_chain:<10-0-encoder-audio-audio-livesync> Queueing Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.020000000, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] } (OnTime)
0:03:04.449675472 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 24:22:02.543341752
0:03:04.449677335 537298 0x555b03cca060 TRACE               livesync imp.rs:812:gstlivesync::livesync::imp::LiveSync::sink_chain:<10-0-encoder-audio-audio-livesync> Incoming Buffer { ptr: 0x7f3ad02aba20, pts: 0:00:00.064000000, dts: --:--:--.---------, duration: 0:00:00.021333333, size: 8192, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(0x0), metas: [] }
0:03:04.450473843 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Ok(Ok) -545143
0:03:04.450501335 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Event(Event { ptr: 0x7f3a800032a0, type: "tag", seqnum: Seqnum(3382), structure: Some(GstTagList-stream { taglist: (GstTagList) ((GstTagList*) 0x7f3a7400a370) }) }))
0:03:04.450546791 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 24:22:02.543341752
0:03:04.450555448 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 325165
0:03:04.450567591 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Event(Event { ptr: 0x7f3ab40d2020, type: "tag", seqnum: Seqnum(1142), structure: Some(GstTagList-global { taglist: (GstTagList) ((GstTagList*) 0x7f3b380021e0) }) }))
0:03:04.450580295 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 24:22:02.543341752
0:03:04.450587088 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 357356
0:03:04.450597888 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Event(Event { ptr: 0x7f3af8002d60, type: "segment", seqnum: Seqnum(3639), structure: Some(GstEventSegment { segment: (GstSegment) ((GstSegment*) 0x7f3b04001cb0) }) }))
0:03:04.450621944 537298 0x555b03d07060 DEBUG               livesync imp.rs:1060:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> pending Segment { format: Time, start: 0:00:00.044000000, offset: 0:00:00.000000000, stop: 0:36:50.924000000, rate: 1.0, applied_rate: 1.0, flags: SegmentFlags(0x0), time: 0:00:00.000000000, base: 24:22:01.544320919, position: 0:00:00.044000000, duration: ->
0:03:04.450632003 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 24:22:02.543341752
0:03:04.450639637 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 409895
0:03:04.450662600 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Buffer(Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.020000000, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] }, OnTime))
0:03:04.450672038 537298 0x555b03d07060 DEBUG               livesync imp.rs:1258:gstlivesync::livesync::imp::LiveSync::buffer_is_early:<10-0-encoder-audio-audio-livesync> Timestamp is too early: buffer starts at 24:22:02.544320919, expected 24:22:02.543341752
0:03:04.450686866 537298 0x555b03d07060 DEBUG               livesync imp.rs:1302:gstlivesync::livesync::imp::LiveSync::patch_output_buffer:<10-0-encoder-audio-audio-livesync> Repeating Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.023532454, dts: --:--:--.---------, duration: 0:00:00.000708333, size: 272, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(0x0), metas: [] }
0:03:04.450762500 537298 0x555b03d07060 DEBUG               livesync imp.rs:1335:gstlivesync::livesync::imp::LiveSync::patch_output_buffer:<10-0-encoder-audio-audio-livesync> Patched output buffer duration to 0:00:00.500000000
0:03:04.450780183 537298 0x555b03d07060 TRACE               livesync imp.rs:1192:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Pushing Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.024240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.450790252 537298 0x555b03d07060 LOG         audiobuffersplit gstaudiobuffersplit.c:715:gst_audio_buffer_split_sink_chain:<10-0-encoder-audio-audiobuffersplit> Processing buffer at running time 99:99:99.999999999 with timestamp 0:03:00.024240787 with duration 0:00:00.500000000 (24000 samples)
0:03:04.450799830 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 0:00:01.500000000
0:03:04.450806894 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 87721043918683
0:03:04.450821361 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Buffer(Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.020000000, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] }, OnTime))
0:03:04.450829346 537298 0x555b03d07060 DEBUG               livesync imp.rs:1258:gstlivesync::livesync::imp::LiveSync::buffer_is_early:<10-0-encoder-audio-audio-livesync> Timestamp is too early: buffer starts at 24:22:02.544320919, expected 0:00:01.500000000
0:03:04.450842892 537298 0x555b03d07060 DEBUG               livesync imp.rs:1302:gstlivesync::livesync::imp::LiveSync::patch_output_buffer:<10-0-encoder-audio-audio-livesync> Repeating Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.024240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.450856397 537298 0x555b03d07060 TRACE               livesync imp.rs:1192:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Pushing Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.524240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.450869612 537298 0x555b03d07060 LOG         audiobuffersplit gstaudiobuffersplit.c:715:gst_audio_buffer_split_sink_chain:<10-0-encoder-audio-audiobuffersplit> Processing buffer at running time 99:99:99.999999999 with timestamp 0:03:00.524240787 with duration 0:00:00.500000000 (24000 samples)
0:03:04.450877347 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 0:00:01.500000000
0:03:04.450883899 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 87721043996030
0:03:04.450905059 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Buffer(Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.020000000, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] }, OnTime))
0:03:04.450912884 537298 0x555b03d07060 DEBUG               livesync imp.rs:1258:gstlivesync::livesync::imp::LiveSync::buffer_is_early:<10-0-encoder-audio-audio-livesync> Timestamp is too early: buffer starts at 24:22:02.544320919, expected 0:00:01.500000000
0:03:04.450926129 537298 0x555b03d07060 DEBUG               livesync imp.rs:1302:gstlivesync::livesync::imp::LiveSync::patch_output_buffer:<10-0-encoder-audio-audio-livesync> Repeating Buffer { ptr: 0x555b03dae5a0, pts: 0:03:00.524240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.450939615 537298 0x555b03d07060 TRACE               livesync imp.rs:1192:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Pushing Buffer { ptr: 0x555b03dae5a0, pts: 0:03:01.024240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.450950495 537298 0x555b03d07060 LOG         audiobuffersplit gstaudiobuffersplit.c:715:gst_audio_buffer_split_sink_chain:<10-0-encoder-audio-audiobuffersplit> Processing buffer at running time 99:99:99.999999999 with timestamp 0:03:01.024240787 with duration 0:00:00.500000000 (24000 samples)
0:03:04.450958511 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 0:00:01.500000000
0:03:04.450965404 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 87721044077283
0:03:04.450979390 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Buffer(Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.020000000, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] }, OnTime))
0:03:04.450986874 537298 0x555b03d07060 DEBUG               livesync imp.rs:1258:gstlivesync::livesync::imp::LiveSync::buffer_is_early:<10-0-encoder-audio-audio-livesync> Timestamp is too early: buffer starts at 24:22:02.544320919, expected 0:00:01.500000000
0:03:04.451004538 537298 0x555b03d07060 DEBUG               livesync imp.rs:1302:gstlivesync::livesync::imp::LiveSync::patch_output_buffer:<10-0-encoder-audio-audio-livesync> Repeating Buffer { ptr: 0x555b03dae5a0, pts: 0:03:01.024240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.451017973 537298 0x555b03d07060 TRACE               livesync imp.rs:1192:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Pushing Buffer { ptr: 0x555b03dae5a0, pts: 0:03:01.524240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.451024986 537298 0x555b03d07060 LOG         audiobuffersplit gstaudiobuffersplit.c:715:gst_audio_buffer_split_sink_chain:<10-0-encoder-audio-audiobuffersplit> Processing buffer at running time 99:99:99.999999999 with timestamp 0:03:01.524240787 with duration 0:00:00.500000000 (24000 samples)
0:03:04.451032320 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 0:00:01.500000000
0:03:04.451039253 537298 0x555b03d07060 TRACE               livesync imp.rs:1026:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Clock returned Err(Early) 87721044151183
0:03:04.451053290 537298 0x555b03d07060 TRACE               livesync imp.rs:1037:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Unqueueing Some(Buffer(Buffer { ptr: 0x7f3ad02abb40, pts: 0:00:00.044000000, dts: --:--:--.---------, duration: 0:00:00.020000000, size: 7680, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(DISCONT), metas: [] }, OnTime))
0:03:04.451060704 537298 0x555b03d07060 DEBUG               livesync imp.rs:1258:gstlivesync::livesync::imp::LiveSync::buffer_is_early:<10-0-encoder-audio-audio-livesync> Timestamp is too early: buffer starts at 24:22:02.544320919, expected 0:00:01.500000000
0:03:04.451073769 537298 0x555b03d07060 DEBUG               livesync imp.rs:1302:gstlivesync::livesync::imp::LiveSync::patch_output_buffer:<10-0-encoder-audio-audio-livesync> Repeating Buffer { ptr: 0x555b03dae5a0, pts: 0:03:01.524240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.451087004 537298 0x555b03d07060 TRACE               livesync imp.rs:1192:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Pushing Buffer { ptr: 0x555b03dae5a0, pts: 0:03:02.024240787, dts: --:--:--.---------, duration: 0:00:00.500000000, size: 192000, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(GAP | TAG_MEMORY), metas: [] }
0:03:04.451094027 537298 0x555b03d07060 LOG         audiobuffersplit gstaudiobuffersplit.c:715:gst_audio_buffer_split_sink_chain:<10-0-encoder-audio-audiobuffersplit> Processing buffer at running time 99:99:99.999999999 with timestamp 0:03:02.024240787 with duration 0:00:00.500000000 (24000 samples)
0:03:04.451101461 537298 0x555b03d07060 TRACE               livesync imp.rs:1018:gstlivesync::livesync::imp::LiveSync::src_loop_inner:<10-0-encoder-audio-audio-livesync> Waiting for clock to reach 0:00:01.500000000
cc @heftig
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information
Admin message

livesync: synchronization broken when receiving early buffer after segment update
