Thanks for the help Tanu. It's very much appreciated.
>> I've*finally* managed to get PulseAudio running on the test workstation
>> with extra logging in pa_source_output_push()!
>>
>> I've attached a copy of pa_source_output_push() with the extra log
>> statements to show where they are. Also, about 1second of gzipped
>> output is attached (because otherwise there's a*lot* of output).
> It seems that you're logging to syslog. In case you didn't know, you
> can also run pulseaudio in a terminal and get the logs in the terminal,
> or if running pulseaudio as a background process is important, it's
> possible to set "log-target = newfile:/tmp/pulselog.txt" in
> /etc/pulse/daemon.conf, or to pass --log-
> target=newfile:/tmp/pulselog.txt on the command line. Of course, if you
> prefer to use syslog for some reason, I have no problem with that.
Given the difficult environment on the test workstation, I've stuck with
syslog just because it's easy.
I've attached the modified pa_source_output_push() and highly pruned,
gzipped output as before.
>> I don't fully understand what's going on, but here are a few things I
>> noticed, which may be suspicious:
>>
>> * There seems to be a number of source-outputs logging output, but
>> I assume the relevant one for module-remap-source is the one with the
>> PA_RESAMPLER_NO_REMIX ("flags=0x04") flag set because of the "remix=no"
>> parameter I gave it.
> If you have pavucontrol running, it will create source outputs for both
> the null sink monitor and the remap source to be able to get the data
> for the volume meters.
>
> I think it would be good to log the source name and some identifier for
> the source output (either just the source output index, or some more
> readable data from the source output proplist).
The latest logging logs source-output creation and outputs the
source-output index, module, source and destination_source names. Any
other output is only done if source or destination_source names are
"voip_source".
The notable events are as follows:
   * At 06:20:00 the source outputs for module-remap-source and
module-rtp-send are created.
   * At 06:21:08 the binary that uses the PulseAudio API to connect to
the rtp_in_sink0.monitor an rtp_in_sink1.monitor sources starts,
creating new source outputs associated with module-native-protocol-unix.
   * At 06:22:01 pavucontrol starts, creating a whole lot of source
outputs, including one for "voip_source", which is one of the source
outputs that has a max_rewind of 2304000bytes.
   * At 06:22:36 another computer attempts to connect with a VoIP
call, which isn't accepted until 06::23:00. One additional source
output for "voip_source" is created at 06:22:36 and has max_rewind of
2304000bytes. No notable event seems to happen at 06:23:00.
   * All source outputs change max_rewind from zero to nonzero soon
after creation, but the only source outputs that ever change max_rewind
beyond that are thos associated with module-rtp-send.
>> * Whenever this source-output calls this function (outputting
>> "rsmplr=30, flags=0x4" in the while loop), there seems to always be
>> another immediately following call (outputting "limit=2304000bytes (1)"
>> at the start of the function) with the*large* 2304000bytes limit that
>> never executes the following "if" and "while" statement bodies. Hence
>> it never calls o->push().
> The limit is the source's max rewind amount, and I see a bug related to
> that in module-remap-source (I wouldn't be surprised if it's in other
> filter sources too). The remap source max rewind is supposed to mirror
> the master source max rewind, but when the master source max rewind
> changes, the remap source max rewind isn't updated. The remap source
> should set the update_max_rewind source output callback, and use the
> callback to update its own max rewind to match the master source.
>
> If the max rewind isn't updated, as is now the case, it will stay at
> whatever value the master source had when the remap source got loaded.
> At that time there are likely no streams that are forcing lower
> latency, leading to a too high max rewind value when a low latency
> stream appears.
This seems to be confirmed by the fact that the only max_rewind changes
(other than after creation) happen in the module-rtp-send module.
Given the platform configuration difficulties I have, can you think of a
CLI-based work-around for this?
Steve
-------------- next part --------------
A non-text attachment was scrubbed...
Name: logging.c
Type: text/x-csrc
Size: 5290 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20171027/d03bd1c3/attachment-0001.c>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: palog.gz
Type: application/gzip
Size: 22298 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20171027/d03bd1c3/attachment-0001.gz>
