Bug 1054212

Summary: Pairing phone Control Center - Bluetooth device - phone fails when DUN service is selected
Product: Red Hat Enterprise Linux 7 Reporter: Martin <mholec>
Component: network-manager-appletAssignee: Dan Winship <danw>
Status: CLOSED CURRENTRELEASE QA Contact: Desktop QE <desktop-qa-list>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.0CC: danw, dcbw, jklimes, rkhan, thaller, tpelka
Target Milestone: rc   
Target Release: 7.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: network-manager-applet-0.9.9.0-15.git20140307.el7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-06-13 11:41:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
ModemManager log
none
fix (?)
none
screenshot
none
second ModemManager log none

Description Martin 2014-01-16 13:10:40 UTC 
Description of problem:
Pairing phone Control Center - Bluetooth device - phone fails when DUN service is selected

Version-Release number of selected component (if applicable):
control-center-3.8.6-5.el7.x86_64
bluez-4.101-12.el7.x86_64

How reproducible:
always

Steps to Reproduce:
1. Control Center - Bluetooth - "+" to add device.
2. Select device from list - Continue
3. Confirm PIN
4. Check "Access the Internet using your mobile phone (DUN)"

Actual results:
Error: timed out detecting phone details.

Expected results:
Pairing setup is complete.

Additional info:

