2014-07-23 12:37:54

by Brian J. Murrell

[permalink] [raw]
Subject: phone connects and then disconnects immediately

Hi,

I am using Bluez 5.18 on my Fedora 20 machine and trying to play music
from my Android (Nexus 4 with KK 4.4.4) phone to the F20 as a Bluetooth
sink.

I have successfully paired the phone and the F20 machine and the phone
sees it as advertising an Audio Sink but when I try to connect the phone
bluetoothctl shows the connect immediately followed by a disconnect:

[CHG] Device XX:XX:XX:XX:XX:XX Connected: yes
[CHG] Device XX:XX:XX:XX:XX:XX Connected: no

No messages in the syslog to indicate any problems.

Any ideas why the immediate disconection or next steps to debug?

Cheers,
b.


Attachments:
signature.asc (490.00 B)
This is a digitally signed message part

2014-07-24 11:05:39

by Brian J. Murrell

[permalink] [raw]
Subject: Re: phone connects and then disconnects immediately

On Thu, 2014-07-24 at 11:16 +0300, Johan Hedberg wrote:
> Hi Brian,

Hi Johan,

> To analyze the matter further we'd need to get bluetoothd debug logs
> (for which you need to pass -d to the daemon)

Did that. Not sure where those debug logs go on a Fedora 20 system
though.

> as well as HCI-level logs
> (e.g. using btmon) of this connection failure.

