When caps changes on the sink, the clock is re-calibrated but it seems to be racy with other threads using the clock. Here is what happens:

I added some extra debug messages to make it easier to see.

1) The renegotiation starts:

0:00:37.969671518 22325  0x94eaa00 DEBUG               basesink gstbasesink.c:3157:gst_base_sink_event:<autoaudiosink0-actual-sink-alsa> received event 0xadcd0520 caps event: 0xadcd0520, time 99:99:99.999999999,
0:00:37.969714342 22325  0x94eaa00 DEBUG               basesink gstbasesink.c:3069:gst_base_sink_default_event:<autoaudiosink0-actual-sink-alsa> caps 0xadcd0520
0:00:37.969735137 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:860:gst_audio_base_sink_setcaps:<autoaudiosink0-actual-sink-alsa> release old ringbuffer
0:00:37.969889649 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:548:gst_audio_base_sink_get_time:<autoaudiosink0-actual-sink-alsa> processed samples: raw 393216, delay 9216, real 384000, time 
0:00:37.969945954 22325  0x94eaa00 ERROR             audioclock gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock> Result: 0:00:08.000000000
0:00:37.969975788 22325  0x94eaa00 ERROR             audioclock gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> + timeoffset: 0:00:21.851435231
0:00:37.970004100 22325  0x94eaa00 DEBUG             audioclock gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock> result 0:00:29.851435231, last_time 0:00:29.851435231
0:00:37.970042086 22325  0x94eaa00 DEBUG              GST_CLOCK gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time 0:00:29.851435231
0:00:37.970075551 22325  0x94eaa00 DEBUG              GST_CLOCK gstclock.c:995:gst_clock_get_time:<GstAudioSinkClock> adjusted time 0:00:29.641049743
0:00:37.970093798 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:868:gst_audio_base_sink_setcaps:<autoaudiosink0-actual-sink-alsa> time was 0:00:29.641049743

Notice how it will store the current time '29.64' to be used later.
Also notice the internal_time -> 8.00 and the timeoffset: 21.85 and the last_time -> 29.85


2) The video sink renders a frame
0:00:38.020787346 22325 0xada3c580 LOG           GST_SCHEDULING gstpad.c:3834:gst_pad_chain_data_unchecked:<webkitvideosink0:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x95980b0, pts 0:
0:00:38.020815448 22325 0xada3c580 DEBUG               basesink gstbasesink.c:3329:gst_base_sink_chain_unlocked:<webkitvideosink0> got times start: 0:00:29.416666666, end: 0:00:29.458333332
0:00:38.020841219 22325 0xada3c580 DEBUG               basesink gstbasesink.c:1897:gst_base_sink_get_sync_times:<webkitvideosink0> got times start: 0:00:29.416666666, stop: 0:00:29.458333332, do_sync 1
0:00:38.020866168 22325 0xada3c580 LOG                 basesink gstbasesink.c:2430:gst_base_sink_do_sync:<webkitvideosink0> avg frame diff 0:00:00.185774346
0:00:38.020884193 22325 0xada3c580 DEBUG               basesink gstbasesink.c:2470:gst_base_sink_do_sync:<webkitvideosink0> reset rc_time to time 0:00:29.416666666
0:00:38.020899970 22325 0xada3c580 DEBUG               basesink gstbasesink.c:2482:gst_base_sink_do_sync:<webkitvideosink0> possibly waiting for clock to reach 0:00:29.416666666, adjusted 0:00:29.416666666
0:00:38.020920275 22325 0xada3c580 LOG                 basesink gstbasesink.c:2068:gst_base_sink_wait_clock:<webkitvideosink0> time 0:00:29.416666666, base_time 0:00:00.000000000
0:00:38.020942711 22325 0xada3c580 DEBUG              GST_CLOCK gstclock.c:533:gst_clock_id_wait:<GstAudioSinkClock> waiting on clock entry 0xadcf2378
0:00:38.020965430 22325 0xada3c580 DEBUG          audiobasesink gstaudiobasesink.c:548:gst_audio_base_sink_get_time:<autoaudiosink0-actual-sink-alsa> processed samples: raw 394240, delay 0, real 394240, time 0:0
0:00:38.020987087 22325 0xada3c580 ERROR             audioclock gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock> Result: 0:00:08.213333333
0:00:38.021003828 22325 0xada3c580 ERROR             audioclock gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> + timeoffset: 0:00:21.851435231
0:00:38.021020087 22325 0xada3c580 DEBUG             audioclock gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock> result 0:00:30.064768564, last_time 0:00:30.064768564
0:00:38.021039992 22325 0xada3c580 DEBUG              GST_CLOCK gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time 0:00:30.064768564
0:00:38.021058124 22325 0xada3c580 DEBUG              GST_CLOCK gstclock.c:995:gst_clock_get_time:<GstAudioSinkClock> adjusted time 0:00:29.854383076

Nothing really wrong here (yet)


3) audio sink continues the negotiation and *resets the clock* as part of gst_audio_sink_ring_buffer_acquire to make the clock start from 0 again