Jan 16 13:55:12 martin-holec bluetoothd[1002]: bluetoothd[1002]: Discovery session 0x7fec88f05870 with :1.245 activated
Jan 16 13:55:12 martin-holec bluetoothd[1002]: Discovery session 0x7fec88f05870 with :1.245 activated
Jan 16 13:55:12 martin-holec gnome-session[3039]: Window manager warning: Buggy client sent a _NET_ACTIVE_WINDOW message with a timestamp of 0 for 0x2800003 (Bluetooth )
Jan 16 13:55:12 martin-holec gnome-session[3039]: Window manager warning: meta_window_activate called by a pager with a 0 timestamp; the pager needs to be fixed.
Jan 16 13:55:14 martin-holec bluetoothd[1002]: bluetoothd[1002]: Stopping discovery
Jan 16 13:55:14 martin-holec bluetoothd[1002]: Stopping discovery
Jan 16 13:55:21 martin-holec dbus-daemon[1040]: dbus[1040]: [system] Rejected send message, 4 matched rules; type="method_return", sender=":1.245" (uid=1000 pid=8719 comm="bluetooth-wizard ") interface="(unset)"
Jan 16 13:55:21 martin-holec dbus[1040]: [system] Rejected send message, 4 matched rules; type="method_return", sender=":1.245" (uid=1000 pid=8719 comm="bluetooth-wizard ") interface="(unset)" member="(unset)" e
Jan 16 13:55:22 martin-holec bluetoothd[1002]: bluetoothd[1002]: input-headset driver probe failed for device 5C:6B:32:13:5F:21
Jan 16 13:55:22 martin-holec bluetoothd[1002]: input-headset driver probe failed for device 5C:6B:32:13:5F:21
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 SyncMLClient
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 DialupNetworking
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXObjectPush
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXFileTransfer
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 AudioSource
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControlTarget
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControl
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 Headset_-_AG
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 HandsfreeAudioGateway
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 Phonebook_Access_-_PSE
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 SyncMLClient
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 DialupNetworking
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXObjectPush
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXFileTransfer
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 AudioSource
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControlTarget
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControl
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 Headset_-_AG
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 HandsfreeAudioGateway
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: has_config_widget 5C:6B:32:13:5F:21 Phonebook_Access_-_PSE
Jan 16 13:55:22 martin-holec gnome-session[3039]: ** Message: Default Bluetooth adapter is powered
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: dun_start: starting DUN device discovery...
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: Detecting phone configuration...
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: dun_start: calling Connect...
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: dun_start: waiting for Connect success...
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: dun_connect_cb: processing Connect reply
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: dun_connect_cb: new rfcomm interface '/dev/rfcomm0'
Jan 16 13:55:23 martin-holec gnome-session[3039]: ** Message: dun_connect_cb: finished
Comment 1 Bastien Nocera 2014-01-28 10:39:26 UTC 
This section of the UI is implemented as a plugin in nm-applet.
Comment 2 Dan Williams 2014-01-28 15:59:08 UTC 
Is ModemManager installed and running?
Comment 3 Dan Williams 2014-02-13 18:52:02 UTC 
Let me know if you have the information requsted in comment 2, otherwise we'll close this bug as insufficient data on 2014-02-28.  Thanks!
Comment 4 Martin 2014-03-05 15:27:57 UTC 
(In reply to Dan Williams from comment #2)
> Is ModemManager installed and running?

Yes, it is running.

To extend my log from #0, this is new:

** (bluetooth-wizard:6460): WARNING **: dun_timeout_cb: DUN error: timed out detecting phone details.
** Message: Error: timed out detecting phone details.
Comment 6 Dan Williams 2014-03-17 16:45:41 UTC 
(In reply to Martin Holec from comment #4)
> (In reply to Dan Williams from comment #2)
> > Is ModemManager installed and running?
> 
> Yes, it is running.
> 
> To extend my log from #0, this is new:
> 
> ** (bluetooth-wizard:6460): WARNING **: dun_timeout_cb: DUN error: timed out
> detecting phone details.
> ** Message: Error: timed out detecting phone details.

Ok, then it seems that MM may not be detecting the phone or may not be able to use it.  Could you:

systemctl stop ModemManager
/usr/sbin/ModemManager --debug

reproduce the problem, and attach the ModemManager log output so we can debug the phone <-> ModemManager communication.  Thanks!
Comment 7 Martin 2014-03-18 13:04:25 UTC 
Created attachment 875925 [details]
ModemManager log
Comment 8 Dan Winship 2014-03-20 12:40:11 UTC 
so, MM eventually reaches

ModemManager[10628]: <debug> [1395147687.476853] [mm-device.c:416] export_modem(): Exported modem '/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4' at path '/org/freedesktop/ModemManager1/Modem/0'

but nma-bt-device apparently never gets a DeviceAdded/object-added signal?

Oh...

Can you try https://brewweb.devel.redhat.com/taskinfo?taskID=7230494 ?
Comment 9 Dan Winship 2014-03-24 14:19:39 UTC 
Created attachment 878082 [details]
fix (?)

this is the (untested) proposed fix
Comment 10 Thomas Haller 2014-03-24 15:04:08 UTC 
(In reply to Dan Winship from comment #9)
> Created attachment 878082 [details]
> fix (?)
> 
> this is the (untested) proposed fix

This seems the right thing to do anyway. Though I would wait with the final changelog entry until it really fixes this bug.

ACK so far :)
Comment 11 Jirka Klimes 2014-03-24 16:44:16 UTC 
It seems right.
Comment 12 Dan Winship 2014-03-25 17:02:32 UTC 
old brew scratch-build timed out, new build at https://brewweb.devel.redhat.com/taskinfo?taskID=7249933
Comment 13 Martin 2014-03-25 17:30:02 UTC 
Created attachment 878597 [details]
screenshot

(In reply to Dan Winship from comment #12)
> old brew scratch-build timed out, new build at
> https://brewweb.devel.redhat.com/taskinfo?taskID=7249933

This build works when adding new phone in "Bluetooth New Device Setup", wizard "New Mobile Broadband Connection" is now opened and I can get successfully through it. After this I see in "Bluetooth New Device Setup" "Your phone is now ready for use!"

But in "Control Center Bluetooth" I have "Access the Internet using your mobile phone (DUN)" not checked. When I check it a get same error as before in "Bluetooth New Device Setup".
Comment 14 Dan Williams 2014-03-26 13:04:51 UTC 
(In reply to Martin Holec from comment #13)
> Created attachment 878597 [details]
> screenshot
> 
> (In reply to Dan Winship from comment #12)
> > old brew scratch-build timed out, new build at
> > https://brewweb.devel.redhat.com/taskinfo?taskID=7249933
> 
> This build works when adding new phone in "Bluetooth New Device Setup",
> wizard "New Mobile Broadband Connection" is now opened and I can get
> successfully through it. After this I see in "Bluetooth New Device Setup"
> "Your phone is now ready for use!"
> 
> But in "Control Center Bluetooth" I have "Access the Internet using your
> mobile phone (DUN)" not checked. When I check it a get same error as before
> in "Bluetooth New Device Setup".

Could you grab some logs from the control center for us?  Run "gnome-control-center" then go to the Bluetooth panel and try checking the button.  Then grab the terminal output from the control center, if any for us to look at.
Comment 15 Martin 2014-03-26 15:14:12 UTC 
Current situation:
1. I can go through "Bluetooth New Device Setup" and in "Control Center Bluetooth" I have "Access the Internet using your mobile phone (DUN)" checked.
2. When I uncheck and check "Access the Internet using your mobile phone (DUN)" I get "Error: Timed out detecting phone details."
3. When I remove phone from Devices and try "Bluetooth New Device Setup" again a get same error.
4. After I restart ModemManager.service both enable scenarios works, but just once.

using: 
nm-connection-editor-0.9.9.0-13.danw1.git20140307.el7.x86_64
ModemManager-1.1.0-6.git20130913.el7.x86_64
NetworkManager-0.9.9.1-7.git20140313.el7.x86_64

Note: I have tested this with phone supporting "PAN/NAP" Bluetooth profile and I can't reproduce it. Problem is only with "DUN" Bluetooth profile.

$ BLUETOOTH_DEBUG=1 gnome-control-center 
** Message: has_config_widget 5C:6B:32:13:5F:21 SyncMLClient
** Message: has_config_widget 5C:6B:32:13:5F:21 DialupNetworking
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXObjectPush
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXFileTransfer
** Message: has_config_widget 5C:6B:32:13:5F:21 AudioSource
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControlTarget
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControl
** Message: has_config_widget 5C:6B:32:13:5F:21 Headset_-_AG
** Message: has_config_widget 5C:6B:32:13:5F:21 HandsfreeAudioGateway
** Message: has_config_widget 5C:6B:32:13:5F:21 Phonebook_Access_-_PSE
** Message: has_config_widget 5C:6B:32:13:5F:21 SyncMLClient
** Message: has_config_widget 5C:6B:32:13:5F:21 DialupNetworking
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXObjectPush
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXFileTransfer
** Message: has_config_widget 5C:6B:32:13:5F:21 AudioSource
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControlTarget
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControl
** Message: has_config_widget 5C:6B:32:13:5F:21 Headset_-_AG
** Message: has_config_widget 5C:6B:32:13:5F:21 HandsfreeAudioGateway
** Message: has_config_widget 5C:6B:32:13:5F:21 Phonebook_Access_-_PSE
** Message: Default Bluetooth adapter is powered
** Message: dun_start: starting DUN device discovery...
** Message: Detecting phone configuration...
** Message: dun_start: calling Connect...
** Message: dun_start: waiting for Connect success...
** Message: dun_connect_cb: processing Connect reply
** Message: dun_connect_cb: new rfcomm interface '/dev/rfcomm0'
** Message: dun_connect_cb: finished
** Message: modem_object_added: (/org/freedesktop/ModemManager1/Modem/0) modem found
** Message: start_wizard: (/org/freedesktop/ModemManager1/Modem/0) starting the mobile wizard
** Message: wizard_done_cb: mobile wizard done
** Message: wizard_done_cb: adding new setting
** Message: wizard_done_cb: waiting for add connection result...
** Message: Your phone is now ready to use!
Device: Martix N9 (5C:6B:32:13:5F:21)
	D-Bus Path: /org/bluez/3335/hci0/dev_5C_6B_32_13_5F_21
	Type: Phone Icon: phone
	Paired: True Trusted: True Connected: True
	UUIDs: SyncMLClient DialupNetworking OBEXObjectPush OBEXFileTransfer AudioSource A/V_RemoteControlTarget A/V_RemoteControl Headset_-_AG HandsfreeAudioGateway Phonebook_Access_-_PSE 

** Message: has_config_widget 5C:6B:32:13:5F:21 SyncMLClient
** Message: has_config_widget 5C:6B:32:13:5F:21 DialupNetworking
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXObjectPush
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXFileTransfer
** Message: has_config_widget 5C:6B:32:13:5F:21 AudioSource
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControlTarget
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControl
** Message: has_config_widget 5C:6B:32:13:5F:21 Headset_-_AG
** Message: has_config_widget 5C:6B:32:13:5F:21 HandsfreeAudioGateway
** Message: has_config_widget 5C:6B:32:13:5F:21 Phonebook_Access_-_PSE
** Message: has_config_widget 5C:6B:32:13:5F:21 SyncMLClient
** Message: has_config_widget 5C:6B:32:13:5F:21 DialupNetworking
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXObjectPush
** Message: has_config_widget 5C:6B:32:13:5F:21 OBEXFileTransfer
** Message: has_config_widget 5C:6B:32:13:5F:21 AudioSource
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControlTarget
** Message: has_config_widget 5C:6B:32:13:5F:21 A/V_RemoteControl
** Message: has_config_widget 5C:6B:32:13:5F:21 Headset_-_AG
** Message: has_config_widget 5C:6B:32:13:5F:21 HandsfreeAudioGateway
** Message: has_config_widget 5C:6B:32:13:5F:21 Phonebook_Access_-_PSE
** Message: Default Bluetooth adapter is powered
Device: Martix N9 (5C:6B:32:13:5F:21)
	D-Bus Path: /org/bluez/3335/hci0/dev_5C_6B_32_13_5F_21
	Type: Phone Icon: phone
	Paired: True Trusted: True Connected: False
	UUIDs: SyncMLClient DialupNetworking OBEXObjectPush OBEXFileTransfer AudioSource A/V_RemoteControlTarget A/V_RemoteControl Headset_-_AG HandsfreeAudioGateway Phonebook_Access_-_PSE 

** Message: dun_start: starting DUN device discovery...
** Message: Detecting phone configuration...
** Message: dun_start: calling Connect...
** Message: dun_start: waiting for Connect success...
Device: Martix N9 (5C:6B:32:13:5F:21)
	D-Bus Path: /org/bluez/3335/hci0/dev_5C_6B_32_13_5F_21
	Type: Phone Icon: phone
	Paired: True Trusted: True Connected: True
	UUIDs: SyncMLClient DialupNetworking OBEXObjectPush OBEXFileTransfer AudioSource A/V_RemoteControlTarget A/V_RemoteControl Headset_-_AG HandsfreeAudioGateway Phonebook_Access_-_PSE 

** Message: dun_connect_cb: processing Connect reply
** Message: dun_connect_cb: new rfcomm interface '/dev/rfcomm0'
** Message: dun_connect_cb: finished

** (gnome-control-center:5440): WARNING **: dun_timeout_cb: DUN error: timed out detecting phone details.
** Message: Error: timed out detecting phone details.
Device: Martix N9 (5C:6B:32:13:5F:21)
	D-Bus Path: /org/bluez/3335/hci0/dev_5C_6B_32_13_5F_21
	Type: Phone Icon: phone
	Paired: True Trusted: True Connected: False
	UUIDs: SyncMLClient DialupNetworking OBEXObjectPush OBEXFileTransfer AudioSource A/V_RemoteControlTarget A/V_RemoteControl Headset_-_AG HandsfreeAudioGateway Phonebook_Access_-_PSE 

** Message: widget_info_destroy: NM Bluetooth widget info being destroyed
Comment 16 Martin 2014-03-26 15:17:09 UTC 
Created attachment 879038 [details]
second ModemManager log
Comment 17 Martin 2014-03-26 16:55:31 UTC 
I got random crash during testing see bug 1081120.
Comment 18 Dan Winship 2014-03-26 18:11:29 UTC 
ok, possible fix at danw/btfix (in network-manager-applet), test build at https://brewweb.devel.redhat.com/taskinfo?taskID=7258951.
Comment 19 Dan Williams 2014-03-26 20:36:29 UTC 
I think 'modems' to be freed in dun_connect_cb() since g_dbus_object_manager_get_objects() returns "A list of GDBusObject objects. The returned list should be freed with g_list_free() after each element has been freed with g_object_unref(). [transfer full][element-type GDBusObject]".

Other than that, code looks good.
Comment 20 Jirka Klimes 2014-03-27 10:59:02 UTC 
Except the 'modems' leak it looks good to me.
Comment 21 Martin 2014-03-27 13:29:23 UTC 
(In reply to Dan Winship from comment #18)
> ok, possible fix at danw/btfix (in network-manager-applet), test build at
> https://brewweb.devel.redhat.com/taskinfo?taskID=7258951.

This build works for me.
Comment 23 Ludek Smid 2014-06-13 11:41:37 UTC 
This request was resolved in Red Hat Enterprise Linux 7.0.

Contact your manager or support representative in case you have further questions about the request.