Alsa timestamps are broken when using external clocks. I've seen other bug
reports where alsasrc ! alsasink does this. Now, the issue is in time
generation. this example will focus on alsasink/alsasrc. It uses the alsasink
clock. Alsasrc starts capturing, timestamps is calculated on line 439, but we
didn't play yet, so realtime is 0, so outreal is -duration, which is negative,
so (time=guint64) ~300years.

A correct fix is to test that real >= dur before subtracting real. We may lose a
few samples because of that in the second buffer, but that's just required, I'm
affraid.

Created attachment 37208 [details] [review]
proposed workaround

Does this fix it?

Hmm...
Using gst-plugins-0.8.7.2, fakesink does not show weird times here.
Only alsasink does, and the workaround fixes it.

But: The workaround breaks the simple 'alsasrc ! alsasink' pipeline, (that
has been working reliably without it) with this error log:

INFO  (0x80508b8 - 308402:00:20.398685000)      GST_STATES(20140)
gstelement.c(2825):gst_element_set_state_func:<alsasink0> setting state from
PAUSED to PLAYING
INFO  (0x80508b8 - 308402:00:20.398736000)       scheduler(20140)
gstoptimalscheduler.c(1690):gst_opt_scheduler_state_transition: setting
scheduler state to running
INFO  (0x80508b8 - 308402:00:20.584928000)       GST_EVENT(20140)
gstevent.c(175):gst_event_new: creating new event type 4: 0x8068210
WARN  (0x80508b8 - 308402:00:20.584963000)  GST_SCHEDULING(20140)
gstpad.c(3218):_invent_event: needed to invent a DISCONT 0x8068210 (time 0) for
alsasrc0:src => alsasink0:sink
INFO  (0x80508b8 - 308402:00:20.585002000)       GST_EVENT(20140)
gstevent.c(96):_gst_event_free: freeing event 0x8068210
INFO  (0x80508b8 - 308402:00:20.956398000)            alsa(20140)
gstalsasink.c(519):gst_alsa_sink_loop:<alsasink0> Skipping 8192 samples to
resync: sample 8192 expected, but got 0
INFO  (0x80508b8 - 308402:00:21.142251000)            alsa(20140)
gstalsasink.c(519):gst_alsa_sink_loop:<alsasink0> Skipping 16378 samples to
resync: sample 16384 expected, but got 6
[Invalid UTF-8] WARN  (0x80508b8 - 308402:00:21.513521000) \x1b[00m          
alsa\x1b[00m(\x1b[335m20140\x1b[00m)
\x1b[00mpcm_hw.c(476):snd_pcm_hw_delay:\x1b[00m alsalib error:
SNDRV_PCM_IOCTL_DELAY failed: Datenubergabe unterbrochen (broken pipe)
INFO  (0x80508b8 - 308402:00:21.513598000)            alsa(20140)
gstalsasink.c(519):gst_alsa_sink_loop:<alsasink0> Skipping 8194 samples to
resync: sample 16390 expected, but got 8196
INFO  (0x80508b8 - 308402:00:21.513857000)            alsa(20140)
gstalsa.c(1727):gst_alsa_set_hw_params: Preparing format: S16_BE 44100Hz, 2 channels
INFO  (0x80508b8 - 308402:00:21.884978000)            alsa(20140)
gstalsasink.c(509):gst_alsa_sink_loop:<alsasink0> Skipping 16384 samples to
resync (complete buffer): sample 24580 expected, but got 8196
INFO  (0x80508b8 - 308402:00:22.256313000)            alsa(20140)
gstalsasink.c(509):gst_alsa_sink_loop:<alsasink0> Skipping 16384 samples to
resync (complete buffer): sample 24580 expected, but got 8196
INFO  (0x80508b8 - 308402:00:22.627734000)            alsa(20140)
gstalsasink.c(509):gst_alsa_sink_loop:<alsasink0> Skipping 16384 samples to
resync (complete buffer): sample 24580 expected, but got 8196
...

Comment on attachment 37208 [details] [review]
proposed workaround

OK, all are wrong. What we need is some way of introducing latency into a
pipeline (latency between clock provider and receiver).

Closing as a WONTFIX. Adding latency, etc to 0.8 is too much work, and we almost
have it in 0.9 now. (alsasrc is currently not stamping its buffers in HEAD, but
that will get fixed as soon as latency calculation is added -- should be a few
weeks.)