Attachment 112049 Details for Bug 87814 – second mono playback (100% -> 95%)

second mono playback (100% -> 95%)

pulse-2.log (text/plain), 24.15 KB, created by Radics Péter on 2015-01-10 09:41:16 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Radics Péter

Created: 2015-01-10 09:41:16 UTC

Size: 24.15 KB

patch

obsolete

># 10:25:00: aplay test.wav
># 10:25:10: change volume of aplay stream from 100% to below 100% (1 step)
># 10:25:44: end of playback
>
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.013| 166.746) [pulseaudio][pulsecore/client.c:80 pa_client_new()] Created 63 "Native client (UNIX socket client)"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.013|   0.000) [pulseaudio][pulsecore/protocol-native.c:2601 command_auth()] Protocol version: remote 29, local 29
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.013|   0.000) [pulseaudio][pulsecore/protocol-native.c:2634 command_auth()] Got credentials: uid=1000 gid=100 success=1
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.013|   0.000) [pulseaudio][pulsecore/protocol-native.c:2664 command_auth()] SHM possible: yes
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.013|   0.000) [pulseaudio][pulsecore/protocol-native.c:2682 command_auth()] Negotiated SHM: yes
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.013|   0.000) [pulseaudio][modules/module-augment-properties.c:270 process()] Looking for .desktop file for aplay
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.001) [pulseaudio][modules/module-intended-roles.c:87 sink_input_new_hook_callback()] Not setting device for stream ALSA Playback, because already set.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][pulsecore/sink-input.c:343 pa_sink_input_new()] Negotiated format: pcm, format.sample_format = "\"s16le\""  format.rate = "16000"  format.channels = "1"  format.channel_map = "\"mono\""
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][pulsecore/sink-input.c:414 pa_sink_input_new()] Trying to change sample rate
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][pulsecore/sink.c:1453 pa_sink_update_rate()] Suspending sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo due to changing the sample rate.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][modules/alsa/alsa-sink.c:1604 sink_update_rate_cb()] Sink does not support sample rate of 48000 Hz
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][modules/module-stream-restore.c:1478 sink_input_fixate_hook_callback()] Restoring volume for sink input sink-input-by-application-name:ALSA plug-in [aplay].
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][modules/module-suspend-on-idle.c:125 resume()] Sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo becomes busy, resuming.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.015|   0.000) [pulseaudio][pulsecore/sink.c:879 pa_sink_suspend()] Suspend cause of sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo is 0x0000, resuming
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.016|   0.000) [pulseaudio][modules/reserve-wrap.c:165 pa_reserve_wrapper_get()] Successfully acquired reservation lock on device 'Audio1'
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.016|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1066 unsuspend()] Trying resume...
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.017|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-util.c:250 pa_alsa_set_hw_params()] Disabling tsched mode since BATCH flag is set
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.017|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-util.c:312 pa_alsa_set_hw_params()] Maximum hw buffer size is 5944 ms
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.017|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-util.c:326 pa_alsa_set_hw_params()] Set buffer size first (to 4408 samples), period size second (to 1102 samples).
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.017|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:991 update_sw_params()] hwbuf_unused=0
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.018|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1003 update_sw_params()] setting avail_min=1
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.018|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1132 unsuspend()] Resumed successfully...
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.022|   0.004) [pulseaudio][modules/module-suspend-on-idle.c:114 restart()] Sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo becomes idle, timeout in 5 seconds.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.022|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1730 thread_func()] Starting playback.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.022|   0.000) [pulseaudio][modules/module-suspend-on-idle.c:114 restart()] Sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo becomes idle, timeout in 5 seconds.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:1149 calc_map_table()] Channel matrix:
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:1149 calc_map_table()]        I00
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:1149 calc_map_table()]     +------
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:1149 calc_map_table()] O00 | 1.000
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:1149 calc_map_table()] O01 | 1.000
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/remap_sse.c:144 init_remap_sse2()] Using SSE2 mono to stereo remapping
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:445 pa_resampler_new()] Resampler:
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:446 pa_resampler_new()]   rate 16000 -> 44100 (method speex-float-1)
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:448 pa_resampler_new()]   format s16le -> s16le (intermediate float32le)
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:449 pa_resampler_new()]   channels 1 -> 2 (resampling 1)
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.023|   0.000) [pulseaudio][pulsecore/resampler.c:1570 speex_init()] Choosing speex quality setting 1.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/memblockq.c:87 pa_memblockq_new()] memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/memblockq.c:98 pa_memblockq_new()] memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()] Created input 11 "ALSA Playback" on alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo with sample spec s16le 1ch 16000Hz and channel map mono
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     media.name = "ALSA Playback"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.name = "ALSA plug-in [aplay]"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     native-protocol.peer = "UNIX socket client"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     native-protocol.version = "29"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.process.id = "4299"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.process.user = "mitch"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.process.host = "foo.example.com"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.process.binary = "aplay"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.language = "en_US.UTF-8"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     window.x11.display = ":0"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.process.machine_id = "2c82e923567a4beda42b710f9a9006cf"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     application.process.session_id = "c4"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.024|   0.000) [pulseaudio][pulsecore/sink-input.c:572 pa_sink_input_new()]     module-stream-restore.id = "sink-input-by-application-name:ALSA plug-in [aplay]"
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.029|   0.004) [pulseaudio][pulsecore/protocol-native.c:961 fix_playback_buffer_attr()] Requested tlength=500.00 ms, minreq=125.00 ms
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.029|   0.000) [pulseaudio][pulsecore/protocol-native.c:970 fix_playback_buffer_attr()] Early requests mode enabled, configuring sink latency to minreq.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.004) [pulseaudio][pulsecore/protocol-native.c:1033 fix_playback_buffer_attr()] Requested latency=125.00 ms, Received latency=99.95 ms
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [pulseaudio][pulsecore/memblockq.c:87 pa_memblockq_new()] memblockq requested: maxlength=4194304, tlength=16000, base=2, prebuf=4000, minreq=3198 maxrewind=0
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [pulseaudio][pulsecore/memblockq.c:98 pa_memblockq_new()] memblockq sanitized: maxlength=4194304, tlength=16000, base=2, prebuf=4000, minreq=3198 maxrewind=0
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [pulseaudio][pulsecore/protocol-native.c:1229 playback_stream_new()] Final latency 599.95 ms = 300.12 ms + 2*99.94 ms + 99.95 ms
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1337 sink_set_volume_cb()] Requested volume: front-left: 13120 /  20% / -41.91 dB,   front-right: 13120 /  20% / -41.91 dB
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1339 sink_set_volume_cb()] Got hardware volume: front-left: 13588 /  21% / -41.00 dB,   front-right: 13588 /  21% / -41.00 dB
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1342 sink_set_volume_cb()] Calculated software volume: front-left: 63279 /  97% / -0.91 dB,   front-right: 63279 /  97% / -0.91 dB (accurate-enough=no)
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.033|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:3576 pa_sink_volume_change_push()] Volume not changing
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.034|   0.000) [pulseaudio][pulsecore/core-subscribe.c:244 pa_subscription_post()] Dropped redundant event due to change event.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.001) [alsa-sink-USB Audio][pulsecore/protocol-native.c:1413 handle_seek()] Requesting rewind due to end of underrun.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1630 process_rewind()] Requested to rewind 17632 bytes.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1653 process_rewind()] Limited to 17376 bytes.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1656 process_rewind()] before: 4344
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1664 process_rewind()] after: 4344
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1672 process_rewind()] Rewound 17376 bytes.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.035|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:993 pa_sink_process_rewind()] Processing rewind...
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.036|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:3693 pa_sink_volume_change_rewind()] latency = 6399
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.036|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1067 pa_sink_input_process_rewind()] Have to rewind 17376 bytes on render memblockq.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.036|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1067 pa_sink_input_process_rewind()] Have to rewind 17376 bytes on render memblockq.
>Jan 10 10:25:00 foo.example.com pulseaudio[3356]: (1713.039|   0.003) [alsa-sink-USB Audio][pulsecore/source.c:899 pa_source_process_rewind()] Processing rewind...
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|  10.123) [pulseaudio][pulsecore/protocol-native.c:3785 command_set_volume()] Client kdeinit4 changes volume of sink input ALSA Playback.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1630 process_rewind()] Requested to rewind 17632 bytes.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1653 process_rewind()] Limited to 17376 bytes.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1656 process_rewind()] before: 4344
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1664 process_rewind()] after: 4344
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|   0.000) [pulseaudio][modules/module-stream-restore.c:1388 subscribe_callback()] Storing volume/mute/device for stream sink-input-by-application-name:ALSA plug-in [aplay].
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.163|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1672 process_rewind()] Rewound 17376 bytes.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:993 pa_sink_process_rewind()] Processing rewind...
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:3693 pa_sink_volume_change_rewind()] latency = 7185
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1067 pa_sink_input_process_rewind()] Have to rewind 17376 bytes on render memblockq.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1067 pa_sink_input_process_rewind()] Have to rewind 17376 bytes on render memblockq.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1092 pa_sink_input_process_rewind()] Have to rewind 3154 bytes on implementor.
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [alsa-sink-USB Audio][pulsecore/source.c:899 pa_source_process_rewind()] Processing rewind...
>Jan 10 10:25:10 foo.example.com pulseaudio[3356]: (1723.164|   0.000) [pulseaudio][pulsecore/protocol-native.c:3875 command_set_mute()] Client kdeinit4 changes mute of sink input ALSA Playback.
>Jan 10 10:25:20 foo.example.com pulseaudio[3356]: (1733.164|   9.999) [pulseaudio][modules/module-stream-restore.c:972 save_time_callback()] Synced.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.701|  23.537) [alsa-sink-USB Audio][pulsecore/protocol-native.c:1600 handle_input_underrun()] Implicit drain of 'ALSA Playback'
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.702|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 1964 bytes ago (15668 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.702|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 1964 bytes ago (15668 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.702|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 1964 bytes ago (15668 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.713|   0.010) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 3728 bytes ago (13904 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.713|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 3728 bytes ago (13904 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.726|   0.013) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 6376 bytes ago (11256 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.734|   0.007) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 7256 bytes ago (10376 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.734|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 7256 bytes ago (10376 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.751|   0.017) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 10784 bytes ago (6848 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.774|   0.023) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 14312 bytes ago (3320 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.774|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 14312 bytes ago (3320 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.776|   0.001) [alsa-sink-USB Audio][pulsecore/sink.c:969 pa_sink_process_input_underruns()] Found underrun 15196 bytes ago (2436 bytes ahead in playback buffer)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.801|   0.025) [alsa-sink-USB Audio][pulsecore/protocol-native.c:1607 handle_input_underrun()] Drain acknowledged of 'ALSA Playback'
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.802|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1929 pa_sink_input_set_state_within_thread()] Requesting rewind due to corking
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.802|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1630 process_rewind()] Requested to rewind 0 bytes.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.802|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1679 process_rewind()] Mhmm, actually there is nothing to rewind.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.802|   0.000) [pulseaudio][modules/module-suspend-on-idle.c:114 restart()] Sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo becomes idle, timeout in 5 seconds.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.805|   0.003) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1337 sink_set_volume_cb()] Requested volume: front-left: 13120 /  20% / -41.91 dB,   front-right: 13120 /  20% / -41.91 dB
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.805|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1339 sink_set_volume_cb()] Got hardware volume: front-left: 13588 /  21% / -41.00 dB,   front-right: 13588 /  21% / -41.00 dB
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1342 sink_set_volume_cb()] Calculated software volume: front-left: 63279 /  97% / -0.91 dB,   front-right: 63279 /  97% / -0.91 dB (accurate-enough=no)
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:3576 pa_sink_volume_change_push()] Volume not changing
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [pulseaudio][modules/module-suspend-on-idle.c:114 restart()] Sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo becomes idle, timeout in 5 seconds.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [pulseaudio][pulsecore/sink-input.c:730 sink_input_free()] Freeing input 11 "ALSA Playback"
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [pulseaudio][pulsecore/client.c:102 pa_client_free()] Freed 63 "ALSA plug-in [aplay]"
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [pulseaudio][pulsecore/protocol-native.c:4903 pstream_die_callback()] Connection died.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1630 process_rewind()] Requested to rewind 17632 bytes.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1653 process_rewind()] Limited to 16492 bytes.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1656 process_rewind()] before: 4123
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1664 process_rewind()] after: 4123
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.806|   0.000) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:1672 process_rewind()] Rewound 16492 bytes.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.807|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:993 pa_sink_process_rewind()] Processing rewind...
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.808|   0.000) [alsa-sink-USB Audio][pulsecore/sink.c:3693 pa_sink_volume_change_rewind()] latency = 7774
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.808|   0.000) [alsa-sink-USB Audio][pulsecore/sink-input.c:1067 pa_sink_input_process_rewind()] Have to rewind 16492 bytes on render memblockq.
>Jan 10 10:25:44 foo.example.com pulseaudio[3356]: (1756.809|   0.000) [alsa-sink-USB Audio][pulsecore/source.c:899 pa_source_process_rewind()] Processing rewind...
>Jan 10 10:25:49 foo.example.com pulseaudio[3356]: (1761.807|   4.997) [pulseaudio][modules/module-suspend-on-idle.c:92 timeout_cb()] Sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo idle for too long, suspending ...
>Jan 10 10:25:49 foo.example.com pulseaudio[3356]: (1761.807|   0.000) [pulseaudio][pulsecore/sink.c:879 pa_sink_suspend()] Suspend cause of sink alsa_output.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.analog-stereo is 0x0004, suspending
>Jan 10 10:25:49 foo.example.com pulseaudio[3356]: (1761.919|   0.111) [alsa-sink-USB Audio][modules/alsa/alsa-sink.c:954 suspend()] Device suspended...
>Jan 10 10:25:49 foo.example.com pulseaudio[3356]: (1761.919|   0.000) [pulseaudio][pulsecore/core.c:273 pa_core_maybe_vacuum()] All sinks and sources are suspended, vacuuming memory
>Jan 10 10:25:49 foo.example.com pulseaudio[3356]: (1761.920|   0.000) [pulseaudio][modules/module-udev-detect.c:296 verify_access()] /dev/snd/controlC1 is accessible: yes
>Jan 10 10:25:49 foo.example.com pulseaudio[3356]: (1761.920|   0.000) [pulseaudio][modules/module-udev-detect.c:363 verify_access()] Resuming all sinks and sources of card alsa_card.usb-Logitech_Inc._Logitech_USB_Headset_H340-00-H340.

Actions: View

Attachments on bug 87814: 111445 | 111446 | 112048 | 112049 | 112803 | 112804 | 112807 | 113244 | 113245

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.