2014-10-14 00:09:41

by John Tobias

[permalink] [raw]
Subject: Not getting an AVDTP: incoming connect

Hi Marcell / Bluez Team:

I was running the PTS 5.2 and there were an occurrences that the bluez
did not show a similar message below:

[agent] Authorize service 0000110d-0000-1000-8000-00805f9b34fb (yes/no):


1. I logs below are the traces of the bluetoothd not prompting the
Authorize service message:

t 13 23:27:22 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/adapter.c:connected_callback() hci0 device 00:1B:DC:07:32:D3
connected eir_len 31
Oct 13 23:27:22 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_connected
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/adapter.c:dev_disconnected() Device 00:1B:DC:07:32:D3
disconnected, reason 2
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/adapter.c:adapter_remove_connection()
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
plugins/policy.c:disconnect_cb() reason 2
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:1B:DC:07:32:D3
type 0 status 0xe
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/device.c:device_bonding_failed() status 14
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/adapter.c:resume_discovery()
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_disconnected
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: setting adv
params failed: Operation not permitted
Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: failed to enable
advertising


2. These messages are the traces of the bluetoothd showing the
Authorize service message:

Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/adapter.c:connected_callback() hci0 device 00:1B:DC:07:32:D3
connected eir_len 31
Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_connected
Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from
00:1B:DC:07:32:D3
Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/source.c:source_set_state() State changed
/org/bluez/hci0/dev_00_1B_DC_07_32_D3: SOURCE_STATE_DISCONNECTED ->
SOURCE_STATE_CONNECTING
Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/agent.c:agent_ref() 0x77a601d0: ref=2
Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/agent.c:agent_authorize_service() authorize service request was
sent for /org/bluez/hci0/dev_00_1B_DC_07_32_D3
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/agent.c:agent_ref() 0x77a601d0: ref=3
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/agent.c:agent_unref() 0x77a601d0: ref=2
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/agent.c:agent_unref() 0x77a601d0: ref=1
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling
channel to 00:1B:DC:07:32:D3
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=672
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:session_cb()
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_parse_cmd() Received DISCOVER_CMD
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:session_cb()
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_parse_cmd() Received
GET_CAPABILITIES_CMD
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/a2dp.c:endpoint_getcap_ind() Sink 0x77a69bd8:
Get_Capability_Ind
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:session_cb()
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_parse_cmd() Received
SET_CONFIGURATION_CMD
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/a2dp.c:endpoint_setconf_ind() Sink 0x77a69bd8:
Set_Configuration_Ind
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_ref() 0x77a6afa8: ref=1
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/a2dp.c:setup_ref() 0x77a5d040: ref=1
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/media.c:media_endpoint_async_call() Calling
SetConfiguration: name = :1.6 path = /MediaEndpoint/A2DPSink
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_ref() 0x77a6afa8: ref=2
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed:
IDLE -> CONFIGURED
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/a2dp.c:setup_unref() 0x77a5d040: ref=0
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/a2dp.c:setup_free() 0x77a5d040
Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_unref() 0x77a6afa8: ref=1
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:session_cb()
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_parse_cmd() Received OPEN_CMD
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/a2dp.c:open_ind() Sink 0x77a69bd8: Open_Ind
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from
00:1B:DC:07:32:D3
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport
channel to 00:1B:DC:07:32:D3
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed:
CONFIGURED -> OPEN
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
src/service.c:change_state() 0x77a70eb8: device 00:1B:DC:07:32:D3
profile a2dp-source state changed: disconnected -> connected (0)
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
plugins/policy.c:service_cb() Added a2dp-source reconnect 1
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/source.c:source_set_state() State changed
/org/bluez/hci0/dev_00_1B_DC_07_32_D3: SOURCE_STATE_CONNECTING ->
SOURCE_STATE_CONNECTED
Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
profiles/audio/transport.c:transport_update_playing()
/org/bluez/hci0/dev_00_1B_DC_07_32_D3/fd19 State=TRANSPORT_STATE_IDLE


It seems the avdtp_server_socket did not received the signals and
that's the reason why the avdtp_confirm_cb function did not execute. I
would like to know what are the possible scenario why the bluetoothd
did not receive the event?.
Because, if I re-run the PTS with the same test case, the bluez could
received the event.

Regards,

john


