search

janvda / balena-pulseaudio

Is a balena application running a pulseaudio server and demonstrating how it can be used for playing and recording audio on a raspberry pi. It also supports bluetooth audio devices.
Eclipse Public License 2.0
6 stars 2 forks source link

terrible playback on bluetooth gear with profile "headset_head_unit" #4

Closed janvda closed 5 years ago

janvda commented 5 years ago

same problem with sony SRS-X11

janvda commented 5 years ago

The log file below covers

  1. the connection to my bluetooth speaker Device A0:E9:DB:09:CF:FF GEAR4 SPW. To connect: within bluetoothctlsession, I entered connect A0:E9:DB:09:CF:FF
  2. playback of audio file by command paplay LRMonoPhase4.wav

The quality of the audio was bad. You could still hear what is said, but with a lot of noise.

30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF
30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: dbus: path=/Profile/HSPAGProfile, interface=org.bluez.Profile1, member=NewConnection
30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: dbus: NewConnection path=/org/bluez/hci0/dev_A0_E9_DB_09_CF_FF, fd=16, profile headset_head_unit
30.08.19 08:12:25 (+0200)  pulseaudio-server  I: [pulseaudio] backend-native.c: doing listen
30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 state: disconnected -> idle
30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 available for profile headset_head_unit
30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=07
30.08.19 08:12:25 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> OK
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Timeout expired, and device /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF still has disconnected profiles: a2dp_sink
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluez5-discover.c: Loading module-bluez5-device path=/org/bluez/hci0/dev_A0_E9_DB_09_CF_FF autodetect_mtu=0
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] module-card-restore.c: Restoring port latency offsets for card bluez_card.A0_E9_DB_09_CF_FF.
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] card.c: Created 0 "bluez_card.A0_E9_DB_09_CF_FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluez5-device.c: Acquiring transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] backend-native.c: doing connect
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] module-bluez5-device.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 acquired: fd 8
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 state: idle -> playing
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] card.c: Setting card bluez_card.A0_E9_DB_09_CF_FF profile headset_head_unit to availability status yes
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-output to status yes
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-input to status yes
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Restoring volume for sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: mono: 30584 /  47%
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c: Created sink 2 "bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit" with sample spec s16le 1ch 8000Hz and channel map mono
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     bluetooth.protocol = "headset_head_unit"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.intended_roles = "phone"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.description = "GEAR4 SPW"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.string = "A0:E9:DB:09:CF:FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.api = "bluez"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.class = "sound"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.bus = "bluetooth"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.form_factor = "headset"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     bluez.path = "/org/bluez/hci0/dev_A0_E9_DB_09_CF_FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     bluez.class = "0x240404"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     bluez.alias = "GEAR4 SPW"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] sink.c:     device.icon_name = "audio-headset-bluetooth"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c: Created source 3 "bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor" with sample spec s16le 1ch 8000Hz and channel map mono
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.description = "Monitor of GEAR4 SPW"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.class = "monitor"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.string = "A0:E9:DB:09:CF:FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.api = "bluez"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.bus = "bluetooth"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.form_factor = "headset"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluez.path = "/org/bluez/hci0/dev_A0_E9_DB_09_CF_FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluez.class = "0x240404"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluez.alias = "GEAR4 SPW"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.icon_name = "audio-headset-bluetooth"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.intended_roles = "phone"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c: Created source 4 "bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit" with sample spec s16le 1ch 8000Hz and channel map mono
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluetooth.protocol = "headset_head_unit"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.intended_roles = "phone"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.description = "GEAR4 SPW"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.string = "A0:E9:DB:09:CF:FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.api = "bluez"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.class = "sound"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.bus = "bluetooth"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.form_factor = "headset"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluez.path = "/org/bluez/hci0/dev_A0_E9_DB_09_CF_FF"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluez.class = "0x240404"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     bluez.alias = "GEAR4 SPW"
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] source.c:     device.icon_name = "audio-headset-bluetooth"
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: IO Thread starting up
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [bluetooth] core-util.c: Failed to acquire real-time scheduling: Not supported
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 resuming
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Stream properly set up, we're ready to roll!
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: INIT -> IDLE
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: state: INIT -> IDLE
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-device-restore.c: Could not set format on sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluetooth-policy.c: Profile headset_head_unit cannot be selected for loopback
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] core.c: configured_default_sink: alsa_output.default -> bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] core.c: default_sink: alsa_output.default -> bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-switch-on-connect.c: No sink inputs to move away.
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit: state: INIT -> IDLE
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluetooth-policy.c: Profile headset_head_unit cannot be selected for loopback
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Source bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] core.c: configured_default_source: alsa_input.hw_1_0 -> bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] core.c: default_source: alsa_input.hw_1_0 -> bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] module-switch-on-connect.c: No source outputs to move away.
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> +VGM=15
30.08.19 08:12:28 (+0200)  pulseaudio-server  I: [pulseaudio] module.c: Loaded "module-bluez5-device" (index: #29; argument: "path=/org/bluez/hci0/dev_A0_E9_DB_09_CF_FF autodetect_mtu=0").
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [avahi-ml] module-zeroconf-publish.c: Successfully created entry group for root@ba7c427: GEAR4 SPW.
30.08.19 08:12:28 (+0200)  pulseaudio-server  D: [avahi-ml] module-zeroconf-publish.c: Successfully created entry group for root@ba7c427: GEAR4 SPW.
30.08.19 08:12:29 (+0200)  pulseaudio-server  I: [avahi-ml] module-zeroconf-publish.c: Successfully established service root@ba7c427: GEAR4 SPW.
30.08.19 08:12:29 (+0200)  pulseaudio-server  I: [avahi-ml] module-zeroconf-publish.c: Successfully established service root@ba7c427: GEAR4 SPW.
30.08.19 08:12:32 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF
30.08.19 08:12:33 (+0200)  pulseaudio-server  I: [pulseaudio] module-suspend-on-idle.c: Source bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit idle for too long, suspending ...
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit: suspend_cause: (none) -> IDLE
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit: state: IDLE -> SUSPENDED
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
30.08.19 08:12:33 (+0200)  pulseaudio-server  I: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit idle for too long, suspending ...
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Releasing transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16
30.08.19 08:12:33 (+0200)  pulseaudio-server  I: [bluetooth] backend-native.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 released
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Audio stream torn down
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: suspend_cause: (none) -> IDLE
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: IDLE -> SUSPENDED
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: suspend_cause: (none) -> IDLE
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: state: IDLE -> SUSPENDED
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 state: playing -> idle
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] card.c: Setting card bluez_card.A0_E9_DB_09_CF_FF profile headset_head_unit to availability status unknown
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-output to status unknown
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-input to status unknown
30.08.19 08:12:33 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] client.c: Created 1 "Native client (UNIX socket client)"
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Protocol version: remote 32, local 32
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Got credentials: uid=0 gid=0 success=1
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: SHM possible: yes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Memfd possible: yes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Negotiated SHM type: shared memfd
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblock.c: Using shared memfd memory pool with 1024 slots of size 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65496
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] srbchannel.c: SHM block is 65496 bytes, ringbuffer capacity is 2 * 32724 bytes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Enabling srbchannel...
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for pacat
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Client enabled srbchannel.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-intended-roles.c: Not setting device for stream LRMonoPhase4.wav, because it lacks role.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] sink-input.c: Negotiated format: pcm, format.sample_format = "\"s16le\""  format.rate = "48000"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c: Trying to change sample rate
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes busy, resuming.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Acquiring transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [bluetooth] backend-native.c: doing connect
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 acquired: fd 40
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 resuming
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Stream properly set up, we're ready to roll!
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: suspend_cause: IDLE -> (none)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: SUSPENDED -> IDLE
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: suspend_cause: IDLE -> (none)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: state: SUSPENDED -> IDLE
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Resampler:
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   rate 48000 -> 8000 (method speex-float-1)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   format s16le -> s16le (intermediate float32le)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   channels 2 -> 1 (resampling 1)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Channel matrix:
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:        I00   I01 
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:     +------------
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: O00 | 0.500 0.500
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] remap_neon.c: Using ARM NEON stereo to mono remapping
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] speex.c: Choosing speex quality setting 1.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=2, prebuf=0, minreq=1 maxrewind=0
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=2, prebuf=0, minreq=2 maxrewind=0
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c: Created input 1 "LRMonoPhase4.wav" on bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit with sample spec s16le 2ch 48000Hz and channel map front-left,front-right
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     media.format = "WAV (Microsoft)"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.name = "paplay"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     media.name = "LRMonoPhase4.wav"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     native-protocol.version = "32"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.id = "543"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.user = "root"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.host = "ba7c427"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.binary = "pacat"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     window.x11.display = "192.168.1.5:0"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.machine_id = "9fade966265e32f64990ed195d67c02a"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:paplay"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Requested tlength=2000.00 ms, minreq=20.00 ms
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Traditional mode enabled, modifying sink usec only for compat with minreq.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Requested latency=1960.00 ms, Received latency=28.00 ms
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=384000, base=4, prebuf=380164, minreq=3840 maxrewind=0
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=384000, base=4, prebuf=380164, minreq=3840 maxrewind=0
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Final latency 2028.00 ms = 1960.00 ms + 2*20.00 ms + 28.00 ms
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: IDLE -> RUNNING
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 state: idle -> playing
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] card.c: Setting card bluez_card.A0_E9_DB_09_CF_FF profile headset_head_unit to availability status yes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-output to status yes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-input to status yes
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluez5-device.c: Resuming source bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit because its transport state changed to playing
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit: suspend_cause: IDLE -> (none)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit: state: SUSPENDED -> IDLE
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluez5-device.c: Resuming sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit because its transport state changed to playing
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [bluetooth] protocol-native.c: Requesting rewind due to end of underrun.
30.08.19 08:13:02 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=06
30.08.19 08:13:02 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: The reference volume of sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit changed from mono: 30584 /  47% to mono: 26215 /  40%.
30.08.19 08:13:02 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> OK
30.08.19 08:13:02 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Storing volume/mute for device+port sink:bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit:headset-output.
30.08.19 08:13:03 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=05
30.08.19 08:13:03 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: The reference volume of sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit changed from mono: 26215 /  40% to mono: 21846 /  33%.
30.08.19 08:13:03 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> OK
30.08.19 08:13:03 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Storing volume/mute for device+port sink:bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit:headset-output.
30.08.19 08:13:04 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=04
30.08.19 08:13:04 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: The reference volume of sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit changed from mono: 21846 /  33% to mono: 17477 /  27%.
30.08.19 08:13:04 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> OK
30.08.19 08:13:04 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Storing volume/mute for device+port sink:bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit:headset-output.
30.08.19 08:13:04 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=03
30.08.19 08:13:04 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: The reference volume of sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit changed from mono: 17477 /  27% to mono: 13108 /  20%.
30.08.19 08:13:04 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> OK
30.08.19 08:13:04 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Storing volume/mute for device+port sink:bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit:headset-output.
30.08.19 08:13:05 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=02
30.08.19 08:13:05 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: The reference volume of sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit changed from mono: 13108 /  20% to mono: 8739 /  13%.
30.08.19 08:13:05 (+0200)  pulseaudio-server  D: [pulseaudio] backend-native.c: RFCOMM >> OK
30.08.19 08:13:05 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Storing volume/mute for device+port sink:bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit:headset-output.
30.08.19 08:13:12 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:13:12 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: RUNNING -> IDLE
30.08.19 08:13:12 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:13:12 (+0200)  pulseaudio-server  D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
30.08.19 08:13:12 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c: Freeing input 1 "LRMonoPhase4.wav"
30.08.19 08:13:12 (+0200)  pulseaudio-server  I: [pulseaudio] client.c: Freed 1 "paplay"
30.08.19 08:13:12 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Connection died.
30.08.19 08:13:12 (+0200)  pulseaudio-server  I: [pulseaudio] module-device-restore.c: Synced.
30.08.19 08:13:17 (+0200)  pulseaudio-server  I: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit idle for too long, suspending ...
30.08.19 08:13:17 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: suspend_cause: (none) -> IDLE
30.08.19 08:13:17 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: IDLE -> SUSPENDED
30.08.19 08:13:17 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: suspend_cause: (none) -> IDLE
30.08.19 08:13:17 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: state: IDLE -> SUSPENDED
30.08.19 08:13:17 (+0200)  pulseaudio-server  D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
janvda commented 5 years ago

