dial up connection establishes and disconnects right away

[Borut Mrak]

I tried connecting over bluetooth through my Nokia E71.

The connection was established, pppd was run and connected successfully, got the IP address and right after that the connection was ended without a byte transferred either way.

I added the "debug" option to /etc/ppp/options, but got nothing useful:

Oct 25 18:48:03 kink modem-manager[1026]: <info> (rfcomm0) opening serial port...
Oct 25 18:48:03 kink kernel: [80648.307860] Bluetooth: TIOCGSERIAL is not supported
Oct 25 18:48:05 kink modem-manager[1026]: <info> (rfcomm0) closing serial port...
Oct 25 18:48:05 kink modem-manager[1026]: <info> (rfcomm0) serial port closed
Oct 25 18:48:05 kink modem-manager[1026]: <info> (Generic): GSM modem /sys/devices/pci0000:00/0000:00:1d.3/usb5/5-1 claimed port rfcomm0
Oct 25 18:48:05 kink modem-manager[1026]: <info> (rfcomm0) opening serial port...
Oct 25 18:48:05 kink kernel: [80650.608550] Bluetooth: TIOCGSERIAL is not supported
Oct 25 18:48:06 kink NetworkManager[1087]: <info> ignoring modem 'rfcomm0' (no associated Bluetooth device)
Oct 25 18:48:06 kink modem-manager[1026]: <info> (rfcomm0) closing serial port...
Oct 25 18:48:06 kink modem-manager[1026]: <info> (rfcomm0) serial port closed
Oct 25 18:48:08 kink dbus[866]: [system] Activating service name='org.blueman.Mechanism' (using servicehelper)
Oct 25 18:48:09 kink blueman-mechanism: Starting blueman-mechanism
Oct 25 18:48:09 kink dbus[866]: [system] Successfully activated service 'org.blueman.Mechanism'
Oct 25 18:48:09 kink blueman-mechanism: loading Ppp
Oct 25 18:48:09 kink blueman-mechanism: loading RfKill
Oct 25 18:48:09 kink blueman-mechanism: loading Network
Oct 25 18:48:09 kink blueman-mechanism: loading Config
Oct 25 18:48:09 kink blueman-mechanism: --> ATZ E0 V1 X4 &C1 +FCLASS=0
Oct 25 18:48:09 kink blueman-mechanism: <-- ['OK']
Oct 25 18:48:09 kink blueman-mechanism: --> ATE0
Oct 25 18:48:09 kink blueman-mechanism: <-- ['ATE0', 'OK']
Oct 25 18:48:09 kink blueman-mechanism: --> AT+GCAP
Oct 25 18:48:09 kink blueman-mechanism: <-- ['+GCAP: +CGSM,+DS,+W', 'OK']
Oct 25 18:48:09 kink blueman-mechanism: --> AT+CGDCONT=1,"IP","internet.simobil.si"
Oct 25 18:48:09 kink blueman-mechanism: <-- ['OK']
Oct 25 18:48:09 kink blueman-mechanism: --> ATD*99#
Oct 25 18:48:11 kink blueman-mechanism: <-- ['CONNECT']
Oct 25 18:48:11 kink blueman-mechanism: Starting pppd
Oct 25 18:48:11 kink pppd[12805]: pppd 2.4.5 started by root, uid 0
Oct 25 18:48:11 kink pppd[12805]: using channel 15
Oct 25 18:48:11 kink blueman-mechanism: using channel 15
Oct 25 18:48:11 kink pppd[12805]: Using interface ppp0
Oct 25 18:48:11 kink NetworkManager[1087]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Oct 25 18:48:11 kink NetworkManager[1087]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
Oct 25 18:48:11 kink NetworkManager[1087]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
Oct 25 18:48:11 kink pppd[12805]: Connect: ppp0 <--> /dev/rfcomm0
Oct 25 18:48:11 kink pppd[12805]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x5b20f6d2> <pcomp> <accomp>]
Oct 25 18:48:11 kink blueman-mechanism: Using interface ppp0
Oct 25 18:48:11 kink pppd[12805]: rcvd [LCP ConfRej id=0x1 <magic 0x5b20f6d2> <pcomp> <accomp>]
Oct 25 18:48:11 kink pppd[12805]: sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
Oct 25 18:48:11 kink blueman-mechanism: Connect: ppp0 <--> /dev/rfcomm0
Oct 25 18:48:11 kink blueman-mechanism: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x5b20f6d2> <pcomp> <accomp>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [LCP ConfRej id=0x1 <magic 0x5b20f6d2> <pcomp> <accomp>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0>]
Oct 25 18:48:11 kink blueman-mechanism: sent [LCP ConfReq id=0x2 <asyncmap 0x0>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [LCP ConfReq id=0x0 <auth pap> <mru 1500> <asyncmap 0xa0000>]
Oct 25 18:48:11 kink pppd[12805]: sent [LCP ConfAck id=0x0 <auth pap> <mru 1500> <asyncmap 0xa0000>]
Oct 25 18:48:11 kink pppd[12805]: sent [LCP EchoReq id=0x0 magic=0x0]
Oct 25 18:48:11 kink pppd[12805]: sent [PAP AuthReq id=0x1 user="kink" password=<hidden>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [LCP ConfReq id=0x0 <auth pap> <mru 1500> <asyncmap 0xa0000>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [LCP EchoRep id=0x0 magic=0x0]
Oct 25 18:48:11 kink blueman-mechanism: sent [LCP ConfAck id=0x0 <auth pap> <mru 1500> <asyncmap 0xa0000>]
Oct 25 18:48:11 kink blueman-mechanism: sent [LCP EchoReq id=0x0 magic=0x0]
Oct 25 18:48:11 kink blueman-mechanism: sent [PAP AuthReq id=0x1 user="kink" password=<hidden>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [PAP AuthAck id=0x1 ""]
Oct 25 18:48:11 kink pppd[12805]: PAP authentication succeeded
Oct 25 18:48:11 kink pppd[12805]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Oct 25 18:48:11 kink pppd[12805]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [IPCP ConfReq id=0x0 <addr 10.6.6.6>]
Oct 25 18:48:11 kink pppd[12805]: sent [IPCP ConfAck id=0x0 <addr 10.6.6.6>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [LCP EchoRep id=0x0 magic=0x0]
Oct 25 18:48:11 kink pppd[12805]: rcvd [LCP ProtRej id=0x0 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Oct 25 18:48:11 kink pppd[12805]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Oct 25 18:48:11 kink blueman-mechanism: rcvd [PAP AuthAck id=0x1 ""]
Oct 25 18:48:11 kink blueman-mechanism: PAP authentication succeeded
Oct 25 18:48:11 kink blueman-mechanism: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Oct 25 18:48:11 kink blueman-mechanism: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [IPCP ConfReq id=0x0 <addr 10.6.6.6>]
Oct 25 18:48:11 kink blueman-mechanism: sent [IPCP ConfAck id=0x0 <addr 10.6.6.6>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [LCP ProtRej id=0x0 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Oct 25 18:48:11 kink pppd[12805]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Oct 25 18:48:11 kink pppd[12805]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Oct 25 18:48:11 kink blueman-mechanism: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Oct 25 18:48:11 kink blueman-mechanism: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [IPCP ConfNak id=0x2 <addr 46.122.xxx.xxx> <ms-dns1 80.95.224.44> <ms-dns2 80.95.224.45>]
Oct 25 18:48:11 kink pppd[12805]: sent [IPCP ConfReq id=0x3 <addr 46.122.xxx.xxx> <ms-dns1 80.95.224.44> <ms-dns2 80.95.224.45>]
Oct 25 18:48:11 kink blueman-mechanism: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [IPCP ConfNak id=0x2 <addr 46.122.xxx.xxx> <ms-dns1 80.95.224.44> <ms-dns2 80.95.224.45>]
Oct 25 18:48:11 kink pppd[12805]: rcvd [IPCP ConfAck id=0x3 <addr 46.122.xxx.xxx> <ms-dns1 80.95.224.44> <ms-dns2 80.95.224.45>]
Oct 25 18:48:11 kink blueman-mechanism: sent [IPCP ConfReq id=0x3 <addr 46.122.xxx.xxx> <ms-dns1 80.95.224.44> <ms-dns2 80.95.224.45>]
Oct 25 18:48:11 kink blueman-mechanism: rcvd [IPCP ConfAck id=0x3 <addr 46.122.xxx.xxx> <ms-dns1 80.95.224.44> <ms-dns2 80.95.224.45>]
Oct 25 18:48:11 kink pppd[12805]: local IP address 46.122.xxx.xxx
Oct 25 18:48:11 kink blueman-mechanism: local IP address 46.122.xxx.xxx
Oct 25 18:48:11 kink pppd[12805]: remote IP address 10.6.6.6
Oct 25 18:48:11 kink blueman-mechanism: remote IP address 10.6.6.6
Oct 25 18:48:11 kink pppd[12805]: primary DNS address 80.95.224.44
Oct 25 18:48:11 kink blueman-mechanism: primary DNS address 80.95.224.44
Oct 25 18:48:11 kink pppd[12805]: secondary DNS address 80.95.224.45
Oct 25 18:48:11 kink blueman-mechanism: secondary DNS address 80.95.224.45
Oct 25 18:48:11 kink pppd[12808]: Script /etc/ppp/ip-up started (pid 12809)
Oct 25 18:48:11 kink pppd[12808]: Hangup (SIGHUP)
Oct 25 18:48:11 kink pppd[12808]: Modem hangup
Oct 25 18:48:11 kink pppd[12808]: Connect time 0.0 minutes.
Oct 25 18:48:11 kink pppd[12808]: Sent 0 bytes, received 0 bytes.
Oct 25 18:48:11 kink pppd[12808]: Connection terminated.
Oct 25 18:48:11 kink avahi-daemon[959]: Withdrawing workstation service for ppp0.
Oct 25 18:48:12 kink NetworkManager[1087]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Oct 25 18:48:12 kink pppd[12808]: Script /etc/ppp/ip-up finished (pid 12809), status = 0x0
Oct 25 18:48:12 kink pppd[12808]: Script /etc/ppp/ip-down started (pid 12850)
Oct 25 18:48:12 kink pppd[12808]: Waiting for 1 child processes...
Oct 25 18:48:12 kink pppd[12808]: script /etc/ppp/ip-down, pid 12850
Oct 25 18:48:12 kink blueman-mechanism: pppd exited with status 0
Oct 25 18:48:12 kink pppd[12808]: Script /etc/ppp/ip-down finished (pid 12850), status = 0x0
Oct 25 18:48:12 kink pppd[12808]: Exit.
Oct 25 18:48:42 kink blueman-mechanism: Exiting
Oct 25 18:49:09 kink modem-manager[1026]: <info> (tty/rfcomm0): released by modem /sys/devices/pci0000:00/0000:00:1d.3/usb5/5-1

I will try using the SIM card in a dedicated modem and report if it works with Network Manager without bluetooth.
Please notify me if there's anything else I could do. I think I could try setting up the bluetooth connection manually and running pppd on that.

ProblemType: Bug
DistroRelease: Ubuntu 12.10
Package: blueman 1.23-0ubuntu3
ProcVersionSignature: Ubuntu 3.5.0-17.28-generic 3.5.5
Uname: Linux 3.5.0-17-generic x86_64
NonfreeKernelModules: wl
ApportVersion: 2.6.1-0ubuntu3
Architecture: amd64
Date: Thu Oct 25 18:56:37 2012
SourcePackage: blueman
UpgradeStatus: Upgraded to quantal on 2012-09-11 (43 days ago)

[Borut Mrak (b9bit)]

Yeah, works if there's no bluetooth involved. I've put the SIM in the computer's built-in modem. (I changed plans recently and don't have a second SIM for data anymore, that's why I'm trying to use bluetooth now).

root@kink:/etc# tail -f /var/log/syslog
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) starting connection 'Vodafone / Simobil Default'
Oct 25 19:18:32 kink NetworkManager[1087]: <info> (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> (ttyUSB0): device state change: prepare -> need-auth (reason 'none') [40 60 0]
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> (ttyUSB0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Oct 25 19:18:32 kink modem-manager[1026]: <info> (ttyUSB0) opening serial port...
Oct 25 19:18:32 kink modem-manager[1026]: <warn> (ttyUSB0): port attributes not fully set
Oct 25 19:18:32 kink modem-manager[1026]: <info> Modem /org/freedesktop/ModemManager/Modems/10: state changed (registered -> connecting)
Oct 25 19:18:32 kink modem-manager[1026]: <info> Modem /org/freedesktop/ModemManager/Modems/10: state changed (connecting -> connected)
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> (ttyUSB0): device state change: prepare -> config (reason 'none') [40 50 0]
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> (ttyUSB0): device state change: config -> ip-config (reason 'none') [50 70 0]
Oct 25 19:18:32 kink NetworkManager[1087]: <info> starting PPP connection
Oct 25 19:18:32 kink NetworkManager[1087]: <info> pppd started with pid 15846
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Oct 25 19:18:32 kink NetworkManager[1087]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Confi...

[Borut Mrak (b9bit)]

I tried changed Local Services -> Network -> DUN Support from Blueman to Network Manager. After connecting to the phone pppd is not run automatically anymore, but the phone also doesn't show up in NM (edit connections -> mobile broadband -> new only shows the built-in modem and an "Any device" option).

However, now I have a working rfcomm0 device. I run pppconfig, created a configuration, used /etc/chatscripts/gprs to talk to the phone and I can establish a connection.

There must be something about the way blueman calls pppd, I'm downloading the source to have a look now.

[Borut Mrak (b9bit)]

Now I noticed that I can actually create a connection in NM via System Settings -> Bluetooth. I simply select the phone and check "Access the internet using your mobile phone (DUN)". That was when I uninstalled blueman to, you know, see what happens :)

It might just be me (the last time I used bluetooth for DUN there was no network manager yet :), but I totally missed (or better, misread) the first paragraph of http://help.ubuntu.com/community/BluetoothDialup. That page definitely needs a cleanup.

This bug is of no great significance, but I wouldn't just close it, the functionality in blueman is still not working. To reiterate:

right click on device, serial ports, DUN connects to the phone, starts pppd and connects, but disconnects the moment the connection is established.
Setting Local Services -> Network -> DUN support to "Network Manager" does not make device available in NM, but does create a DUN connection (rfcomm0 device) that can be used by manually configuring pppd.

The only way to use the connection via GUI is to use the system bluetooth settings, not blueman.