2014-10-14 22:27:51

by John Tobias

[permalink] [raw]
Subject: Re: Not getting an AVDTP: incoming connect

Hi Luiz,

I was able to reproduce again and here are the logs.

HCI LOGS:

HCI Event: Connect Request (0x04) plen 10
bdaddr 00:1B:DC:07:32:D3 class 0x080418 type ACL
< HCI Command: Accept Connection Request (0x01|0x0009) plen 7
bdaddr 00:1B:DC:07:32:D3 role 0x00
Role: Master
> HCI Event: Command Status (0x0f) plen 4
Accept Connection Request (0x01|0x0009) status 0x00 ncmd 1
> HCI Event: Connect Complete (0x03) plen 11
status 0x00 handle 1 bdaddr 00:1B:DC:07:32:D3 type ACL encrypt 0x00
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
handle 1
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
bdaddr 00:1B:DC:07:32:D3 mode 1
> HCI Event: Command Status (0x0f) plen 4
Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1
> HCI Event: Read Remote Supported Features (0x0b) plen 11
status 0x00 handle 1
Features: 0xff 0xff 0x8f 0x7e 0xd8 0x1f 0x5b 0x87
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3
handle 1 page 1
> HCI Event: Command Status (0x0f) plen 4
Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1
> HCI Event: Max Slots Change (0x1b) plen 3
handle 1 slots 5
> HCI Event: Read Remote Extended Features (0x23) plen 13
status 0x00 handle 1 page 1 max 1
Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
< HCI Command: Remote Name Request (0x01|0x0019) plen 10
bdaddr 00:1B:DC:07:32:D3 mode 2 clkoffset 0x0000
> HCI Event: Command Status (0x0f) plen 4
Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
> HCI Event: Remote Name Req Complete (0x07) plen 255
status 0x00 bdaddr 00:1B:DC:07:32:D3 name 'PTS-A2DP-WIN-4MP7G5VHB2U'
< HCI Command: Disconnect (0x01|0x0006) plen 3
handle 1 reason 0x13
Reason: Remote User Terminated Connection
> HCI Event: Command Status (0x0f) plen 4
Disconnect (0x01|0x0006) status 0x00 ncmd 1
> HCI Event: Disconn Complete (0x05) plen 4
status 0x00 handle 1 reason 0x16
Reason: Connection Terminated by Local Host
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0
> HCI Event: Command Complete (0x0e) plen 10
Read BD ADDR (0x04|0x0009) ncmd 1
status 0x00 bdaddr D0:E7:82:ED:B0:1A


Additionally, I've encounter a scenario where I was able to respond to
the prompt (Confirm passkey 773535 (yes/no):), after entering yes and
enter, the hcidump did not logs any event.

Regards,

john