The sampler settings of the run (see previous comment):

30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Resampler:
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   rate 48000 -> 8000 (method speex-float-1)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   format s16le -> s16le (intermediate float32le)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   channels 2 -> 1 (resampling 1)
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Channel matrix:
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:        I00   I01 
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:     +------------
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: O00 | 0.500 0.500
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] remap_neon.c: Using ARM NEON stereo to mono remapping
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] speex.c: Choosing speex quality setting 1.
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=2, prebuf=0, minreq=1 maxrewind=0
30.08.19 08:12:59 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=2, prebuf=0, minreq=2 maxrewind=0
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c: Created input 1 "LRMonoPhase4.wav" on bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit with sample spec s16le 2ch 48000Hz and channel map front-left,front-right
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     media.format = "WAV (Microsoft)"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.name = "paplay"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     media.name = "LRMonoPhase4.wav"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     native-protocol.version = "32"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.id = "543"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.user = "root"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.host = "ba7c427"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.binary = "pacat"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     window.x11.display = "192.168.1.5:0"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.machine_id = "9fade966265e32f64990ed195d67c02a"
30.08.19 08:12:59 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:paplay"
janvda commented 5 years ago

I just set resample-method = speex-float-3 (the default is speex-float-1) in daemon.conf but it didn't make an audible difference.

