Fix SDP resolving segfault

Guys,

I think this patch fixes the weird segfault I had been experiencing for the last few months.

Manuel

From: Manuel Francisco Naranjo <[email protected]>
Date: Tue, 20 Jul 2010 20:12:56 -0300
Subject: [PATCH] Possible fix for BlueZ SDP segfaults

modified: src/glib-helper.c

Sometimes when you do a DiscoverServices through DBUS and the device goes out of range then BlueZ will end with a SegFault. I've traced it, and it seems like connect_watch is been triggered, it gets into the failed tag and when it does the callback as the btd_device has been released before, the callback triggers the segfault.

This patch seems to fix the problem, not sure if this is the best way, or the right one at all. Maybe the problem is that btd_device has no direct reference to the search_context and then when btd_device is released there's no direct search_context release (this happens through the function bt_cancel_discovery, but I have a feeling this approach is actually failing in some cases).

---
 src/glib-helper.c |   18 ++++++++++++------
 1 files changed, 12 insertions(+), 6 deletions(-)

index 41f5e3c..fef0d41 100644
@@ -156,8 +156,10 @@ static void search_context_cleanup(struct search_context *ctxt)
 {
 	context_list = g_slist_remove(context_list, ctxt);
 
-	if (ctxt->destroy)
+	if (ctxt->destroy){
 		ctxt->destroy(ctxt->user_data);
+		ctxt->user_data = NULL;
+	}
 
 	g_free(ctxt);
 }

