Dear all,

When I use pulsesink based playback, I found no sound heard very shortly(around 100ms) when resume paused playback.
The reproduce step is:
 - play 1 second (44100Hz, mono, 16bit signed short) of wav file via pulsesink,
 - pause playback around EOS (1sec),
 - seek to 0, resume.
 - pcm was dropped(no sound) around 100ms at starting of resume.


// pa_stream_write() at the end of playback

0:00:47.458404541    pulse pulsesink.c:783:gst_pulsering_stream_request_cb:<pulsesink3> got request for length 6856
0:00:47.459289550    pulse pulsesink.c:1824:gst_pulseringbuffer_commit:<pulsesink3> requesting 2276 bytes of shared memory
0:00:47.459381103    pulse pulsesink.c:1833:gst_pulseringbuffer_commit:<pulsesink3> got 2276 bytes of shared memory
0:00:47.459411621    pulse pulsesink.c:1842:gst_pulseringbuffer_commit:<pulsesink3> writing 1138 samples at offset 342180
0:00:47.459472656    pulse pulsesink.c:1895:gst_pulseringbuffer_commit:<pulsesink3> flushing 1138 samples at offset 342180
0:00:47.459564209    pulse pulsesink.c:1939:gst_pulseringbuffer_commit:<pulsesink3> wrote 1138 samples

// end of buffer, pulsesink got eos event.

0:00:47.459777832 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3> received event 0xaf8be130 eos event: 0xaf8be130, time 99:99:99.999999999, seq-num 1241, (NULL)
0:00:47.459869384 pulse pulsesink.c:1998:gst_pulsering_flush:<pulsesink3> entering flush
0:00:47.459991455 basesink gstbasesink.c:1854:gst_base_sink_get_sync_times:<pulsesink3> sync times for EOS 99:99:99.999999999
0:00:47.460052490 basesink gstbasesink.c:2308:gst_base_sink_wait:<pulsesink3> checking preroll 0

// try to wait until 3.905 sec

0:00:47.460083007 basesink gstbasesink.c:2319:gst_base_sink_wait:<pulsesink3> possibly waiting for clock to reach 0:00:01.001043084
0:00:47.460113525 basesink gstbasesink.c:2073:gst_base_sink_wait_clock:<pulsesink3> time 0:00:01.001043084, base_time 0:00:02.903992000
0:00:47.460205078    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.739977000
0:00:47.519287109    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.802569000
0:00:47.519683838    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.802989000
0:00:47.519927978    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.803247000
0:00:47.520233154    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.803602000

// waiting was broken due to application tried to pause.

0:00:47.520477295 pulse pulsesink.c:1490:gst_pulseringbuffer_pause:<pulsesink3> pausing and corking
0:00:47.520507812 pulse pulsesink.c:1355:gst_pulsering_set_corked:<pulsesink3> setting corked state to 1
0:00:47.525177002    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905315028000, 0:344456, 0:345094, 90252, 90000
0:00:47.525390625    pulse pulsesink.c:783:gst_pulsering_stream_request_cb:<pulsesink3> got request for length 10340
0:00:47.525543213    pulse pulsesink.c:801:gst_pulsering_stream_underflow_cb:<pulsesink3> Got underflow
0:00:47.526428222    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink6> type 0012, idx 347
0:00:47.526489257    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink5> type 0012, idx 347
0:00:47.526550293    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink4> type 0012, idx 347
0:00:47.526580810    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink3> type 0012, idx 347
0:00:47.526611328    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink2> type 0012, idx 347
0:00:47.526672363    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink1> type 0012, idx 347
0:00:47.526702881    pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink0> type 0012, idx 347

// read_index & write_index became 344456 (3.905 sec) after pause, it seems ok.

0:00:47.526824951    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905317561000, 0:344456, 0:344456, 80791, 90000
0:00:47.526977539    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905318721000, 0:344456, 0:344456, 79297, 90000
0:00:47.527343750 basesink gstbasesink.c:2328:gst_base_sink_wait:<pulsesink3> clock returned 2
0:00:47.527404785 basesink gstbasesink.c:2308:gst_base_sink_wait:<pulsesink3> checking preroll 1
0:00:47.528472900    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.805343000
0:00:47.537872314    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905330501000, 0:344456, 0:344456, 67521, 90000
0:00:47.559356689    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905351955000, 0:344456, 0:344456, 89655, 90000

// application try to seek & flush using pa_stream_flush()

