# 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.