@@ -206,7 +208,7 @@ static void search_completed_cb(uint8_t type, uint16_t status,
 done:
 	cache_sdp_session(&ctxt->src, &ctxt->dst, ctxt->session);
 
-	if (ctxt->cb)
+	if (ctxt->cb && ctxt->user_data)
 		ctxt->cb(recs, err, ctxt->user_data);
 
 	if (recs)

@@ -236,7 +238,7 @@ failed:
 		sdp_close(ctxt->session);
 		ctxt->session = NULL;
 
-		if (ctxt->cb)
+		if (ctxt->cb && ctxt->user_data)
 			ctxt->cb(NULL, err, ctxt->user_data);
 
 		search_context_cleanup(ctxt);

@@ -254,6 +256,8 @@ static gboolean connect_watch(GIOChannel *chan, GIOCondition cond, gpointer user
 	int sk, err = 0;
 
 	sk = g_io_channel_unix_get_fd(chan);
+	if (ctxt->io_id)
+	    g_source_remove(ctxt->io_id);
 	ctxt->io_id = 0;
 
 	len = sizeof(err);

@@ -293,7 +297,7 @@ failed:
 	sdp_close(ctxt->session);
 	ctxt->session = NULL;
 
-	if (ctxt->cb)
+	if (ctxt->cb && ctxt->user_data)
 		ctxt->cb(NULL, -err, ctxt->user_data);
 
 	search_context_cleanup(ctxt);

@@ -391,11 +395,13 @@ int bt_cancel_discovery(const bdaddr_t *src, const bdaddr_t *dst)
 		return -ENODATA;
 
 	ctxt = match->data;
-	if (!ctxt->session)
-		return -ENOTCONN;
 
 	if (ctxt->io_id)
 		g_source_remove(ctxt->io_id);
+	ctxt->io_id = 0;
+
+	if (!ctxt->session)
+		return -ENOTCONN;
 
 	if (ctxt->session)
 		sdp_close(ctxt->session);

1.6.4.4

Hi Manuel,

Thanks for the patch proposal. It seems like you're trying to to fix the issue by doing all sorts of minor tweaks here and there, i.e. it seems like there isn't a full understanding of the real root cause.

Hi,

Yep, I suspect it is something else too, there doesn't seems to be a call to bt_cancel_discovery in the last trace sent to the list, but the check for ctxt->session there seems buggy, we should always remove the context doesn't matter if it is connected or not.

@Manuel: Does valgrind give you a nice bracktrace when it bluetoothd segfaults?

Normally I use something like this:

Luiz Augusto von Dentz
Computer Engineer

Luiz,

I think the problem is that the watch function is still registered even though we no longer have a session... maybe this doesn't make sense, no way we have a context and don't have a session.

Still if there's no session the context never gets released.

Check the other email, I made it by running bluetoothd -ndt (this is a feature I commited, which uses instrumentation-functions from gcc, a really nice feature).

Manuel

Johan,

I agree, I know this doesn't fix the root cause, it only works it out. Like we say in Argentina we attach it with aluminium threads.

Then the problem is the callback function!

The trace shows that browse_cb gets right into search_cb which never checks if user_data is NULL. It doesn't do it because MOST of the time it isn't only when something weird happens.

Ok you got me I missed that.

I think this is the one that really fix the problem. I see connect_watch getting called and then getting into the crash. I have a nice log with the tracing feature I sent the other day, here's the end of it (the hole thing is almost 40 megs if someone wants just ask for it).

        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x80893be (from 0x808a166)   cmd_status()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x8089425 (from 0x808a187)   cmd_complete()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x8089b72 (from 0x808a2f4)   conn_complete()
        +  2 0x80add52 (from 0x8089bda)    hcid_dbus_conn_complete()
        +  3 0x80ac3e0 (from 0x80adda1)     get_adapter_and_device()
        +  4 0x809d9c3 (from 0x80ac405)      manager_find_adapter()
        +  5 0x809d8e3 (from 0x16847e)       adapter_cmp()
        +  6 0x80a44f7 (from 0x809d91b)        adapter_get_address()
        +  7 0x809dff1 (from 0x80a4525)         bacpy()
        +  6 0x809cf7c (from 0x809d92d)        bacmp()
        +  4 0x80a0aba (from 0x80ac45b)      adapter_get_device()
        +  5 0x8087840 (from 0x80a0b03)       btd_debug()
        +  5 0x80a041a (from 0x80a0b22)       adapter_find_device()
        +  6 0x80a883e (from 0x16847e)        device_address_cmp()
....
        +  6 0x80a883e (from 0x16847e)        device_address_cmp()
        +  3 0x80a80a3 (from 0x80addc4)     device_get_secmode3_conn()
        +  3 0x80a80e1 (from 0x80addda)     device_set_secmode3_conn()
        +  3 0x80aaddf (from 0x80added)     device_is_bonding()
        +  3 0x80a9cf7 (from 0x80ade0f)     device_is_temporary()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x80891f0 (from 0x808a239)   inquiry_complete()
        +  2 0x809d9c3 (from 0x808923f)    manager_find_adapter()
        +  3 0x809d8e3 (from 0x16847e)     adapter_cmp()
        +  4 0x80a44f7 (from 0x809d91b)      adapter_get_address()
        +  5 0x809dff1 (from 0x80a4525)       bacpy()
        +  4 0x809cf7c (from 0x809d92d)      bacmp()
        +  2 0x809e7a5 (from 0x808929a)    adapter_resolve_names()
        +  3 0x809dff1 (from 0x809e804)     bacpy()
        +  3 0x80a46bb (from 0x809e81d)     adapter_search_found_devices()
        +  2 0x80a4642 (from 0x80892b0)    adapter_get_state()
        +  2 0x80a453a (from 0x80892fe)    adapter_set_state()
        +  3 0x80a4d46 (from 0x80a45e5)     adapter_update_oor_devices()
        +  3 0x80ac200 (from 0x80a4618)     emit_property_changed()
        +  4 0x80abf1d (from 0x80ac29c)      append_variant()
        +  4 0x804f543 (from 0x80ac2ae)      g_dbus_send_message()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x80893be (from 0x808a166)   cmd_status()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x804da4a (from 0x17fdab)  watch_func()
        +  1 0x804df9b (from 0x9cc0dd)   dispatch_status()
        +  2 0x804d9fb (from 0x804dfdd)    queue_dispatch()
        +  0 0x804d996 (from 0x14953c)  message_dispatch()
        +  1 0x8050409 (from 0x9cec8d)   message_filter()
        +  1 0x804ea38 (from 0x9dbf13)   generic_message()
        +  2 0x804e9b5 (from 0x804ea7b)    find_interface()
        +  2 0x80a0d23 (from 0x804eafd)    adapter_stop_discovery()
        +  3 0x809f488 (from 0x80a0d7f)     find_session()
        +  3 0x809f895 (from 0x80a0db2)     session_unref()
        +  4 0x8087840 (from 0x809f8f7)      btd_debug()
        +  4 0x809f7a8 (from 0x809f913)      session_free()
        +  5 0x8050a57 (from 0x809f7e3)       g_dbus_remove_watch()
        +  6 0x804fd59 (from 0x8050aa2)        filter_data_find_callback()
        +  6 0x804fd59 (from 0x8050aa2)        filter_data_find_callback()
        +  6 0x804fd59 (from 0x8050aa2)        filter_data_find_callback()
        +  6 0x804fd59 (from 0x8050aa2)        filter_data_find_callback()
        +  6 0x8050032 (from 0x8050abd) 
filter_data_remove_callback()
        +  7 0x804fb14 (from 0x80500db)         remove_match()
        +  8 0x804f8ea (from 0x804fb4e)          format_rule()
        +  8 0x804de1d (from 0x9e1783)          add_timeout()
        +  8 0x804df9b (from 0x9cc0dd)          dispatch_status()
        +  9 0x804d9fb (from 0x804dfdd)           queue_dispatch()
        +  8 0x804decc (from 0x9e16ff)          remove_timeout()
        +  8 0x804ddbf (from 0x9e1469)          timeout_handler_free()
        +  7 0x804fdf7 (from 0x805011d)         filter_data_free()
        +  7 0x804f790 (from 0x8050150)         filter_data_find()
        +  5 0x809f58c (from 0x809f7ee)       session_remove()
        +  6 0x8087840 (from 0x809f616)        btd_debug()
        +  6 0x8087840 (from 0x809f721)        btd_debug()
        +  6 0x809e6a8 (from 0x809f72c)        pending_remote_name_cancel()
        +  7 0x809dff1 (from 0x809e70e)         bacpy()
        +  7 0x80a46bb (from 0x809e727) 
adapter_search_found_devices()
        +  6 0x809e391 (from 0x809f737)        clear_found_devices_list()
        +  6 0x8085e04 (from 0x809f787)        hciops_stop_discovery()
        +  7 0x8084898 (from 0x8085e7b)         hci_test_bit()
        +  3 0x80877a4 (from 0x80a0dbe)     info()
        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x8089425 (from 0x808a187)   cmd_complete()
        +  2 0x80891f0 (from 0x808951e)    inquiry_complete()
        +  3 0x809d9c3 (from 0x808923f)     manager_find_adapter()
        +  4 0x809d8e3 (from 0x16847e)      adapter_cmp()
        +  5 0x80a44f7 (from 0x809d91b)       adapter_get_address()
        +  6 0x809dff1 (from 0x80a4525)        bacpy()
        +  5 0x809cf7c (from 0x809d92d)       bacmp()
        +  3 0x80a4642 (from 0x808926f)     adapter_get_state()
        +  3 0x80a453a (from 0x8089288)     adapter_set_state()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x804da4a (from 0x17fdab)  watch_func()
        +  1 0x804df9b (from 0x9cc0dd)   dispatch_status()
        +  2 0x804d9fb (from 0x804dfdd)    queue_dispatch()
        +  0 0x804d996 (from 0x14953c)  message_dispatch()
        +  1 0x8050409 (from 0x9cec8d)   message_filter()
        +  1 0x804ea38 (from 0x9dbf13)   generic_message()
        +  2 0x804e9b5 (from 0x804ea7b)    find_interface()
        +  2 0x80a0bde (from 0x804eafd)    adapter_start_discovery()
        +  3 0x809f488 (from 0x80a0c3d)     find_session()
        +  3 0x80a0b66 (from 0x80a0c92)     adapter_start_inquiry()
        +  4 0x809e6a8 (from 0x80a0ba4)      pending_remote_name_cancel()
        +  5 0x809dff1 (from 0x809e70e)       bacpy()
        +  5 0x80a46bb (from 0x809e727) 
adapter_search_found_devices()
        +  4 0x8085c9a (from 0x80a0bc1)      hciops_start_discovery()
        +  3 0x809ed21 (from 0x80a0cdd)     create_session()
        +  4 0x805092f (from 0x809ede5)      g_dbus_add_disconnect_watch()
        +  5 0x8050834 (from 0x8050978)       g_dbus_add_service_watch()
        +  6 0x804fbbb (from 0x8050898)        filter_data_get()
        +  7 0x804f790 (from 0x804fc08)         filter_data_find()
        +  7 0x804f790 (from 0x804fc6b)         filter_data_find()
        +  7 0x804fa5a (from 0x804fd0c)         add_match()
        +  8 0x804f8ea (from 0x804fa94)          format_rule()
        +  8 0x804de1d (from 0x9e1783)          add_timeout()
        +  8 0x804df9b (from 0x9cc0dd)          dispatch_status()
        +  9 0x804d9fb (from 0x804dfdd)           queue_dispatch()
        +  8 0x804decc (from 0x9e16ff)          remove_timeout()
        +  8 0x804ddbf (from 0x9e1469)          timeout_handler_free()
        +  6 0x804ff5d (from 0x80508d8)        filter_data_add_callback()
        +  4 0x80877a4 (from 0x809ee20)      info()
        +  4 0x809eca1 (from 0x809ee2b)      session_ref()
        +  5 0x8087840 (from 0x809ed03)       btd_debug()
        +  0 0x808a019 (from 0x17fdab)  io_security_event()
        +  1 0x8087c29 (from 0x808a121)   hci_test_bit()
        +  1 0x8089425 (from 0x808a187)   cmd_complete()
        +  2 0x80890df (from 0x80894fe)    start_inquiry()
        +  3 0x809d9c3 (from 0x808912e)     manager_find_adapter()
        +  4 0x809d8e3 (from 0x16847e)      adapter_cmp()
        +  5 0x80a44f7 (from 0x809d91b)       adapter_get_address()
        +  6 0x809dff1 (from 0x80a4525)        bacpy()
        +  5 0x809cf7c (from 0x809d92d)       bacmp()
        +  3 0x80a4642 (from 0x8089158)     adapter_get_state()
        +  3 0x80a543e (from 0x8089166)     adapter_has_discov_sessions()
        +  3 0x80a453a (from 0x808918a)     adapter_set_state()
        +  4 0x80ac200 (from 0x80a4618)      emit_property_changed()
        +  5 0x80abf1d (from 0x80ac29c)       append_variant()
        +  5 0x804f543 (from 0x80ac2ae)       g_dbus_send_message()
        +  1 0x808812b (from 0x808a38a)   check_pending_hci_req()
        +  0 0x80962cd (from 0x17fdab)  connect_watch()
        +  1 0x80a97cf (from 0x80964ae)   browse_cb()

Last call is search_cb I'm sure about it, thing is that the tracer only traces function when they exit, not when they get in.

I think the best way to solve this is that the device structure has a reference to the context so it can release it when it gets removed without any issue. We don't need the sdp callback if we no longer have a device anyway.

Manuel

Hi,

I just figure out that our connect_watch in glib_helper.c is not quite right, it should be something similar as we have btio.c, specially this one is particular important:

	/* If the user aborted this connect attempt */
	if ((cond & G_IO_NVAL) || check_nval(io))
		return FALSE;

It is probably because of not having this check that the cb is still called after bt_cancel_discovery. Of course this doesn't invalidate your fix to bt_cancel_discovery itself, but I guess this should also be included to safe that the callback is not called after cancelling the discovery.

Luiz Augusto von Dentz
Computer Engineer

Hi Manuel,

Can you try the patch attached to this email?

Luiz Augusto von Dentz
Computer Engineer

From 28953f5b419693d8281f057055a34d9bc3e4442e Mon Sep 17 00:00:00 2001
From: Luiz Augusto von Dentz <[email protected]>
Date: Wed, 28 Jul 2010 16:41:12 +0300
Subject: [PATCH] core: fix not handling sdp connection errors properly

---
 src/glib-helper.c |  145 +++++++++++++++++++++++++++++++++++++----------------
 1 files changed, 101 insertions(+), 44 deletions(-)

index 41f5e3c..afd664e 100644
@@ -44,6 +44,8 @@
 #include <glib.h>
 
 #include "glib-helper.h"
+#include "btio.h"
+#include "log.h"
 
 /* Number of seconds to keep a sdp_session_t in the cache */
 #define CACHE_TIMEOUT 2

@@ -98,7 +100,7 @@ static sdp_session_t *get_sdp_session(const bdaddr_t *src, const bdaddr_t *dst)
 		return session;
 	}
 
-	return sdp_connect(src, dst, SDP_NON_BLOCKING);
+	return NULL;
 }
 
 static void cache_sdp_session(bdaddr_t *src, bdaddr_t *dst,

@@ -143,6 +145,7 @@ struct search_context {
 	bdaddr_t		src;
 	bdaddr_t		dst;
 	sdp_session_t		*session;
+	GIOChannel		*io;
 	bt_callback_t		cb;
 	bt_destroy_t		destroy;
 	gpointer		user_data;

@@ -245,56 +248,99 @@ failed:
 	return FALSE;
 }
 
-static gboolean connect_watch(GIOChannel *chan, GIOCondition cond, gpointer user_data)
+static int sdp_search(struct search_context *ctxt)
 {
-	struct search_context *ctxt = user_data;
+	GIOChannel *chan;
 	sdp_list_t *search, *attrids;
 	uint32_t range = 0x0000ffff;
-	socklen_t len;
-	int sk, err = 0;
-
-	sk = g_io_channel_unix_get_fd(chan);
-	ctxt->io_id = 0;
+	int err, sk;
 
-	len = sizeof(err);
-	if (getsockopt(sk, SOL_SOCKET, SO_ERROR, &err, &len) < 0) {
-		err = errno;
-		goto failed;
-	}
-
-	if (err != 0)
-		goto failed;
-
-	if (sdp_set_notify(ctxt->session, search_completed_cb, ctxt) < 0) {
-		err = EIO;
-		goto failed;
-	}
+	err = sdp_set_notify(ctxt->session, search_completed_cb, ctxt);
+	if (err < 0)
+		return err;
 
 	search = sdp_list_append(NULL, &ctxt->uuid);
 	attrids = sdp_list_append(NULL, &range);
-	if (sdp_service_search_attr_async(ctxt->session,
-				search, SDP_ATTR_REQ_RANGE, attrids) < 0) {
-		sdp_list_free(attrids, NULL);
-		sdp_list_free(search, NULL);
-		err = EIO;
-		goto failed;
-	}
 
+	err = sdp_service_search_attr_async(ctxt->session, search,
+						SDP_ATTR_REQ_RANGE, attrids);
 	sdp_list_free(attrids, NULL);
 	sdp_list_free(search, NULL);
+	if (err < 0)
+		return err;
+
+	sk = sdp_get_socket(ctxt->session);
+	chan = g_io_channel_unix_new(sk);
 
 	/* Set callback responsible for update the internal SDP transaction */
 	ctxt->io_id = g_io_add_watch(chan,
 				G_IO_IN | G_IO_HUP | G_IO_ERR | G_IO_NVAL,
 				search_process_cb, ctxt);
-	return FALSE;
+
+	return 0;
+}
+
+static void connect_watch(GIOChannel *chan, GError *gerr, gpointer user_data)
+{
+	struct search_context *ctxt = user_data;
+	int sk, err = 0;
+
+	if (gerr) {
+		err = -EHOSTDOWN;
+		goto failed;
+	}
+
+	g_io_channel_set_close_on_unref(ctxt->io, FALSE);
+	g_io_channel_unref(ctxt->io);
+	ctxt->io = NULL;
+
+	sk = g_io_channel_unix_get_fd(chan);
+	ctxt->session = sdp_create(sk, SDP_NON_BLOCKING);
+	if (ctxt->session == NULL) {
+		err = -ENOMEM;
+		goto failed;
+	}
+
+	err = sdp_search(ctxt);
+	if (err < 0)
+		goto failed;
+
+	return;
 
 failed:
+	if (ctxt->session) {
+		sdp_close(ctxt->session);
+		ctxt->session = NULL;
+	}
+
+	if (ctxt->io) {
+		g_io_channel_shutdown(ctxt->io, TRUE, NULL);
+		g_io_channel_unref(ctxt->io);
+		ctxt->io = NULL;
+	}
+
+	if (ctxt->cb)
+		ctxt->cb(NULL, err, ctxt->user_data);
+
+	search_context_cleanup(ctxt);
+}
+
+static gboolean sdp_resume(gpointer data)
+{
+	struct search_context *ctxt = data;
+	int err;
+
+	ctxt->io_id = 0;
+
+	err = sdp_search(ctxt);
+	if (err == 0)
+		return FALSE;
+
 	sdp_close(ctxt->session);
 	ctxt->session = NULL;
 
 	if (ctxt->cb)
-		ctxt->cb(NULL, -err, ctxt->user_data);
+		ctxt->cb(NULL, err, ctxt->user_data);
 
 	search_context_cleanup(ctxt);
 

@@ -306,15 +352,11 @@ static int create_search_context(struct search_context **ctxt,
 				uuid_t *uuid)
 {
 	sdp_session_t *s;
-	GIOChannel *chan;
+	GError *err = NULL;
 
 	if (!ctxt)
 		return -EINVAL;
 
-	s = get_sdp_session(src, dst);
-	if (!s)
-		return -errno;
-
 	*ctxt = g_try_malloc0(sizeof(struct search_context));
 	if (!*ctxt) {
 		sdp_close(s);

@@ -323,14 +365,27 @@ static int create_search_context(struct search_context **ctxt,
 
 	bacpy(&(*ctxt)->src, src);
 	bacpy(&(*ctxt)->dst, dst);
-	(*ctxt)->session = s;
 	(*ctxt)->uuid = *uuid;
 
-	chan = g_io_channel_unix_new(sdp_get_socket(s));
-	(*ctxt)->io_id = g_io_add_watch(chan,
-				G_IO_OUT | G_IO_HUP | G_IO_ERR | G_IO_NVAL,
-				connect_watch, *ctxt);
-	g_io_channel_unref(chan);
+	s = get_sdp_session(src, dst);
+	if (s != NULL) {
+		(*ctxt)->session = s;
+		(*ctxt)->io_id = g_idle_add(sdp_resume, *ctxt);
+		return 0;
+	}
+
+	(*ctxt)->io = bt_io_connect(BT_IO_L2CAP, connect_watch, *ctxt,
+					NULL, &err,
+					BT_IO_OPT_SOURCE_BDADDR, src,
+					BT_IO_OPT_DEST_BDADDR, dst,
+					BT_IO_OPT_PSM, SDP_PSM,
+					BT_IO_OPT_SEC_LEVEL, BT_IO_SEC_SDP,
+					BT_IO_OPT_INVALID);
+	if ((*ctxt)->io == NULL) {
+		g_error_free(err);
+		search_context_cleanup(*ctxt);
+		return -EINVAL;
+	}
 
 	return 0;
 }

@@ -391,15 +446,17 @@ int bt_cancel_discovery(const bdaddr_t *src, const bdaddr_t *dst)
 		return -ENODATA;
 
 	ctxt = match->data;
-	if (!ctxt->session)
-		return -ENOTCONN;
-
 	if (ctxt->io_id)
 		g_source_remove(ctxt->io_id);
 
 	if (ctxt->session)
 		sdp_close(ctxt->session);
 
+	if (ctxt->io) {
+		g_io_channel_shutdown(ctxt->io, TRUE, NULL);
+		g_io_channel_unref(ctxt->io);
+	}
+
 	search_context_cleanup(ctxt);
 	return 0;
 }

1.7.0.4

Hi Luiz,

I give it a try and let you know how it goes.

Manuel

Luiz,

Bad news it doesn't work, it keeps doing the same. This is the output of bluetoothd -n -d:
bluetoothd[3572]: audio/manager.c:handle_uuid() server not enabled for 0000110a-0000-1000-8000-00805f9b34fb (0x110a) bluetoothd[3572]: audio/manager.c:handle_uuid() Found AV Target bluetoothd[3572]: audio/control.c:control_init() Registered interface org.bluez.Control on path /org/bluez/3572/hci0/dev_00_24_91_E4_E9_05 bluetoothd[3572]: audio/manager.c:handle_uuid() Found AV Target bluetoothd[3572]: src/device.c:btd_device_unref() 0x90f9e08: ref=2 bluetoothd[3572]: src/device.c:btd_device_ref() 0x90f9e08: ref=3 bluetoothd[3572]: src/device.c:search_cb() /org/bluez/3572/hci0/dev_00_24_91_E4_E9_05: No service update bluetoothd[3572]: src/device.c:btd_device_unref() 0x90f9e08: ref=2 bluetoothd[3572]: src/adapter.c:session_unref() 0x90b2790: ref=0 bluetoothd[3572]: src/adapter.c:session_remove() Discovery session 0x90b2790 with :1.81 deactivated
bluetoothd[3572]: src/adapter.c:session_remove() Stopping discovery bluetoothd[3572]: Stopping discovery
bluetoothd[3572]: src/device.c:btd_device_ref() 0x90adfd0: ref=2 bluetoothd[3572]: Discovery session 0x90fe178 with :1.81 activated bluetoothd[3572]: src/adapter.c:session_ref() 0x90fe178: ref=1 bluetoothd[3572]: src/adapter.c:adapter_remove_connection() Removing temporary device /org/bluez/3572/hci0/dev_C8_7E_75_DC_1E_86 bluetoothd[3572]: src/device.c:device_remove() Removing device /org/bluez/3572/hci0/dev_C8_7E_75_DC_1E_86 bluetoothd[3572]: src/device.c:btd_device_unref() 0x90fc080: ref=1 bluetoothd[3572]: src/device.c:btd_device_unref() 0x90fc080: ref=0 bluetoothd[3572]: src/device.c:device_free() 0x90fc080 bluetoothd[3572]: src/adapter.c:adapter_get_device() 00:05:4F:63:5A:E0 bluetoothd[3572]: src/adapter.c:session_unref() 0x90fe178: ref=0 bluetoothd[3572]: src/adapter.c:session_remove() Discovery session 0x90fe178 with :1.81 deactivated
bluetoothd[3572]: src/adapter.c:session_remove() Stopping discovery bluetoothd[3572]: Stopping discovery
bluetoothd[3572]: Discovery session 0x90b1e00 with :1.81 activated bluetoothd[3572]: src/adapter.c:session_ref() 0x90b1e00: ref=1 bluetoothd[3572]: <27>Jul 28 14:26:36 bluetoothd[3572]: : error updating services: Host is down (112)

And this is the call trace during the crash:
+ 4 0x80ac636 (from 0x80a9a28) device_remove_connection():
/home/manuel/bluez/src/device.c:908
+ 5 0x80ac4ca (from 0x80ac753) device_set_connected():
/home/manuel/bluez/src/device.c:875
+ 6 0x80b0d08 (from 0x80ac517) emit_property_changed():
/home/manuel/bluez/src/dbus-common.c:266
+ 7 0x80b0a31 (from 0x80b0da4) append_variant():
/home/manuel/bluez/src/dbus-common.c:195
+ 7 0x805005d (from 0x80b0db6) g_dbus_send_message():
/home/manuel/bluez/gdbus/object.c:615
+ 4 0x80ae60e (from 0x80a9a55) device_get_address():
/home/manuel/bluez/src/device.c:1654
+ 5 0x80aa5a4 (from 0x80ae639) bacpy():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:132
+ 4 0x808a77f (from 0x80a9a6d) hci_req_queue_remove():
/home/manuel/bluez/src/security.c:169
+ 4 0x80affea (from 0x80a9a78) device_is_authenticating():
/home/manuel/bluez/src/device.c:2339
+ 4 0x80ae749 (from 0x80a9a9a) device_is_temporary():
/home/manuel/bluez/src/device.c:1683
+ 1 0x808a82f (from 0x808cdb4) check_pending_hci_req():
/home/manuel/bluez/src/security.c:186
+ 0 0x8094781 (from 0x2cddab) connect_cb(): /home/manuel/bluez/src/btio.c:138
+ 1 0x8094628 (from 0x80947be) check_nval():
/home/manuel/bluez/src/btio.c:103
+ 1 0x8097b6e (from 0x8094849) bt_io_error_quark():
/home/manuel/bluez/src/btio.c:1296
+ 1 0x8099523 (from 0x80948c1) connect_watch():
/home/manuel/bluez/src/glib-helper.c:283
+ 2 0x80ae1c5 (from 0x809966f) browse_cb():
/home/manuel/bluez/src/device.c:1540
+ 3 0x80adf2f (from 0x80ae312) search_cb():
/home/manuel/bluez/src/device.c:1476
+ 4 0x8089ef6 (from 0x80adf90) error(): /home/manuel/bluez/src/log.c:47

If you go through the code it fails in the line:
static void search_cb(sdp_list_t *recs, int err, gpointer user_data)

{
	struct browse_req *req = user_data;
	struct btd_device *device = req->device;

	if (err < 0) {
		error("%s: error updating services: %s (%d)",
				device->path, strerror(-err), -err);
		goto send_reply;
	}

It fails because device->path is not valid.

My patch even though than ugly it worked. I know this is not the best for upstream, but at least is something to start with. For some reason either user_data or device is invalid when that callback gets.

Manuel

Manuel Francisco Naranjo
Software Department Argentina
Wireless Cables Inc
www.aircable.net
cel: +5493412010019
skype: naranjomanuelfrancisco

Hi Manuel,

I guess I finally figure out what could be the source of your problems, we are not removing the watches when caching the session and since the context is already freed bt_cancel_discovery doesn't work.

The attached patch should fix this problem, Im also reseting the internal data of the session by doing sdp_set_notify so if we are not closing the session it will then reset the callback and data to NULL.

Luiz Augusto von Dentz
Computer Engineer

From 204247e7ad5dad50ea25188022c725e36cbd6ef5 Mon Sep 17 00:00:00 2001
From: Luiz Augusto von Dentz <[email protected]>
Date: Thu, 29 Jul 2010 11:28:18 +0300
Subject: [PATCH] core: fix not removing watches when caching sdp session

---
 src/glib-helper.c |   19 ++++++++++---------
 1 files changed, 10 insertions(+), 9 deletions(-)

index 41f5e3c..e75e270 100644
@@ -156,6 +156,12 @@ static void search_context_cleanup(struct search_context *ctxt)
 {
 	context_list = g_slist_remove(context_list, ctxt);
 
+	if (ctxt->io_id)
+		g_source_remove(ctxt->io_id);
+
+	if (ctxt->session)
+		sdp_close(ctxt->session);
+
 	if (ctxt->destroy)
 		ctxt->destroy(ctxt->user_data);
 

@@ -204,7 +210,10 @@ static void search_completed_cb(uint8_t type, uint16_t status,
 	} while (scanned < (ssize_t) size && bytesleft > 0);
 
 done:
-	cache_sdp_session(&ctxt->src, &ctxt->dst, ctxt->session);
+	if (sdp_set_notify(ctxt->session, NULL, NULL) == 0) {
+		cache_sdp_session(&ctxt->src, &ctxt->dst, ctxt->session);
+		ctxt->session = NULL;
+	}
 
 	if (ctxt->cb)
 		ctxt->cb(recs, err, ctxt->user_data);

@@ -391,14 +400,6 @@ int bt_cancel_discovery(const bdaddr_t *src, const bdaddr_t *dst)
 		return -ENODATA;
 
 	ctxt = match->data;
-	if (!ctxt->session)
-		return -ENOTCONN;
-
-	if (ctxt->io_id)
-		g_source_remove(ctxt->io_id);
-
-	if (ctxt->session)
-		sdp_close(ctxt->session);
 
 	search_context_cleanup(ctxt);
 	return 0;

1.7.0.4

Luiz,

Looks like a possible fix nice work thanks!.

Unfortunately I will not be able to test until next week. I let you know when I get some results, I got my netbook today in a mall with some more debug messages, I added a few calls to error in the search_cb that prints all the pointer numbers when it gets called, that will get some more information. I could fix the problem this way as well, but this is working on the simpthon not on the cause like yours.

You think the hole problem is because of the cache? Wow I never thought it that way. But it makes sense. It also makes sense to move cleanup processes inside the cleanup function.

I will give this a try and let you know. Maybe I can results before the Tuesday, but I doubt it.

Manuel

As I said on IRC it keeps crashing. Here's the log, as you can see the crash happened in a different place now.

bluetoothd[1842]: src/device.c:btd_device_ref() 0x9411de0: ref=1 bluetoothd[1842]: src/device.c:btd_device_ref() 0x9411de0: ref=2 bluetoothd[1842]: src/device.c:btd_device_ref() 0x9409570: ref=2 bluetoothd[1842]: src/device.c:btd_device_ref() 0x9408b60: ref=2 bluetoothd[1842]: src/adapter.c:create_device() C8:7E:75:D6:B3:B0 bluetoothd[1842]: src/adapter.c:adapter_create_device() C8:7E:75:D6:B3:B0 bluetoothd[1842]: src/device.c:device_create() Creating device /org/bluez/1842/hci0/dev_C8_7E_75_D6_B3_B0
bluetoothd[1842]: src/device.c:btd_device_ref() 0x93fd258: ref=1 bluetoothd[1842]: src/device.c:btd_device_ref() 0x93fd258: ref=2 bluetoothd[1842]: src/device.c:btd_device_ref() 0x9404dc0: ref=3 bluetoothd[1842]: Discovery session 0x93fb658 with :1.58 activated bluetoothd[1842]: src/adapter.c:session_ref() 0x93fb658: ref=1 bluetoothd[1842]: src/adapter.c:adapter_get_device() 00:25:47:2D:20:98 bluetoothd[1842]: src/adapter.c:session_unref() 0x93fb658: ref=0 bluetoothd[1842]: src/adapter.c:session_remove() Discovery session 0x93fb658 with :1.58 deactivated
bluetoothd[1842]: src/adapter.c:session_remove() Stopping discovery bluetoothd[1842]: Stopping discovery
bluetoothd[1842]: /org/bluez/1842/hci0/dev_C8_7E_75_D6_B3_B0: error updating services: Device or resource busy (16) bluetoothd[1842]: src/device.c:btd_device_unref() 0x93fd258: ref=1 bluetoothd[1842]: Discovery session 0x93fd4b0 with :1.58 activated bluetoothd[1842]: src/adapter.c:session_ref() 0x93fd4b0: ref=1 bluetoothd[1842]: /org/bluez/1842/hci0/dev_00_26_E2_3C_5E_05: error updating services: Host is down (112)
bluetoothd[1842]: src/device.c:btd_device_unref() 0x9404dc0: ref=2 bluetoothd[1842]: src/adapter.c:adapter_get_device() 00:26:E2:3C:5E:05 bluetoothd[1842]: src/adapter.c:session_unref() 0x93fd4b0: ref=0 bluetoothd[1842]: src/adapter.c:session_remove() Discovery session 0x93fd4b0 with :1.58 deactivated
bluetoothd[1842]: src/adapter.c:session_remove() Stopping discovery bluetoothd[1842]: Stopping discovery
bluetoothd[1842]: /org/bluez/1842/hci0/dev_00_1C_D6_B1_58_1B: error updating services: Device or resource busy (16) bluetoothd[1842]: src/device.c:btd_device_unref() 0x9409570: ref=1 bluetoothd[1842]: Discovery session 0x93f9f80 with :1.58 activated bluetoothd[1842]: src/adapter.c:session_ref() 0x93f9f80: ref=1 bluetoothd[1842]: src/adapter.c:adapter_remove_connection() Removing temporary device /org/bluez/1842/hci0/dev_00_25_47_2D_20_98 bluetoothd[1842]: src/device.c:device_remove() Removing device /org/bluez/1842/hci0/dev_00_25_47_2D_20_98
bluetoothd[1842]: src/device.c:btd_device_unref() 0x9411120: ref=1 bluetoothd[1842]: src/device.c:btd_device_unref() 0x9411120: ref=0 bluetoothd[1842]: src/device.c:device_free() 0x9411120 bluetoothd[1842]: src/adapter.c:adapter_get_device() 00:17:D5:65:D0:3D bluetoothd[1842]: src/adapter.c:session_unref() 0x93f9f80: ref=0 bluetoothd[1842]: src/adapter.c:session_remove() Discovery session 0x93f9f80 with :1.58 deactivated
bluetoothd[1842]: src/adapter.c:session_remove() Stopping discovery bluetoothd[1842]: Stopping discovery
bluetoothd[1842]: Discovery session 0x9410560 with :1.58 activated bluetoothd[1842]: src/adapter.c:session_ref() 0x9410560: ref=1 bluetoothd[1842]: src/device.c:device_probe_drivers() Probe drivers for /org/bluez/1842/hci0/dev_00_17_D5_65_D0_3D bluetoothd[1842]: serial/manager.c:serial_probe() path /org/bluez/1842/hci0/dev_00_17_D5_65_D0_3D:
00001105-0000-1000-8000-00805f9b34fb
bluetoothd[1842]: serial/port.c:create_serial_device() Registered interface org.bluez.Serial on path /org/bluez/1842/hci0/dev_00_17_D5_65_D0_3D
bluetoothd[1842]: src/device.c:btd_device_unref() 0x9408b60: ref=1 Segmentation fault

Manuel Francisco Naranjo
Software Department Argentina
Wireless Cables Inc
www.aircable.net
cel: +5493412010019
skype: naranjomanuelfrancisco

Hi Manuel,

This looks like a different issue, at least it doesn't seems to crash in the same point, so I assume the patch does fix something but uncover another problem. But we have to find out where exactly is this other problem because btd_device_unref doesn't seems to be the place, can't you get any core dumps from the tests you did?

Luiz Augusto von Dentz
Computer Engineer

Luiz,

I agree it looks like it triggered another issue, I will try to get logs tomorrow.

Manuel

Luiz,

Here's the call trace, unfortunately I don't have bluetoothd debug messages, just this
+ 0 0x804e4ea (from 0x7e0dab) watch_func():
/home/manuel/bluez/gdbus/mainloop.c:94
+ 1 0x804ea3b (from 0x7140dd) dispatch_status():
/home/manuel/bluez/gdbus/mainloop.c:244
+ 2 0x804e49b (from 0x804ea7d) queue_dispatch():
/home/manuel/bluez/gdbus/mainloop.c:87
+ 0 0x804e436 (from 0x7aa53c) message_dispatch():
/home/manuel/bluez/gdbus/mainloop.c:73
+ 1 0x8050fa1 (from 0x716c8d) message_filter():
/home/manuel/bluez/gdbus/watch.c:408
+ 1 0x804f506 (from 0x723f13) generic_message():
/home/manuel/bluez/gdbus/object.c:236
+ 2 0x804f483 (from 0x804f549) find_interface():
/home/manuel/bluez/gdbus/object.c:219
+ 2 0x80a4d46 (from 0x804f5cb) adapter_start_discovery():
/home/manuel/bluez/src/adapter.c:1215
+ 3 0x80a354c (from 0x80a4da5) find_session():
/home/manuel/bluez/src/adapter.c:621
+ 3 0x80a4cce (from 0x80a4dfa) adapter_start_inquiry():
/home/manuel/bluez/src/adapter.c:1203
+ 4 0x80a2744 (from 0x80a4d0c) pending_remote_name_cancel():
/home/manuel/bluez/src/adapter.c:263
+ 5 0x80a208d (from 0x80a27aa) bacpy():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:132
+ 5 0x80a8b8e (from 0x80a27c3) adapter_search_found_devices():
/home/manuel/bluez/src/adapter.c:2667
+ 4 0x808831a (from 0x80a4d29) hciops_start_discovery():
/home/manuel/bluez/plugins/hciops.c:570
+ 3 0x80a2de5 (from 0x80a4e45) create_session():
/home/manuel/bluez/src/adapter.c:425
+ 4 0x80514c7 (from 0x80a2ea9) g_dbus_add_disconnect_watch():
/home/manuel/bluez/gdbus/watch.c:572
+ 5 0x80513cc (from 0x8051510) g_dbus_add_service_watch():
/home/manuel/bluez/gdbus/watch.c:544
+ 6 0x8050753 (from 0x8051430) filter_data_get():
/home/manuel/bluez/gdbus/watch.c:177
+ 7 0x80502a8 (from 0x80507a0) filter_data_find():
/home/manuel/bluez/gdbus/watch.c:69
+ 7 0x80502a8 (from 0x8050803) filter_data_find():
/home/manuel/bluez/gdbus/watch.c:69
+ 7 0x8050572 (from 0x80508a4) add_match():
/home/manuel/bluez/gdbus/watch.c:134
+ 8 0x8050402 (from 0x80505cc) format_rule():
/home/manuel/bluez/gdbus/watch.c:111
+ 8 0x804e8bd (from 0x729783) add_timeout():
/home/manuel/bluez/gdbus/mainloop.c:207
+ 8 0x804ea3b (from 0x7140dd) dispatch_status():
/home/manuel/bluez/gdbus/mainloop.c:244
+ 9 0x804e49b (from 0x804ea7d) queue_dispatch():
/home/manuel/bluez/gdbus/mainloop.c:87
+ 8 0x804e96c (from 0x7296ff) remove_timeout():
/home/manuel/bluez/gdbus/mainloop.c:227
+ 8 0x804e85f (from 0x729469) timeout_handler_free():
/home/manuel/bluez/gdbus/mainloop.c:195
+ 6 0x8050af5 (from 0x8051470) filter_data_add_callback():
/home/manuel/bluez/gdbus/watch.c:272

	+  4 0x8089ea8 (from 0x80a2ee4)      info(): /home/manuel/bluez/src/log.c:36
	+  4 0x80a2d65 (from 0x80a2eef)      session_ref():

/home/manuel/bluez/src/adapter.c:416
+ 5 0x8089f44 (from 0x80a2dc7) btd_debug():
/home/manuel/bluez/src/log.c:58
+ 0 0x808c945 (from 0x7e0dab) io_security_event():
/home/manuel/bluez/src/security.c:967
+ 1 0x808a32d (from 0x808caa9) hci_test_bit():
/home/manuel/bluez/./lib/bluetooth/hci_lib.h:167
+ 1 0x808bc97 (from 0x808cb24) cmd_complete():
/home/manuel/bluez/src/security.c:690
+ 2 0x808b951 (from 0x808bd70) start_inquiry():
/home/manuel/bluez/src/security.c:570
+ 3 0x80a1a5d (from 0x808b9a0) manager_find_adapter():
/home/manuel/bluez/src/manager.c:343
+ 4 0x80a1955 (from 0x7c947e) adapter_cmp():
/home/manuel/bluez/src/manager.c:319
+ 5 0x80a89ca (from 0x80a198d) adapter_get_address():
/home/manuel/bluez/src/adapter.c:2625
+ 6 0x80a208d (from 0x80a89f8) bacpy():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:132
+ 5 0x80a1000 (from 0x80a199f) bacmp():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:128
+ 3 0x80a8b15 (from 0x808b9ca) adapter_get_state():
/home/manuel/bluez/src/adapter.c:2657
+ 3 0x80a995b (from 0x808b9d8) adapter_has_discov_sessions():
/home/manuel/bluez/src/adapter.c:3021
+ 3 0x80a8a0d (from 0x808b9fc) adapter_set_state():
/home/manuel/bluez/src/adapter.c:2630
+ 4 0x80b0b44 (from 0x80a8aeb) emit_property_changed():
/home/manuel/bluez/src/dbus-common.c:266
+ 5 0x80b086d (from 0x80b0be0) append_variant():
/home/manuel/bluez/src/dbus-common.c:195
+ 5 0x805005d (from 0x80b0bf2) g_dbus_send_message():
/home/manuel/bluez/gdbus/object.c:615
+ 1 0x808a82f (from 0x808cdb4) check_pending_hci_req():
/home/manuel/bluez/src/security.c:186
+ 0 0x808c945 (from 0x7e0dab) io_security_event():
/home/manuel/bluez/src/security.c:967
+ 1 0x808a32d (from 0x808caa9) hci_test_bit():
/home/manuel/bluez/./lib/bluetooth/hci_lib.h:167
+ 1 0x808bc30 (from 0x808cafa) cmd_status():
/home/manuel/bluez/src/security.c:681
+ 1 0x808a82f (from 0x808cdb4) check_pending_hci_req():
/home/manuel/bluez/src/security.c:186
+ 0 0x808c945 (from 0x7e0dab) io_security_event():
/home/manuel/bluez/src/security.c:967
+ 1 0x808a32d (from 0x808caa9) hci_test_bit():
/home/manuel/bluez/./lib/bluetooth/hci_lib.h:167
+ 1 0x808c6e1 (from 0x808cd1b) disconn_complete():
/home/manuel/bluez/src/security.c:916
+ 2 0x80b2947 (from 0x808c734) hcid_dbus_disconn_complete():
/home/manuel/bluez/src/dbus-hci.c:779
+ 3 0x80a1a5d (from 0x80b29a3) manager_find_adapter():
/home/manuel/bluez/src/manager.c:343
+ 4 0x80a1955 (from 0x7c947e) adapter_cmp():
/home/manuel/bluez/src/manager.c:319
+ 5 0x80a89ca (from 0x80a198d) adapter_get_address():
/home/manuel/bluez/src/adapter.c:2625
+ 6 0x80a208d (from 0x80a89f8) bacpy():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:132
+ 5 0x80a1000 (from 0x80a199f) bacmp():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:128
+ 3 0x80a45fd (from 0x80b29d2) adapter_find_connection():
/home/manuel/bluez/src/adapter.c:1025
+ 4 0x80ac5b0 (from 0x80a4644) device_has_connection():
/home/manuel/bluez/src/device.c:934
+ 3 0x80a97f0 (from 0x80b2a2c) adapter_remove_connection():
/home/manuel/bluez/src/adapter.c:2992
+ 4 0x80ac472 (from 0x80a9864) device_remove_connection():
/home/manuel/bluez/src/device.c:908
+ 5 0x80ac306 (from 0x80ac58f) device_set_connected():
/home/manuel/bluez/src/device.c:875
+ 6 0x80b0b44 (from 0x80ac353) emit_property_changed():
/home/manuel/bluez/src/dbus-common.c:266
+ 7 0x80b086d (from 0x80b0be0) append_variant():
/home/manuel/bluez/src/dbus-common.c:195
+ 7 0x805005d (from 0x80b0bf2) g_dbus_send_message():
/home/manuel/bluez/gdbus/object.c:615
+ 4 0x80ae44a (from 0x80a9891) device_get_address():
/home/manuel/bluez/src/device.c:1654
+ 5 0x80aa3e0 (from 0x80ae475) bacpy():
/home/manuel/bluez/./lib/bluetooth/bluetooth.h:132
+ 4 0x808a77f (from 0x80a98a9) hci_req_queue_remove():
/home/manuel/bluez/src/security.c:169
+ 4 0x80afe26 (from 0x80a98b4) device_is_authenticating():
/home/manuel/bluez/src/device.c:2339
+ 4 0x80ae585 (from 0x80a98d6) device_is_temporary():
/home/manuel/bluez/src/device.c:1683
+ 1 0x808a82f (from 0x808cdb4) check_pending_hci_req():
/home/manuel/bluez/src/security.c:186
+ 0 0x8099459 (from 0x7e0dab) connect_watch():
/home/manuel/bluez/src/glib-helper.c:257
+ 1 0x80ae001 (from 0x809963a) browse_cb():
/home/manuel/bluez/src/device.c:1540

I think it keeps crashing the same way, when browse_cb gets called user_data points to non valid data.

Manuel