search

google / bumble

Apache License 2.0
246 stars 70 forks source link

CONNECTION_REFUSED_PSM_NOT_SUPPORTED #428

Open veaceslavgspot opened 7 months ago

veaceslavgspot commented 7 months ago

I am trying to run the speaker example and connect to it from an emulator: python3 run_classic_discoverable.py speaker.json android-netsim.

The speaker appears in NetSim GUI and also it's discoverable in the emulator, but when attempting to pair with it connection seems to fail with CONNECTION_REFUSED_PSM_NOT_SUPPORTED. Any thoughts?

Emulators: Pixel 7 API 34 and Pixel 8 API 34.

Here the full log:

  bd_addr:         DA:4C:10:DE:17:00/P
  class_of_device: 5898764
  link_type:       ACL
DEBUG:bumble.device:*** Connection request: DA:4C:10:DE:17:00/P
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_ACCEPT_CONNECTION_REQUEST_COMMAND:
  bd_addr: DA:4C:10:DE:17:00/P
  role:    1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_STATUS_EVENT:
  status:                  PENDING
  num_hci_command_packets: 1
  command_opcode:          HCI_ACCEPT_CONNECTION_REQUEST_COMMAND
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_CONNECTION_COMPLETE_EVENT:
  status:             HCI_SUCCESS
  connection_handle:  3838
  bd_addr:            DA:4C:10:DE:17:00/P
  link_type:          ACL
  encryption_enabled: 0
DEBUG:bumble.host:### BR/EDR CONNECTION: [0x0EFE] DA:4C:10:DE:17:00/P
DEBUG:bumble.device:*** Connection: [0x0EFE] DA:4C:10:DE:17:00/P
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=10, data=060001000a0202000200
DEBUG:bumble.hci:<<< ACL PDU: 060001000a0202000200
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_INFORMATION_REQUEST [ID=2]:
  info_type: EXTENDED_FEATURES_SUPPORTED
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_INFORMATION_RESPONSE [ID=2]:
  info_type: EXTENDED_FEATURES_SUPPORTED
  result:    SUCCESS
  data:      80000000
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c0001000b0208000200000080000000
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c0001000b0208000200000080000000
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=10, data=060001000a0302000300
DEBUG:bumble.hci:<<< ACL PDU: 060001000a0302000300
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_INFORMATION_REQUEST [ID=3]:
  info_type: FIXED_CHANNELS_SUPPORTED
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_INFORMATION_RESPONSE [ID=3]:
  info_type: FIXED_CHANNELS_SUPPORTED
  result:    SUCCESS
  data:      f200000000000000
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=20, data=100001000b030c0003000000f200000000000000
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=20, data=100001000b030c0003000000f200000000000000
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=12, data=080001000204040001004f00
DEBUG:bumble.hci:<<< ACL PDU: 080001000204040001004f00
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONNECTION_REQUEST [ID=4]:
  psm:        1
  source_cid: 79
DEBUG:bumble.l2cap:creating server channel with cid=64 for psm 1
DEBUG:bumble.l2cap:Channel(64->79, PSM=1, MTU=2048/48, state=CLOSED) state change -> WAIT_CONNECT
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONNECTION_RESPONSE [ID=4]:
  destination_cid: 64
  source_cid:      79
  result:          CONNECTION_SUCCESSFUL
  status:          0
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c0001000304080040004f0000000000
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c0001000304080040004f0000000000
DEBUG:bumble.l2cap:Channel(64->79, PSM=1, MTU=2048/48, state=WAIT_CONNECT) state change -> WAIT_CONFIG
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONFIGURE_REQUEST [ID=1]:
  destination_cid: 79
  flags:           0
  options:         01020008
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c000100040108004f00000001020008
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c000100040108004f00000001020008
DEBUG:bumble.l2cap:Channel(64->79, PSM=1, MTU=2048/48, state=WAIT_CONFIG) state change -> WAIT_CONFIG_REQ_RSP
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=16, data=0c000100040508004000000001020004
DEBUG:bumble.hci:<<< ACL PDU: 0c000100040508004000000001020004
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONFIGURE_REQUEST [ID=5]:
  destination_cid: 64
  flags:           0
  options:         01020004