0:00:47.592529297 basesink gstbasesink.c:4366:gst_base_sink_send_event:<pulsesink3> handling event 0xaf8be010 seek event: 0xaf8be010, time 99:99:99.999999999, seq-num 1287, GstEventSeek, rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_ACCURATE, cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:47.593109131 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3> received event 0xb85b3170 flush-start event: 0xb85b3170, time 99:99:99.999999999, seq-num 1288, (NULL)
0:00:47.593475341 basesink gstbasesink.c:3000:gst_base_sink_default_event:<pulsesink3> flush-start 0xb85b3170
0:00:47.593719482 basesink gstbasesink.c:2349:gst_base_sink_wait:<pulsesink3> we are flushing
0:00:47.594177246    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.805343000
0:00:47.594818115 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3> received event 0xb85b30e0 flush-stop event: 0xb85b30e0, time 99:99:99.999999999, seq-num 1296, GstEventFlushStop, reset-time=(boolean)true;
0:00:47.595062256 pulse pulsesink.c:1404:gst_pulseringbuffer_clear:<pulsesink3> clearing
0:00:47.597290039    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905389064000, 1:344456, 0:344456, 88854, 90000
0:00:47.597503662    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905389735000, 0:344456, 0:344456, 88153, 90000
0:00:47.597747802 basesink gstbasesink.c:3010:gst_base_sink_default_event:<pulsesink3> flush-stop 0xb85b30e0, reset_time: 1
0:00:47.600616455 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3> received event 0xaf8be178 segment event: 0xaf8be178, time 99:99:99.999999999, seq-num 1298, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_RESET, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)1001043084;";
0:00:47.601135254 basesink gstbasesink.c:1902:gst_base_sink_get_sync_times:<pulsesink3> got times start: 0:00:00.000000000, stop: 0:00:00.046439910, do_sync 0
0:00:47.601226806 basesink gstbasesink.c:1455:gst_base_sink_commit_state:<pulsesink3> commiting state to PAUSED
0:00:47.601257324 basesink gstbasesink.c:1480:gst_base_sink_commit_state:<pulsesink3> posting PAUSED state change message
0:00:47.601318359 basesink gstbasesink.c:1486:gst_base_sink_commit_state:<pulsesink3> posting async-done message
0:00:47.602111816 basesink gstbasesink.c:4413:gst_base_sink_send_event:<pulsesink3> handled event 0xaf8be010 seek event: 0xaf8be010, time 99:99:99.999999999, seq-num 1287, GstEventSeek, rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_ACCURATE, cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;: 1
0:00:47.606475830    pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3> latency_update, 1441797905399135000, 0:344456, 0:344456, 78731, 90000
0:00:47.609008789    pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3> current time is 0:00:03.805343000
0:00:47.609649658 basesink gstbasesink.c:4366:gst_base_sink_send_event:<pulsesink3> handling event 0xb85b3050 latency event: 0xb85b3050, time 99:99:99.999999999, seq-num 1310, GstEventLatency, latency=(guint64)0;
0:00:47.609985351 basesink gstbasesink.c:4413:gst_base_sink_send_event:<pulsesink3> handled event 0xb85b3050 latency event: 0xb85b3050, time 99:99:99.999999999, seq-num 1310, GstEventLatency, latency=(guint64)0;: 1

// application try to resume,
// pa_stream_write()

0:00:47.610321045 basesink gstbasesink.c:4975:gst_base_sink_change_state:<pulsesink3> PAUSED to PLAYING, don't need preroll
0:00:47.610534668 pulse pulsesink.c:1707:gst_pulseringbuffer_commit:<pulseringbuffer3> start!
0:00:47.610565185 pulse pulsesink.c:1450:gst_pulseringbuffer_start:<pulsesink3> starting
0:00:47.610595703 pulse pulsesink.c:1714:gst_pulseringbuffer_commit:<pulsesink3> entering commit
0:00:47.610626220 pulse pulsesink.c:1732:gst_pulseringbuffer_commit:<pulsesink3> in 2047, out 2047

// I expect that offset should be around "344456", but pa_stream_get_time() returns "335630".
// around 100ms of pcm couldn't heard due to discontinuity.

0:00:47.610748291    pulse pulsesink.c:1755:gst_pulseringbuffer_commit:<pulsesink3> need to write 2048 samples at offset 335630
0:00:47.610778808    pulse pulsesink.c:1759:gst_pulseringbuffer_commit:<pulsesink3> discontinuity, offset is 335630, last offset was 344456
0:00:47.610809326    pulse pulsesink.c:1824:gst_pulseringbuffer_commit:<pulsesink3> requesting 4096 bytes of shared memory
0:00:47.610870361    pulse pulsesink.c:1833:gst_pulseringbuffer_commit:<pulsesink3> got 4096 bytes of shared memory
0:00:47.610900879    pulse pulsesink.c:1842:gst_pulseringbuffer_commit:<pulsesink3> writing 2048 samples at offset 335630
0:00:47.610931396    pulse pulsesink.c:1895:gst_pulseringbuffer_commit:<pulsesink3> flushing 2048 samples at offset 335630
0:00:47.611022949    pulse pulsesink.c:1916:gst_pulseringbuffer_commit:<pulsesink3> read_index at 344456, offset 339726
0:00:47.611053466    pulse pulsesink.c:1939:gst_pulseringbuffer_commit:<pulsesink3> wrote 2048 samples
0:00:47.611206054 basesink gstbasesink.c:1902:gst_base_sink_get_sync_times:<pulsesink3> got times start: 0:00:00.046439910, stop: 0:00:00.092879819, do_sync 0



When I tried to disable interpolation timing(PA_STREAM_INTERPOLATE_TIMING) flag in pulsesink.c, the
offset move expectedly and sound heard well without this kind of drop. Please refer below test patch.

-------------------------------------------------------------------------------
diff --git a/ext/pulse/pulsesink.c b/ext/pulse/pulsesink.c
index e580afc..a10da7e 100755
--- a/ext/pulse/pulsesink.c
+++ b/ext/pulse/pulsesink.c
@@ -961,8 +961,8 @@ gst_pulseringbuffer_acquire (GstAudioRingBuffer * buf,
   }

   /* construct the flags */
-  flags = PA_STREAM_INTERPOLATE_TIMING | PA_STREAM_AUTO_TIMING_UPDATE |
-      PA_STREAM_ADJUST_LATENCY | PA_STREAM_START_CORKED;
+  flags = PA_STREAM_AUTO_TIMING_UPDATE | PA_STREAM_ADJUST_LATENCY |
+      PA_STREAM_START_CORKED;

   if (psink->mute_set) {
     if (psink->mute)
-------------------------------------------------------------------------------

I guess interpolation timing isn't correct in some special cases than index based timing, but I have no idea why.
Can you give us any feedback about this issue?  Is it proper disabling "PA_STREAM_INTERPOLATE_TIMING" flag than use it?

Regards,
KimJeongYeon