Re: Not getting an AVDTP: incoming connect

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi John,

On Tue, Oct 14, 2014 at 3:09 AM, John Tobias <john.tobias.ph@xxxxxxxxx> 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
--
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




[Index of Archives]     [Bluez Devel]     [Linux Wireless Networking]     [Linux Wireless Personal Area Networking]     [Linux ATH6KL]     [Linux USB Devel]     [Linux Media Drivers]     [Linux Audio Users]     [Linux Kernel]     [Linux SCSI]     [Big List of Linux Books]

  Powered by Linux