> HCI Event: Connect Request (0x04) plen 10 [hci0] 556.517273
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Class: 0x5a020c
Major class: Phone (cellular, cordless, payphone, modem)
Minor class: Smart phone
Networking (LAN, Ad hoc)
Capturing (Scanner, Microphone)
Object Transfer (v-Inbox, v-Folder)
Telephony (Cordless telephony, Modem, Headset)
Link type: ACL (0x01)
< HCI Command: Accept Connection Requ.. (0x01|0x0009) plen 7 [hci0] 556.517375
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Role: Master (0x00)
> HCI Event: Command Status (0x0f) plen 4 [hci0] 556.520255
Accept Connection Request (0x01|0x0009) ncmd 1
Status: Success (0x00)
> HCI Event: Role Change (0x12) plen 8 [hci0] 556.684269
Status: Success (0x00)
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Role: Master (0x00)
> HCI Event: Connect Complete (0x03) plen 11 [hci0] 556.832264
Status: Success (0x00)
Handle: 11
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Link type: ACL (0x01)
Encryption: Disabled (0x00)
< HCI Command: Read Remote Supported... (0x01|0x001b) plen 2 [hci0] 556.832500
Handle: 11
> HCI Event: Command Status (0x0f) plen 4 [hci0] 556.835253
Read Remote Supported Features (0x01|0x001b) ncmd 1
Status: Success (0x00)
> HCI Event: Read Remote Supported Features (0x0b) plen 11 [hci0] 556.836249
Status: Success (0x00)
Handle: 11
Features: 0xff 0xfe 0x8f 0xfe 0xd8 0x3f 0x5b 0x87
3 slot packets
5 slot packets
Encryption
Slot offset
Timing accuracy
Role switch
Hold mode
Sniff mode
Power control requests
Channel quality driven data rate (CQDDR)
SCO link
HV2 packets
HV3 packets
u-law log synchronous data
A-law log synchronous data
CVSD synchronous data
Paging parameter negotiation
Power control
Transparent synchronous data
Broadcast Encryption
Enhanced Data Rate ACL 2 Mbps mode
Enhanced Data Rate ACL 3 Mbps mode
Enhanced inquiry scan
Interlaced inquiry scan
Interlaced page scan
RSSI with inquiry results
Extended SCO link (EV3 packets)
AFH capable slave
AFH classification slave
LE Supported (Controller)
3-slot Enhanced Data Rate ACL packets
5-slot Enhanced Data Rate ACL packets
Sniff subrating
Pause encryption
AFH capable master
AFH classification master
Enhanced Data Rate eSCO 2 Mbps mode
Extended Inquiry Response
Simultaneous LE and BR/EDR (Controller)
Secure Simple Pairing
Encapsulated PDU
Non-flushable Packet Boundary Flag
Link Supervision Timeout Changed Event
Inquiry TX Power Level
Enhanced Power Control
Extended features
< HCI Command: Read Remote Extended F.. (0x01|0x001c) plen 3 [hci0] 556.836473
Handle: 11
Page: 1
> HCI Event: Command Status (0x0f) plen 4 [hci0] 556.839254
Read Remote Extended Features (0x01|0x001c) ncmd 1
Status: Success (0x00)
> HCI Event: Max Slots Change (0x1b) plen 3 [hci0] 556.859258
Handle: 11
Max slots: 5
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7 [hci0] 556.862250
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Page scan repetition mode: R1 (0x01)
> ACL Data RX: Handle 11 flags 0x02 dlen 10 [hci0] 556.907263
L2CAP: Information Request (0x0a) ident 2 len 2
Type: Extended features supported (0x0002)
< ACL Data TX: Handle 11 flags 0x00 dlen 16 [hci0] 556.907343
L2CAP: Information Response (0x0b) ident 2 len 8
Type: Extended features supported (0x0002)
Result: Success (0x0000)
Features: 0x000002b8
Enhanced Retransmission Mode
Streaming Mode
FCS Option
Fixed Channels
Unicast Connectionless Data Reception
> HCI Event: Read Remote Extended Features (0x23) plen 13 [hci0] 556.913287
Status: Success (0x00)
Handle: 11
Page: 1/2
Features: 0x03 0x00 0x00 0x00 0x00 0x00 0x00 0x00
Secure Simple Pairing (Host Support)
LE Supported (Host)
> ACL Data RX: Handle 11 flags 0x02 dlen 10 [hci0] 556.913303
L2CAP: Information Request (0x0a) ident 3 len 2
Type: Fixed channels supported (0x0003)
< HCI Command: Remote Name Request (0x01|0x0019) plen 10 [hci0] 556.913381
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Page scan repetition mode: R2 (0x02)
Page scan mode: Mandatory (0x00)
Clock offset: 0x0000
< ACL Data TX: Handle 11 flags 0x00 dlen 20 [hci0] 556.913399
L2CAP: Information Response (0x0b) ident 3 len 12
Type: Fixed channels supported (0x0003)
Result: Success (0x0000)
Channels: 0x0000000000000006
L2CAP Signaling (BR/EDR)
Connectionless reception
> HCI Event: Command Status (0x0f) plen 4 [hci0] 556.916243
Remote Name Request (0x01|0x0019) ncmd 1
Status: Success (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 556.918245
Num handles: 1
Handle: 11
Count: 2
> ACL Data RX: Handle 11 flags 0x02 dlen 12 [hci0] 556.918264
L2CAP: Connection Request (0x02) ident 4 len 4
PSM: 1 (0x0001)
Source CID: 67
< ACL Data TX: Handle 11 flags 0x00 dlen 16 [hci0] 556.918383
L2CAP: Connection Response (0x03) ident 4 len 8
Destination CID: 64
Source CID: 67
Result: Connection pending (0x0001)
Status: No further information available (0x0000)
< ACL Data TX: Handle 11 flags 0x00 dlen 10 [hci0] 556.918410
L2CAP: Information Request (0x0a) ident 1 len 2
Type: Extended features supported (0x0002)
@ Device Connected: XX:XX:XX:XX:XX:XX (0) flags 0x0000
04 0d 0c 02 5a ....Z
> ACL Data RX: Handle 11 flags 0x02 dlen 16 [hci0] 556.925247
L2CAP: Information Response (0x0b) ident 1 len 8
Type: Extended features supported (0x0002)
Result: Success (0x0000)
Features: 0x000000b8
Enhanced Retransmission Mode
Streaming Mode
FCS Option
Fixed Channels
< ACL Data TX: Handle 11 flags 0x00 dlen 10 [hci0] 556.925323
L2CAP: Information Request (0x0a) ident 2 len 2
Type: Fixed channels supported (0x0003)
> HCI Event: Remote Name Req Complete (0x07) plen 255 [hci0] 556.937296
Status: Success (0x00)
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Name: Brian's phone
> HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 556.938252
Num handles: 1
Handle: 11
Count: 2
> ACL Data RX: Handle 11 flags 0x02 dlen 20 [hci0] 556.978252
L2CAP: Information Response (0x0b) ident 2 len 12
Type: Fixed channels supported (0x0003)
Result: Success (0x0000)
Channels: 0x0000000000000052
L2CAP Signaling (BR/EDR)
Attribute Protocol
Security Manager
< ACL Data TX: Handle 11 flags 0x00 dlen 16 [hci0] 556.978338
L2CAP: Connection Response (0x03) ident 4 len 8
Destination CID: 64
Source CID: 67
Result: Connection successful (0x0000)
Status: No further information available (0x0000)
< ACL Data TX: Handle 11 flags 0x00 dlen 23 [hci0] 556.978367
L2CAP: Configure Request (0x04) ident 3 len 15
Destination CID: 67
Flags: 0x0000
Option: Retransmission and Flow Control (0x04)
Mode: Basic (0x00)
TX window size: 0
Max transmit: 0
Retransmission timeout: 0
Monitor timeout: 0
Maximum PDU size: 0
> HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 556.982245
Num handles: 1
Handle: 11
Count: 2
> ACL Data RX: Handle 11 flags 0x02 dlen 16 [hci0] 556.982266
L2CAP: Configure Request (0x04) ident 5 len 8
Destination CID: 64
Flags: 0x0000
Option: Maximum Transmission Unit (0x01)
MTU: 256
< ACL Data TX: Handle 11 flags 0x00 dlen 18 [hci0] 556.982334
L2CAP: Configure Response (0x05) ident 5 len 10
Source CID: 67
Flags: 0x0000
Result: Success (0x0000)
Option: Maximum Transmission Unit (0x01)
MTU: 256
> ACL Data RX: Handle 11 flags 0x02 dlen 14 [hci0] 556.983252
L2CAP: Configure Response (0x05) ident 3 len 6
Source CID: 64
Flags: 0x0000
Result: Success (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 556.987254
Num handles: 1
Handle: 11
Count: 2
> ACL Data RX: Handle 11 flags 0x02 dlen 28 [hci0] 556.987269
Channel: 64 len 24 [PSM 17 mode 0] {chan 0}
06 00 00 00 13 35 03 19 11 0b 00 f0 35 09 09 00 .....5......5...
01 09 00 04 09 00 09 00 ........
< ACL Data TX: Handle 11 flags 0x00 dlen 14 [hci0] 556.987795
Channel: 67 len 10 [PSM 1 mode 0] {chan 2}
SDP: Service Search Attribute Response (0x07) tid 0 len 5
Attribute bytes: 2
Continuation state: 0
> ACL Data RX: Handle 11 flags 0x02 dlen 12 [hci0] 556.992262
L2CAP: Disconnection Request (0x06) ident 6 len 4
Destination CID: 64
Source CID: 67
< ACL Data TX: Handle 11 flags 0x00 dlen 12 [hci0] 556.992361
L2CAP: Disconnection Response (0x07) ident 6 len 4
Destination CID: 64
Source CID: 67
> HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 556.997246
Num handles: 1
Handle: 11
Count: 2
> HCI Event: Link Key Request (0x17) plen 6 [hci0] 557.120266
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 [hci0] 557.120346
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
Link key: 577a9d0df3707630fa0b08fcfd0b37f9
> HCI Event: Command Complete (0x0e) plen 10 [hci0] 557.205250
Link Key Request Reply (0x01|0x000b) ncmd 1
Status: Success (0x00)
Address: XX:XX:XX:XX:XX:XX (LG Electronics)
> ACL Data RX: Handle 11 flags 0x02 dlen 12 [hci0] 557.273255
L2CAP: Connection Request (0x02) ident 7 len 4
PSM: 25 (0x0019)
Source CID: 75
< ACL Data TX: Handle 11 flags 0x00 dlen 16 [hci0] 557.273330
L2CAP: Connection Response (0x03) ident 7 len 8
Destination CID: 0
Source CID: 75
Result: Connection refused - PSM not supported (0x0002)
Status: No further information available (0x0000)
> HCI Event: Encryption Change (0x08) plen 4 [hci0] 557.275239
Status: Success (0x00)
Handle: 11
Encryption: Enabled with E0 (0x01)
> HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 557.432260
Num handles: 1
Handle: 11
Count: 1
< HCI Command: Disconnect (0x01|0x0006) plen 3 [hci0] 560.994017
Handle: 11
Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4 [hci0] 560.996192
Disconnect (0x01|0x0006) ncmd 1
Status: Invalid HCI Command Parameters (0x12)
> HCI Event: Disconnect Complete (0x05) plen 4 [hci0] 561.145201
Status: Success (0x00)
Handle: 11
Reason: Remote User Terminated Connection (0x13)
@ Device Disconnected: XX:XX:XX:XX:XX:XX (0) reason 3

Cheers,
b.


Attachments:
signature.asc (490.00 B)
This is a digitally signed message part

2014-07-24 08:16:59

by Johan Hedberg

[permalink] [raw]
Subject: Re: phone connects and then disconnects immediately

Hi Brian,

On Wed, Jul 23, 2014, Brian J. Murrell wrote:
> I am using Bluez 5.18 on my Fedora 20 machine and trying to play music
> from my Android (Nexus 4 with KK 4.4.4) phone to the F20 as a Bluetooth
> sink.
>
> I have successfully paired the phone and the F20 machine and the phone
> sees it as advertising an Audio Sink but when I try to connect the phone
> bluetoothctl shows the connect immediately followed by a disconnect:
>
> [CHG] Device XX:XX:XX:XX:XX:XX Connected: yes
> [CHG] Device XX:XX:XX:XX:XX:XX Connected: no
>
> No messages in the syslog to indicate any problems.
>
> Any ideas why the immediate disconection or next steps to debug?

To analyze the matter further we'd need to get bluetoothd debug logs
(for which you need to pass -d to the daemon) as well as HCI-level logs
(e.g. using btmon) of this connection failure.

Johan