Hello Luiz, On Thu, Jun 21, 2018 at 3:27 AM, Luiz Augusto von Dentz <luiz.dentz@xxxxxxxxx> wrote: > >> Im trying to reproduce this with sony sbh50 but apparently it doesn't >> have the same problem as it worked just fine, one thing I notice >> though is that HFP does not connect: >> >> https://gist.github.com/Vudentz/6f385ededcb00d1d0f4403f06923fd1a >> >> As you can see locally we only support HSP which means there is no >> match for MFP, but perhaps you are running with oFono? Anyway I should >> have an mw600 somewhere but that is quite old already, but you >> mentioned it did not work with MDR-XB950N1 which is quite new model? Sorry, I forgot to mention: I was not running oFono, so only PulseAudio's HSP implementation was registered with bluetoothd. I personally have only been able to reproduce this problem on the Sony MW-600, from the headsets I have access to. Our QA team at Endless have seen similar symptoms on the Sony MDR-XB950N1, AMP Pulse BXH-300, Intopic HM-BT001, and The Coopidea CP-TW-01. I have not able to confirm 100% whether that is the exact same problem on all of them, as I'm focusing on the MW-600 which is the one I have access to. >> Anyway if you can gather some logs of bluetoothd that would be useful >> to identify where is the problem. > I've actually was not able to reproduce the exact same symptoms yesterday: instead of the headset disconnecting A2DP and the card being destroyed, the OFF profile ended up being selected. The transport for HSP got available first, the card was created 3s afterwards (due to WAIT_FOR_PROFILES_TIMEOUT_USEC being reached), but a2dp actually got connected about 50s afterwards. Then after looking into it for a while I realized a few extra things that I had not noticed befofe. PulseAudio logs for this case can be seen right bellow, and for the "disconnecting case" afterwards. I can still collect bluetoothd logs if needed. Notice that the "module-card-restore.c: Restoring profile X for card Y" message is wrong, as this is from PulseAudio 11 plus some backported patches, but it does not contain "card-restore: log the correct profile name". I marked it on the logs bellow for attention. 1. OFF CASE - org.bluez.Profile1.NewConnection() is called on PulseAudio's HSPAGProfile object path: Jun 20 17:09:11 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_58_17_0C_EA_02_89 Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] backend-native.c: dbus: path=/Profile/HSPAGProfile, interface=org.bluez.Profile1, member=NewConnection Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] backend-native.c: dbus: NewConnection path=/org/bluez/hci0/dev_58_17_0C_EA_02_89, fd=23, profile headset_head_unit Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] backend-native.c: doing listen Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: disconnected -> idle Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 available for profile headset_head_unit Jun 20 17:09:12 endless pulseaudio[899]: [pulseaudio] backend-native.c: RFCOMM << AT+CLIP=1 - WAIT_FOR_PROFILES_TIMEOUT_USEC expires: Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Timeout expired, and device /org/bluez/hci0/dev_58_17_0C_EA_02_89 still has disconnected profiles: a2dp_sink Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module-bluez5-discover.c: Loading module-bluez5-device path=/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=0 Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module-card-restore.c: Restoring port latency offsets for card bluez_card.58_17_0C_EA_02_89. ** wrong message here --> Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module-card-restore.c: Restoring profile 'headset_head_unit' for card bluez_card.58_17_0C_EA_02_89. Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] card.c: Created 1 "bluez_card.58_17_0C_EA_02_89" ** and the following message indicates module-card-restore was trying to restore a2dp_sink instead Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module-bluez5-device.c: Profile a2dp_sink has no transport Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] card.c: Changed profile of card 1 "bluez_card.58_17_0C_EA_02_89" to off Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 20 17:09:15 endless pulseaudio[899]: [pulseaudio] module.c: Loaded "module-bluez5-device" (index: #25; argument: "path=/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=0"). - Now the card remains created and idle for a while, since its profile has been set to OFF, except for some boring RFCOMM chat. Jun 20 17:09:22 endless pulseaudio[899]: [pulseaudio] backend-native.c: RFCOMM << AT+CSCS="UTF-8" Jun 20 17:09:32 endless pulseaudio[899]: [pulseaudio] backend-native.c: RFCOMM << AT*SEAM="MW600",13 Jun 20 17:09:42 endless pulseaudio[899]: [pulseaudio] backend-native.c: RFCOMM << AT+CLAN? Jun 20 17:09:52 endless pulseaudio[899]: [pulseaudio] backend-native.c: RFCOMM << AT+COLP=1 Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] backend-native.c: RFCOMM << AT+CCLK? - Exact 50s after the NewConnection() call there is a org.bluez.MediaTransport1.SetConfiguration() call on PulseAudio's A2DPSource object path: Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Introspectable found, skipping Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.MediaTransport1 found, skippingJun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Properties found, skipping Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=SetConfiguration Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: disconnected -> idle Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] card.c: Setting card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability status unknown Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 available for profile a2dp_sink Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Properties changed in transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: idle -> playing Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] card.c: Setting card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability status yes Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] device-port.c: Setting port headset-output to status yes Jun 20 17:10:02 endless pulseaudio[899]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Properties changed in transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd0 state: playing -> idle Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] card.c: Setting card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability status unknown Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] device-port.c: Setting port headset-output to status unknown Jun 20 17:10:08 endless pulseaudio[899]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. 2. DISCONNECTING CASE (here I had WAIT_FOR_PROFILES_TIMEOUT_USEC=60s, so it does not expire): - org.bluez.Profile1.NewConnection() is called on PulseAudio's HSPAGProfile object path: Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_58_17_0C_EA_02_89 Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: dbus: path=/Profile/HSPAGProfile, interface=org.bluez.Profile1, member=NewConnection Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: dbus: NewConnection path=/org/bluez/hci0/dev_58_17_0C_EA_02_89, fd=23, profile headset_head_unit Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: doing listen Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: disconnected -> idle Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 available for profile headset_head_unit Jun 13 15:22:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT+CLIP=1 Jun 13 15:22:20 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT+CSCS="UTF-8" Jun 13 15:22:30 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT*SEAM="MW600",13 Jun 13 15:22:40 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT+CLAN? Jun 13 15:22:50 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT+COLP=1 Jun 13 15:23:00 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT+CCLK? - Exact 51s after the NewConnection() call there is a org.bluez.MediaTransport1.SetConfiguration() call on PulseAudio's A2DPSource object path: Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=SetConfiguration Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 state: disconnected -> idle Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-bluez5-discover.c: Loading module-bluez5-device path=/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=0 Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-card-restore.c: Restoring port latency offsets for card bluez_card.58_17_0C_EA_02_89. ** wrong message, it is restoring headset_head_unit --> Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-card-restore.c: Restoring profile 'a2dp_sink' for card bluez_card.58_17_0C_EA_02_89. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Created 2 "bluez_card.58_17_0C_EA_02_89" - SCO is established Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-bluez5-device.c: Acquiring transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] backend-native.c: doing connect Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-bluez5-device.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 acquired: fd 13 Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: idle -> playing Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Setting card bluez_card.58_17_0C_EA_02_89 profile headset_head_unit to availability status yes Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] device-port.c: Setting port headset-output to status yes Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] device-port.c: Setting port headset-input to status yes Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: Created sink 2 "bluez_sink.58_17_0C_EA_02_89.headset_head_unit" with sample spec s16le 1ch 8000Hz and channel map mono Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: bluetooth.protocol = "headset_head_unit" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.intended_roles = "phone" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.description = "MW600" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.string = "58:17:0C:EA:02:89" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.api = "bluez" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.class = "sound" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.bus = "bluetooth" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.form_factor = "headset" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: bluez.path = "/org/bluez/hci0/dev_58_17_0C_EA_02_89" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: bluez.class = "0x240404" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: bluez.alias = "MW600" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] sink.c: device.icon_name = "audio-headset-bluetooth" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: Created source 3 "bluez_sink.58_17_0C_EA_02_89.headset_head_unit.monitor" with sample spec s16le 1ch 8000Hz and channel map mono Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.description = "Monitor of MW600" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.class = "monitor" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.string = "58:17:0C:EA:02:89" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.api = "bluez" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.bus = "bluetooth" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.form_factor = "headset" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluez.path = "/org/bluez/hci0/dev_58_17_0C_EA_02_89" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluez.class = "0x240404" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluez.alias = "MW600" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.icon_name = "audio-headset-bluetooth" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.intended_roles = "phone" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: Created source 4 "bluez_source.58_17_0C_EA_02_89.headset_head_unit" with sample spec s16le 1ch 8000Hz and channel map mono Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluetooth.protocol = "headset_head_unit" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.intended_roles = "phone" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.description = "MW600" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.string = "58:17:0C:EA:02:89" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.api = "bluez" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.class = "sound" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.bus = "bluetooth" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.form_factor = "headset" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluez.path = "/org/bluez/hci0/dev_58_17_0C_EA_02_89" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluez.class = "0x240404" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: bluez.alias = "MW600" Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] source.c: device.icon_name = "audio-headset-bluetooth" Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] module-bluez5-device.c: IO Thread starting up Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] core-util.c: RealtimeKit worked. Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5. Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 resuming Jun 13 15:23:01 endless pulseaudio[809]: [bluetooth] module-bluez5-device.c: Stream properly set up, we're ready to roll! Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-device-restore.c: Could not set format on sink bluez_sink.58_17_0C_EA_02_89.headset_head_unit Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-bluetooth-policy.c: Profile headset_head_unit cannot be selected for loopback Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.58_17_0C_EA_02_89.headset_head_unit becomes idle, timeout in 5 seconds. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core.c: default_sink: alsa_output.pci-0000_00_1f.3.analog-stereo -> bluez_sink.58_17_0C_EA_02_89.headset_head_unit Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM >> +VGS=15 Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-bluetooth-policy.c: Profile headset_head_unit cannot be selected for loopback Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module-suspend-on-idle.c: Source bluez_source.58_17_0C_EA_02_89.headset_head_unit becomes idle, timeout in 5 seconds. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core.c: default_source: alsa_input.pci-0000_00_1f.3.analog-stereo -> bluez_source.58_17_0C_EA_02_89.headset_head_unit Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM >> +VGM=15 Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] module.c: Loaded "module-bluez5-device" (index: #27; argument: "path=/org/bluez/hci0/dev_58_17_0C_EA_02_89 autodetect_mtu=0"). - org.bluez.MediaTransport1.ClearConfiguration() call on PulseAudio's A2DPSource object path, makes a2dp_sink unavailable: Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 available for profile a2dp_sink Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=ClearConfiguration Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Clearing transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 profile a2dp_sink Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd1 state: idle -> disconnected Jun 13 15:23:01 endless pulseaudio[809]: [pulseaudio] card.c: Setting card bluez_card.58_17_0C_EA_02_89 profile a2dp_sink to availability status no Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] module-suspend-on-idle.c: Source bluez_source.58_17_0C_EA_02_89.headset_head_unit idle for too long, suspending ... Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] source.c: Suspend cause of source bluez_source.58_17_0C_EA_02_89.headset_head_unit is 0x0004, suspending Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum. Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.58_17_0C_EA_02_89.headset_head_unit idle for too long, suspending ... Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] sink.c: Suspend cause of sink bluez_sink.58_17_0C_EA_02_89.headset_head_unit is 0x0004, suspending Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth] module-bluez5-device.c: Releasing transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth] backend-native.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 released Jun 13 15:23:06 endless pulseaudio[809]: [bluetooth] module-bluez5-device.c: Audio stream torn down Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum. Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_58_17_0C_EA_02_89/fd23 state: playing -> idle Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] card.c: Setting card bluez_card.58_17_0C_EA_02_89 profile headset_head_unit to availability status unknown Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] device-port.c: Setting port headset-output to status unknown Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] device-port.c: Setting port headset-input to status unknown Jun 13 15:23:06 endless pulseaudio[809]: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. Jun 13 15:23:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM << AT+VGS=15 Jun 13 15:23:10 endless pulseaudio[809]: [pulseaudio] backend-native.c: RFCOMM >> OK There was still another situation I've seen, which is the RFCOMM getting disconnected at this point with WAIT_FOR_PROFILES_TIMEOUT_USEC=3s (which makes we create the card without all profiles connected), but I don't have logs for it atm. > Managed to reproduce the issue, if I recall correctly MW600 don't like > that SCO is open before A2DP is configured which is caused by: > That is aligned with my observations when debugging this over the past few days, and with I've seen on the logs above. > > /* Ignore card if has already set other initial profile than a2dp */ > if (card->active_profile && > !pa_streq(card->active_profile->name, "a2dp") && > !pa_streq(card->active_profile->name, "a2dp_sink")) > return PA_HOOK_OK; > > /* Set initial profile to hsp */ > card_set_profile(u, card, false); > > If I get it correctly the first if statement will not return in case > of A2DP, which basically negates restored profile?, and then it sets > HSP which I find to be the opposite of what we should be doing except > if there already an stream tagged with voice otherwise we shall really > prefer A2DP. > I'm reading this correctly, this code path is reached only when there is a source-output which is tagged with media.role=phone (unless some extra heuristic is enabled by passing "auto_switch=2" to module-bluetooth-policy, which is not the case here), which is controlled by the "if (source_output_count(c, userdata) == 0)" branch about 8 lines above the ones you pasted. I'm adding some extra debug around the initial profile selection to have a clear picture of what is going on there and will keep analyzing this further. I'll get back when I have something, now that I have a better idea of what to look for, but any insights are welcome in the meantime. Thanks for the help! -- João Paulo Rechi Vita http://about.me/jprvita -- To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