On Tue, Oct 14, 2014 at 2:51 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi John,
>
> On Tue, Oct 14, 2014 at 3:09 AM, John Tobias <[email protected]> wrote:
>> Hi Marcell / Bluez Team:
>>
>> I was running the PTS 5.2 and there were an occurrences that the bluez
>> did not show a similar message below:
>>
>> [agent] Authorize service 0000110d-0000-1000-8000-00805f9b34fb (yes/no):
>>
>>
>> 1. I logs below are the traces of the bluetoothd not prompting the
>> Authorize service message:
>>
>> t 13 23:27:22 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/adapter.c:connected_callback() hci0 device 00:1B:DC:07:32:D3
>> connected eir_len 31
>> Oct 13 23:27:22 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_connected
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/adapter.c:dev_disconnected() Device 00:1B:DC:07:32:D3
>> disconnected, reason 2
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/adapter.c:adapter_remove_connection()
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> plugins/policy.c:disconnect_cb() reason 2
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:1B:DC:07:32:D3
>> type 0 status 0xe
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/device.c:device_bonding_complete() bonding (nil) status 0x0e
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/device.c:device_bonding_failed() status 14
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/adapter.c:resume_discovery()
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_disconnected
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: setting adv
>> params failed: Operation not permitted
>> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: failed to enable
>> advertising
>>
>>
>> 2. These messages are the traces of the bluetoothd showing the
>> Authorize service message:
>>
>> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/adapter.c:connected_callback() hci0 device 00:1B:DC:07:32:D3
>> connected eir_len 31
>> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_connected
>> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from
>> 00:1B:DC:07:32:D3
>> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/source.c:source_set_state() State changed
>> /org/bluez/hci0/dev_00_1B_DC_07_32_D3: SOURCE_STATE_DISCONNECTED ->
>> SOURCE_STATE_CONNECTING
>> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/agent.c:agent_ref() 0x77a601d0: ref=2
>> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/agent.c:agent_authorize_service() authorize service request was
>> sent for /org/bluez/hci0/dev_00_1B_DC_07_32_D3
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/agent.c:agent_ref() 0x77a601d0: ref=3
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/agent.c:agent_unref() 0x77a601d0: ref=2
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/agent.c:agent_unref() 0x77a601d0: ref=1
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling
>> channel to 00:1B:DC:07:32:D3
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=672
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:session_cb()
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_parse_cmd() Received DISCOVER_CMD
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:session_cb()
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_parse_cmd() Received
>> GET_CAPABILITIES_CMD
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/a2dp.c:endpoint_getcap_ind() Sink 0x77a69bd8:
>> Get_Capability_Ind
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:session_cb()
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_parse_cmd() Received
>> SET_CONFIGURATION_CMD
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/a2dp.c:endpoint_setconf_ind() Sink 0x77a69bd8:
>> Set_Configuration_Ind
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_ref() 0x77a6afa8: ref=1
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/a2dp.c:setup_ref() 0x77a5d040: ref=1
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/media.c:media_endpoint_async_call() Calling
>> SetConfiguration: name = :1.6 path = /MediaEndpoint/A2DPSink
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_ref() 0x77a6afa8: ref=2
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed:
>> IDLE -> CONFIGURED
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/a2dp.c:setup_unref() 0x77a5d040: ref=0
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/a2dp.c:setup_free() 0x77a5d040
>> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_unref() 0x77a6afa8: ref=1
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:session_cb()
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_parse_cmd() Received OPEN_CMD
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/a2dp.c:open_ind() Sink 0x77a69bd8: Open_Ind
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from
>> 00:1B:DC:07:32:D3
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport
>> channel to 00:1B:DC:07:32:D3
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed:
>> CONFIGURED -> OPEN
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> src/service.c:change_state() 0x77a70eb8: device 00:1B:DC:07:32:D3
>> profile a2dp-source state changed: disconnected -> connected (0)
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> plugins/policy.c:service_cb() Added a2dp-source reconnect 1
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/source.c:source_set_state() State changed
>> /org/bluez/hci0/dev_00_1B_DC_07_32_D3: SOURCE_STATE_CONNECTING ->
>> SOURCE_STATE_CONNECTED
>> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
>> profiles/audio/transport.c:transport_update_playing()
>> /org/bluez/hci0/dev_00_1B_DC_07_32_D3/fd19 State=TRANSPORT_STATE_IDLE
>>
>>
>> It seems the avdtp_server_socket did not received the signals and
>> that's the reason why the avdtp_confirm_cb function did not execute. I
>> would like to know what are the possible scenario why the bluetoothd
>> did not receive the event?.
>> Because, if I re-run the PTS with the same test case, the bluez could
>> received the event.
>
> It would probably help if you have the HCI logs as well, perhaps there
> is something wrong with authentication or we are rejecting the L2CAP
> connection for some reason. Also note that the server socket is only
> initialized if once a endpoint is registered so perhaps in case 1 you
> did not have any endpoint available.
>
>
> --
> Luiz Augusto von Dentz

2014-10-14 09:51:56

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Not getting an AVDTP: incoming connect

Hi John,

