Problem with Simple.Connect

[Pablo Martí Gamboa <pmarti warp es>]

Hi all,

I'm getting a unreliable behavior with Simple.Connect, the first call will succeed, but further calls won't.

Going through the logs with Tambet, we have noticed that there is something weird going on with IPv6 code:

( http://pastebin.ca/1597233 )

Oct  6 10:26:43 lenovo NetworkManager: <info>  (/dev/ttyUSB0): device state change: 4 -> 5 (reason 0)

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 2 of 5 (Device Configure) successful.

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 2 of 5 (Device Configure) complete.

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 3 of 5 (IP Configure Start) started...

Oct  6 10:26:43 lenovo NetworkManager: <info>  (/dev/ttyUSB0): device state change: 5 -> 7 (reason 0)

Oct  6 10:26:43 lenovo NetworkManager: <info>  Starting pppd connection

Oct  6 10:26:43 lenovo NetworkManager: <debug> [1254817603.714520] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute /dev/ttyUSB0 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/3 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so

Oct  6 10:26:43 lenovo NetworkManager: <debug> [1254817603.726521] nm_ppp_manager_start(): ppp started with pid 3625

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...

Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation (/dev/ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.

Oct  6 10:26:51 lenovo wpa_supplicant[1228]: CTRL-EVENT-SCAN-RESULTS 

Oct  6 10:27:04 lenovo NetworkManager: <WARN>  pppd_timed_out(): Looks like pppd didn't initialize our dbus module

Oct  6 10:27:04 lenovo NetworkManager: <info>  (/dev/ttyUSB0): device state change: 7 -> 9 (reason 14)

Oct  6 10:27:04 lenovo NetworkManager: <info>  Marking connection 'Vodafone (Airtel) connection' invalid.

As you can see, it starts stage 4/5 IP6, then goes to 3/5 of IP. After that I get a pppd_timed_out because it times out. It seems there is something weird going related to IPv6.

Tambet recommended me to create a simple test case that, issues a Connect.Simple call and then starts pppd manually without the ipparam argument. This results in a better reliability ( 5 successful connections in a row). Attached you can find the script.

At this stage I'm quite lost, Tambet has mentioned that there was a "recent" ipv6 merge that could be related to it. Any hints / ideas about what to try?

Best regards,

--
Pablo Martí
http://www.linkedin.com/in/pmarti || http://www.warp.es
python -c "print '706d6172746940776172702e6573'.decode('hex')"

#!/usr/bin/env python

import os
import sys
import time

import dbus
from wader.common.consts import (WADER_SERVICE, WADER_OBJPATH, WADER_INTFACE,
                                 SPL_INTFACE, MDM_INTFACE)

def usage():
    print "*" * 62
    print "usage:"
    print './connect_simple.py [/org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0]'
    print "*" * 62

def main():
    try:
        udi = sys.argv[1:]
    except:
        udi = None

    # obtain wader service and get the first available device
    if not udi:
        obj = dbus.SystemBus().get_object(WADER_SERVICE, WADER_OBJPATH)
        udi = obj.EnumerateDevices(dbus_interface=WADER_INTFACE)[0]

    print "GETTING REFERENCE TO UDI", udi
    device = dbus.SystemBus().get_object(WADER_SERVICE, udi)

    # .Enable the device (no PIN auth checking)
    device.Enable(True, dbus_interface=MDM_INTFACE)

    settings = {
        'network_mode' : 1,
        'apn' : 'ac.vodafone.es',
        'number' : '*99#',
    }

    device.Connect(settings, dbus_interface=SPL_INTFACE)
    time.sleep(1)

    os.system("/usr/sbin/pppd nodetach lock nodefaultroute /dev/ttyUSB0 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so")
    time.sleep(40)

    device.Disconnect(dbus_interface=SPL_INTFACE)
    # now that we are done, issue an .Enable(False) to free resources
    device.Enable(False, dbus_interface=MDM_INTFACE)
    return 0


if __name__ == '__main__':
    sys.exit(main())