DEBUG:bumble.l2cap:peer MTU = 1024
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONFIGURE_RESPONSE [ID=5]:
  source_cid: 79
  flags:      0
  result:     SUCCESS
  options:    01020004
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=18, data=0e00010005050a004f000000000001020004
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=18, data=0e00010005050a004f000000000001020004
DEBUG:bumble.l2cap:Channel(64->79, PSM=1, MTU=2048/1024, state=WAIT_CONFIG_REQ_RSP) state change -> WAIT_CONFIG_RSP
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=14, data=0a00010005010600400000000000
DEBUG:bumble.hci:<<< ACL PDU: 0a00010005010600400000000000
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONFIGURE_RESPONSE [ID=1]:
  source_cid: 64
  flags:      0
  result:     SUCCESS
  options:
DEBUG:bumble.l2cap:Channel(64->79, PSM=1, MTU=2048/1024, state=WAIT_CONFIG_RSP) state change -> OPEN
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=28, data=180040000600000013350319110b03f0350909000109000409000900
DEBUG:bumble.hci:<<< ACL PDU: 180040000600000013350319110b03f0350909000109000409000900
DEBUG:bumble.sdp:<<< Received SDP Request: SDP_SERVICE_SEARCH_ATTRIBUTE_REQUEST [TID=0]:
  service_search_pattern:       SEQUENCE([UUID(UUID-16:110B (AudioSink))])
  maximum_attribute_byte_count: 1008
  attribute_id_list:            SEQUENCE([UNSIGNED_INTEGER(1#2),UNSIGNED_INTEGER(4#2),UNSIGNED_INTEGER(9#2)])
  continuation_state:           00
DEBUG:bumble.sdp:Search response: SEQUENCE([SEQUENCE([UNSIGNED_INTEGER(1#2),SEQUENCE([UUID(UUID-16:110B (AudioSink))]),UNSIGNED_INTEGER(4#2),SEQUENCE([SEQUENCE([UUID(UUID-16:0100 (L2CAP)),UNSIGNED_INTEGER(25#2)]),SEQUENCE([UUID(UUID-16:0019 (AVDTP)),UNSIGNED_INTEGER(256#2)])]),UNSIGNED_INTEGER(9#2),SEQUENCE([SEQUENCE([UUID(UUID-16:110D (AdvancedAudioDistribution)),UNSIGNED_INTEGER(256#2)])])])])
DEBUG:bumble.sdp:>>> Sending SDP Response: SDP_SERVICE_SEARCH_ATTRIBUTE_RESPONSE [TID=0]:
  attribute_lists_byte_count: 46
  attribute_lists:            SEQUENCE([SEQUENCE([UNSIGNED_INTEGER(1#2),SEQUENCE([UUID(UUID-16:110B (AudioSink))]),UNSIGNED_INTEGER(4#2),SEQUENCE([SEQUENCE([UUID(UUID-16:0100 (L2CAP)),UNSIGNED_INTEGER(25#2)]),SEQUENCE([UUID(UUID-16:0019 (AVDTP)),UNSIGNED_INTEGER(256#2)])]),UNSIGNED_INTEGER(9#2),SEQUENCE([SEQUENCE([UUID(UUID-16:110D (AdvancedAudioDistribution)),UNSIGNED_INTEGER(256#2)])])])])
  continuation_state:         00
DEBUG:bumble.l2cap:>>> Sending L2CAP PDU on connection [0x0EFE] (CID=79) DA:4C:10:DE:17:00/P: 54 bytes, SDP_SERVICE_SEARCH_ATTRIBUTE_RESPONSE [TID=0]:
  attribute_lists_byte_count: 46
  attribute_lists:            SEQUENCE([SEQUENCE([UNSIGNED_INTEGER(1#2),SEQUENCE([UUID(UUID-16:110B (AudioSink))]),UNSIGNED_INTEGER(4#2),SEQUENCE([SEQUENCE([UUID(UUID-16:0100 (L2CAP)),UNSIGNED_INTEGER(25#2)]),SEQUENCE([UUID(UUID-16:0019 (AVDTP)),UNSIGNED_INTEGER(256#2)])]),UNSIGNED_INTEGER(9#2),SEQUENCE([SEQUENCE([UUID(UUID-16:110D (AdvancedAudioDistribution)),UNSIGNED_INTEGER(256#2)])])])])
  continuation_state:         00
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=79) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=58, data=36004f000700000031002e352c352a090001350319110b0900043510350619010009001935061900190901000900093508350619110d09010000
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=58, data=36004f000700000031002e352c352a090001350319110b0900043510350619010009001935061900190901000900093508350619110d09010000
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=12, data=080001000606040040004f00
DEBUG:bumble.hci:<<< ACL PDU: 080001000606040040004f00
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_DISCONNECTION_REQUEST [ID=6]:
  destination_cid: 64
  source_cid:      79
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_DISCONNECTION_RESPONSE [ID=6]:
  destination_cid: 64
  source_cid:      79
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=12, data=080001000706040040004f00
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=12, data=080001000706040040004f00
DEBUG:bumble.l2cap:Channel(64->79, PSM=1, MTU=2048/1024, state=OPEN) state change -> CLOSED
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_ENCRYPTION_CHANGE_EVENT:
  status:             HCI_SUCCESS
  connection_handle:  3838
  encryption_enabled: AES_CCM
DEBUG:bumble.device:*** Connection Encryption Change: [0x0EFE] DA:4C:10:DE:17:00/P as PERIPHERAL, encryption=2
DEBUG:bumble.host:### CONTROLLER -> HOST: ACL: handle=0x0efe, pb=2, bc=0, data_total_length=12, data=080001000207040019005000
DEBUG:bumble.hci:<<< ACL PDU: 080001000207040019005000
DEBUG:bumble.l2cap:<<< Received L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONNECTION_REQUEST [ID=7]:
  psm:        25
  source_cid: 80
WARNING:bumble.l2cap:No server for connection 0x0EFE on PSM 25
DEBUG:bumble.l2cap:>>> Sending L2CAP Signaling Control Frame on connection [0x0EFE] (CID=1) DA:4C:10:DE:17:00/P:
L2CAP_CONNECTION_RESPONSE [ID=7]:
  destination_cid: 80
  source_cid:      0
  result:          CONNECTION_REFUSED_PSM_NOT_SUPPORTED
  status:          0
DEBUG:bumble.host:>>> ACL packet enqueue: (CID=1) ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c000100030708005000000002000000
DEBUG:bumble.host:### HOST -> CONTROLLER: ACL: handle=0x0efe, pb=0, bc=0, data_total_length=16, data=0c000100030708005000000002000000
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT:
  number_of_handles:        1
  connection_handle[0]:     3838
  num_completed_packets[0]: 1
zxzxwu commented 7 months ago

run_classic_discoverable.py only provides a fake SDP record, and there is no corresponding profile for it. To run speaker example, I suggest you to use apps/speaker.

https://github.com/google/bumble/blob/main/apps/speaker/speaker.py

barbibulle commented 6 months ago

NOTE: you will also see CONNECTION_REFUSED_PSM_NOT_SUPPORTED when running the speaker app with Android as the client. This is perfectly normal: the speaker app doesn't (yet) implement AVRCP (remote control), which is a service on PSM 23. Somehow Android insists on connecting to AVRCP even though it's not advertised in the SDP. But that should not block anything else.