On Tue, Oct 14, 2014 at 3:09 AM, John Tobias <[email protected]> wrote:
> Hi Marcell / Bluez Team:
>
> I was running the PTS 5.2 and there were an occurrences that the bluez
> did not show a similar message below:
>
> [agent] Authorize service 0000110d-0000-1000-8000-00805f9b34fb (yes/no):
>
>
> 1. I logs below are the traces of the bluetoothd not prompting the
> Authorize service message:
>
> t 13 23:27:22 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/adapter.c:connected_callback() hci0 device 00:1B:DC:07:32:D3
> connected eir_len 31
> Oct 13 23:27:22 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_connected
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/adapter.c:dev_disconnected() Device 00:1B:DC:07:32:D3
> disconnected, reason 2
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/adapter.c:adapter_remove_connection()
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> plugins/policy.c:disconnect_cb() reason 2
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:1B:DC:07:32:D3
> type 0 status 0xe
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/device.c:device_bonding_complete() bonding (nil) status 0x0e
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/device.c:device_bonding_failed() status 14
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/adapter.c:resume_discovery()
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_disconnected
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: setting adv
> params failed: Operation not permitted
> Oct 13 23:27:26 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: failed to enable
> advertising
>
>
> 2. These messages are the traces of the bluetoothd showing the
> Authorize service message:
>
> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/adapter.c:connected_callback() hci0 device 00:1B:DC:07:32:D3
> connected eir_len 31
> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]: on_connected
> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from
> 00:1B:DC:07:32:D3
> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/source.c:source_set_state() State changed
> /org/bluez/hci0/dev_00_1B_DC_07_32_D3: SOURCE_STATE_DISCONNECTED ->
> SOURCE_STATE_CONNECTING
> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/agent.c:agent_ref() 0x77a601d0: ref=2
> Oct 13 23:29:48 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/agent.c:agent_authorize_service() authorize service request was
> sent for /org/bluez/hci0/dev_00_1B_DC_07_32_D3
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/agent.c:agent_ref() 0x77a601d0: ref=3
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/agent.c:agent_unref() 0x77a601d0: ref=2
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/agent.c:agent_unref() 0x77a601d0: ref=1
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling
> channel to 00:1B:DC:07:32:D3
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=672
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:session_cb()
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_parse_cmd() Received DISCOVER_CMD
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:session_cb()
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_parse_cmd() Received
> GET_CAPABILITIES_CMD
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/a2dp.c:endpoint_getcap_ind() Sink 0x77a69bd8:
> Get_Capability_Ind
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:session_cb()
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_parse_cmd() Received
> SET_CONFIGURATION_CMD
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/a2dp.c:endpoint_setconf_ind() Sink 0x77a69bd8:
> Set_Configuration_Ind
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_ref() 0x77a6afa8: ref=1
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/a2dp.c:setup_ref() 0x77a5d040: ref=1
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/media.c:media_endpoint_async_call() Calling
> SetConfiguration: name = :1.6 path = /MediaEndpoint/A2DPSink
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_ref() 0x77a6afa8: ref=2
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed:
> IDLE -> CONFIGURED
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/a2dp.c:setup_unref() 0x77a5d040: ref=0
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/a2dp.c:setup_free() 0x77a5d040
> Oct 13 23:29:52 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_unref() 0x77a6afa8: ref=1
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:session_cb()
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_parse_cmd() Received OPEN_CMD
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/a2dp.c:open_ind() Sink 0x77a69bd8: Open_Ind
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from
> 00:1B:DC:07:32:D3
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport
> channel to 00:1B:DC:07:32:D3
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed:
> CONFIGURED -> OPEN
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> src/service.c:change_state() 0x77a70eb8: device 00:1B:DC:07:32:D3
> profile a2dp-source state changed: disconnected -> connected (0)
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> plugins/policy.c:service_cb() Added a2dp-source reconnect 1
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/source.c:source_set_state() State changed
> /org/bluez/hci0/dev_00_1B_DC_07_32_D3: SOURCE_STATE_CONNECTING ->
> SOURCE_STATE_CONNECTED
> Oct 13 23:29:53 DEV9MRCNERGAAAQYDKGP bluetoothd[152]:
> profiles/audio/transport.c:transport_update_playing()
> /org/bluez/hci0/dev_00_1B_DC_07_32_D3/fd19 State=TRANSPORT_STATE_IDLE
>
>
> It seems the avdtp_server_socket did not received the signals and
> that's the reason why the avdtp_confirm_cb function did not execute. I
> would like to know what are the possible scenario why the bluetoothd
> did not receive the event?.
> Because, if I re-run the PTS with the same test case, the bluez could
> received the event.

It would probably help if you have the HCI logs as well, perhaps there
is something wrong with authentication or we are rejecting the L2CAP
connection for some reason. Also note that the server socket is only
initialized if once a endpoint is registered so perhaps in case 1 you
did not have any endpoint available.


--
Luiz Augusto von Dentz