Maybe it is the resampling of 2 channels into 1 channel (Using ARM NEON stereo to mono remapping) that is causing the poor audio quality.

30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Resampler:
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   rate 48000 -> 8000 (method speex-float-3)
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   format s16le -> s16le (intermediate float32le)
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   channels 2 -> 1 (resampling 1)
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Channel matrix:
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:        I00   I01 
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:     +------------
30.08.19 08:45:40 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: O00 | 0.500 0.500
30.08.19 08:45:40 (+0200)  pulseaudio-server  I: [pulseaudio] remap_neon.c: Using ARM NEON stereo to mono remapping
30.08.19 08:45:40 (+0200)  pulseaudio-server  I: [pulseaudio] speex.c: Choosing speex quality setting 3.
janvda commented 5 years ago

One of the options would be

Following link might give some more ideas: https://wiki.archlinux.org/index.php/PulseAudio/Troubleshooting

janvda commented 5 years ago

Still got the problem with following mono recording http://www0.cs.ucl.ac.uk/teaching/GZ05/samples/lathe-adpcm.wav

30.08.19 18:09:06 (+0200)  pulseaudio-server  I: [pulseaudio] client.c: Created 4 "Native client (UNIX socket client)"
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Protocol version: remote 32, local 32
30.08.19 18:09:06 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Got credentials: uid=0 gid=0 success=1
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: SHM possible: yes
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Memfd possible: yes
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Negotiated SHM type: shared memfd
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] memblock.c: Using shared memfd memory pool with 1024 slots of size 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65496
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] srbchannel.c: SHM block is 65496 bytes, ringbuffer capacity is 2 * 32724 bytes
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Enabling srbchannel...
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for pacat
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Client enabled srbchannel.
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] module-intended-roles.c: Not setting device for stream lathe-adpcm.wav, because it lacks role.
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] sink-input.c: Negotiated format: pcm, format.sample_format = "\"uLaw\""  format.rate = "8000"  format.channels = "1"  format.channel_map = "\"mono\""
30.08.19 18:09:06 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c: Trying to change sample rate
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes busy, resuming.
30.08.19 18:09:06 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Acquiring transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16
30.08.19 18:09:06 (+0200)  pulseaudio-server  I: [bluetooth] backend-native.c: doing connect
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 acquired: fd 40
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 resuming
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [bluetooth] module-bluez5-device.c: Stream properly set up, we're ready to roll!
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: suspend_cause: IDLE -> (none)
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: SUSPENDED -> IDLE
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: suspend_cause: IDLE -> (none)
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] source.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit.monitor: state: SUSPENDED -> IDLE
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit becomes idle, timeout in 5 seconds.
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] resampler.c: Forcing resampler 'copy', because of fixed, identical sample rates.
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c: Resampler:
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   rate 8000 -> 8000 (method copy)
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   format uLaw -> s16le (intermediate s16le)
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] resampler.c:   channels 1 -> 1 (resampling 1)
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=2, prebuf=0, minreq=1 maxrewind=0
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=2, prebuf=0, minreq=2 maxrewind=0
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c: Created input 3 "lathe-adpcm.wav" on bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit with sample spec uLaw 1ch 8000Hz and channel map mono
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     media.format = "WAV (Microsoft)"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.name = "paplay"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     media.name = "lathe-adpcm.wav"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     native-protocol.version = "32"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.id = "320"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.user = "root"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.host = "ba7c427"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.binary = "pacat"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     window.x11.display = "192.168.1.5:0"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     application.process.machine_id = "9fade966265e32f64990ed195d67c02a"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:paplay"
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Requested tlength=2000.00 ms, minreq=20.00 ms
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Traditional mode enabled, modifying sink usec only for compat with minreq.
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] protocol-native.c: Requested latency=1960.00 ms, Received latency=28.00 ms
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=16000, base=1, prebuf=15841, minreq=160 maxrewind=0
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=16000, base=1, prebuf=15841, minreq=160 maxrewind=0
30.08.19 18:09:07 (+0200)  pulseaudio-server  I: [pulseaudio] protocol-native.c: Final latency 2028.00 ms = 1960.00 ms + 2*20.00 ms + 28.00 ms
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] sink.c: bluez_sink.A0_E9_DB_09_CF_FF.headset_head_unit: state: IDLE -> RUNNING
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_A0_E9_DB_09_CF_FF/fd16 state: idle -> playing
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] card.c: Setting card bluez_card.A0_E9_DB_09_CF_FF profile headset_head_unit to availability status yes
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-output to status yes
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] device-port.c: Setting port headset-input to status yes
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
30.08.19 18:09:07 (+0200)  pulseaudio-server  D: [pulseaudio] module-bluez5-device.c: Resuming source bluez_source.A0_E9_DB_09_CF_FF.headset_head_unit because its transport state changed to playing
janvda commented 5 years ago

Section HSP problem: the bluetooth sink and source are created, but no audio is being transmitted of the following link https://www.freedesktop.org/wiki/Software/PulseAudio/Documentation/User/Bluetooth/

reports the following:

Current Raspbian versions do this automatically: https://github.com/RPi-Distro/pi-bluetooth/commit/0dffacec9452b975ed7c17b530e4f230ea17b727

BCM2835 doesn't work properly even with the fixed routing. There's audio, but it's very bad.

So it is mentioning that audio is very bad.

janvda commented 5 years ago

another link: https://github.com/raspberrypi/linux/issues/2229 especially following comment : https://github.com/raspberrypi/linux/issues/2229#issuecomment-391397669

janvda commented 5 years ago

I have applied the change in previous comment (see https://github.com/janvda/balena-pulseaudio/commit/2868002bb4932063c36d72913f73d565a3eecd25 ) and this fixed the playback issue.

There is still some little humming - but the playback is much much better.