0:00:38.023680401 22325  0x94eaa00 DEBUG             audioclock gstaudioclock.c:173:gst_audio_clock_reset:<GstAudioSinkClock> reset clock to 0:00:00.000000000, last 0:00:30.064768564, offset 0:00:30.064768564
0:00:38.023807328 22325  0x94eaa00 INFO              ringbuffer gstaudioringbuffer.c:573:gst_audio_ring_buffer_acquire:<audiosinkringbuffer0> Allocating an array for 9 timestamps
0:00:38.023846821 22325  0x94eaa00 DEBUG             ringbuffer gstaudioringbuffer.c:603:gst_audio_ring_buffer_acquire:<audiosinkringbuffer0> acquired device
0:00:38.023861024 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:894:gst_audio_base_sink_setcaps:<autoaudiosink0-actual-sink-alsa> activate ringbuffer
0:00:38.023874256 22325  0x94eaa00 DEBUG             ringbuffer gstaudioringbuffer.c:763:gst_audio_ring_buffer_activate:<audiosinkringbuffer0> activate device
0:00:38.023898862 22325  0x94eaa00 DEBUG              audiosink gstaudiosink.c:445:gst_audio_sink_ring_buffer_activate:<autoaudiosink0-actual-sink-alsa> starting thread
0:00:38.023946052 22325  0x94eaa00 DEBUG              audiosink gstaudiosink.c:453:gst_audio_sink_ring_buffer_activate:<autoaudiosink0-actual-sink-alsa> waiting for thread

Here's when the bad things happen. Now the clock offset is at 30.06.

4) A position query happens:
0:00:38.024022982 22325  0x8ccc360 ERROR             audioclock gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock> Result: 0:00:08.192000000
0:00:38.024042358 22325  0x8ccc360 ERROR             audioclock gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> + timeoffset: 0:00:30.064768564
0:00:38.024061434 22325  0x8ccc360 DEBUG             audioclock gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock> result 0:00:38.256768564, last_time 0:00:38.256768564
0:00:38.024087391 22325  0x8ccc360 DEBUG              GST_CLOCK gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time 0:00:38.256768564
0:00:38.024108207 22325  0x8ccc360 DEBUG              GST_CLOCK gstclock.c:995:gst_clock_get_time:<GstAudioSinkClock> adjusted time 0:00:38.046383076
0:00:38.024129431 22325  0x8ccc360 DEBUG               basesink gstbasesink.c:4577:gst_base_sink_get_position:<autoaudiosink0-actual-sink-alsa> now 0:00:38.046383076 - base_time 0:00:00.000000000 - base 0:00:00.000000000 + time 0:00:00.000000000  last 0:00:29.819333333
0:00:38.024165394 22325  0x8ccc360 DEBUG               basesink gstbasesink.c:4590:gst_base_sink_get_position:<autoaudiosink0-actual-sink-alsa> res: 1, POSITION: 0:00:29.819333333
0:00:38.024197783 22325  0x8ccc360 DEBUG               basesink gstbasesink.c:4787:default_element_query:<autoaudiosink0-actual-sink-alsa> query position returns 1

The query actually returns the correct 29s position, but it has the side effect of updating the last_time in the clock to 38.25

5) setcaps continues and the clock is recalibrated (wrongly...)
0:00:38.030842676 22325  0x94eaa00 DEBUG              audiosink gstaudiosink.c:456:gst_audio_sink_ring_buffer_activate:<autoaudiosink0-actual-sink-alsa> thread is started
0:00:38.030867116 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:548:gst_audio_base_sink_get_time:<autoaudiosink0-actual-sink-alsa> processed samples: raw 0, delay 0, real 0, time 0:00:00.00000
0:00:38.030889831 22325  0x94eaa00 ERROR             audioclock gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock> Result: 0:00:00.000000000
0:00:38.030907637 22325  0x94eaa00 ERROR             audioclock gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> + timeoffset: 0:00:30.064768564
0:00:38.030924223 22325  0x94eaa00 DEBUG             audioclock gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock> result 0:00:38.256768564, last_time 0:00:38.256768564
0:00:38.030945841 22325  0x94eaa00 DEBUG              GST_CLOCK gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time 0:00:38.256768564
0:00:38.030966176 22325  0x94eaa00 DEBUG              GST_CLOCK gstclock.c:1050:gst_clock_set_calibration:<GstAudioSinkClock> internal 0:00:38.256768564 external 0:00:29.641049743 1/1 = 1.000000

Because the last sample was updated to 38.25s, the recalibration will use that as the new internal time, while the external (the value got in step 1) was 29.64 and at that time the internal time was much different (smaller).

6) Rendering will be delayed because the clock jumped ahead (will translate ~29s to ~38s and always add those 9s to timestamps)
0:00:38.068158241 22325  0x94eaa00 DEBUG               basesink gstbasesink.c:3329:gst_base_sink_chain_unlocked:<autoaudiosink0-actual-sink-alsa> got times start: 0:00:29.789297052, end: 0:00:29.812517007
0:00:38.068190035 22325  0x94eaa00 DEBUG               basesink gstbasesink.c:1897:gst_base_sink_get_sync_times:<autoaudiosink0-actual-sink-alsa> got times start: 0:00:29.789297052, stop: 0:00:29.812517007, do_sync 0
0:00:38.068206523 22325  0x94eaa00 DEBUG               basesink gstbasesink.c:3411:gst_base_sink_chain_unlocked:<autoaudiosink0-actual-sink-alsa> rendering object 0xada8eb28
0:00:38.068218646 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:1695:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa> time 0:00:29.789297052, offset -1, start 0:00:00.000000000, samples 1024
0:00:38.068235753 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:1732:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa> sync-offset 0, render-delay 0:00:00.000000000, ts-offset 0
0:00:38.068248476 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:1794:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa> running: start 0:00:29.789297052 - stop 0:00:29.812517006
0:00:38.068299882 22325  0x94eaa00 DEBUG          audiobasesink gstaudiobasesink.c:1836:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa> final timestamps: start 0:00:38.405015873 - stop 0:00:38.42823