Re: Slow mobile broadband detection

[dave guandalino <guandalino gmail com>]

Hello,

> Debug logs would be helpful.

I attached them to this mail, hope this helps.

> files in the email, pastebins usually expire). Once you have them, Ctrl
> +C in each terminal will stop the debug processes, and then done you can
> go back to non-debug:
> $> sudo /etc/init.d/network-manager start

At this network-manager start the connection happens immediately.

TIA

$ sudo service network-manager stop
network-manager stop/waiting

$ sudo modem-manager --debug
$ sudo modem-manager --debug
modem-manager[1661]: <info>  [1308077419.036974] [main.c:167] main(): ModemManager (version 0.4) starting...
modem-manager[1661]: <warn>  [1308077419.038568] [main.c:98] create_dbus_proxy(): Could not acquire the org.freedesktop.ModemManager service as it is already taken. Return: 3
$

$ sudo NetworkManager --no-daemon --log-level=DEBUG
NetworkManager[1744]: <info> NetworkManager (version 0.8.3.998) is starting...
NetworkManager[1744]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
NetworkManager[1744]: <info> VPN: loaded org.freedesktop.NetworkManager.pptp
NetworkManager[1744]: <info> modem-manager is now available
NetworkManager[1744]: <info> monitoring kernel firmware directory '/lib/firmware'.
NetworkManager[1744]:    SCPlugin-Ifupdown: init!
NetworkManager[1744]:    SCPlugin-Ifupdown: update_system_hostname
NetworkManager[1744]:    SCPluginIfupdown: management mode: unmanaged
NetworkManager[1744]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:1c.0/0000:07:00.0/net/eth0, iface: eth0)
NetworkManager[1744]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:1c.0/0000:07:00.0/net/eth0, iface: eth0): no ifupdown configuration found.
NetworkManager[1744]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:1c.1/0000:0d:00.0/net/wlan0, iface: wlan0)
NetworkManager[1744]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:1c.1/0000:0d:00.0/net/wlan0, iface: wlan0): no ifupdown configuration found.
NetworkManager[1744]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/lo, iface: lo)
NetworkManager[1744]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/lo, iface: lo): no ifupdown configuration found.
NetworkManager[1744]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/vboxnet0, iface: vboxnet0)
NetworkManager[1744]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/vboxnet0, iface: vboxnet0): no ifupdown configuration found.
NetworkManager[1744]:    SCPlugin-Ifupdown: end _init.
NetworkManager[1744]: <info> Loaded plugin ifupdown: (C) 2008 Canonical Ltd.  To report bugs please use the NetworkManager mailing list.
NetworkManager[1744]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
NetworkManager[1744]:    Ifupdown: get unmanaged devices count: 0
NetworkManager[1744]:    SCPlugin-Ifupdown: (30527952) ... get_connections.
NetworkManager[1744]:    SCPlugin-Ifupdown: (30527952) ... get_connections (managed=false): return empty list.
NetworkManager[1744]:    keyfile: parsing MOBILE BROADBAND ... 
NetworkManager[1744]:    keyfile:     read connection 'MOBILE BROADBAND'
NetworkManager[1744]:    keyfile: parsing XXXXXXXXXX ... 
NetworkManager[1744]:    keyfile:     read connection 'XXXXXXXXXX'
NetworkManager[1744]:    keyfile: parsing YYYYYYYYYY ... 
NetworkManager[1744]:    keyfile:     read connection 'YYYYYYYYYY'
NetworkManager[1744]:    Ifupdown: get unmanaged devices count: 0
NetworkManager[1744]: <info> found WiFi radio killswitch rfkill0 (at /sys/devices/pci0000:00/0000:00:1c.1/0000:0d:00.0/ieee80211/phy0/rfkill0) (driver <unknown>)
NetworkManager[1744]: <info> WiFi enabled by radio killswitch; disabled by state file
NetworkManager[1744]: <info> WWAN enabled by radio killswitch; enabled by state file
NetworkManager[1744]: <info> WiMAX enabled by radio killswitch; enabled by state file
NetworkManager[1744]: <info> Networking is enabled by state file
NetworkManager[1744]: <debug> [1308077457.356034] [nm-device-ethernet.c:2273] supports_ethtool_carrier_detect(): ethtool is supported
NetworkManager[1744]: <debug> [1308077457.356084] [nm-device-ethernet.c:798] real_update_initial_hw_address(): (eth0): read initial MAC address 2C:27:D7:A5:05:C4
NetworkManager[1744]: <debug> [1308077457.356141] [nm-device-ethernet.c:428] constructor(): (eth0): kernel ifindex 2
NetworkManager[1744]: <info> (eth0): carrier is OFF
NetworkManager[1744]: <info> (eth0): new Ethernet device (driver: 'r8169' ifindex: 2)
NetworkManager[1744]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
NetworkManager[1744]: <info> (eth0): now managed
NetworkManager[1744]: <info> (eth0): device state change: 1 -> 2 (reason 2)
NetworkManager[1744]: <info> (eth0): bringing up device.
NetworkManager[1744]: <info> (eth0): preparing device.
NetworkManager[1744]: <info> (eth0): deactivating device (reason: 2).
NetworkManager[1744]: <debug> [1308077457.377016] [nm-device-ethernet.c:684] _set_hw_addr(): (eth0): no MAC address change needed
NetworkManager[1744]: <debug> [1308077457.377034] [nm-system.c:1362] flush_routes(): (eth0): flushing routes ifindex 2 family INET (2)
NetworkManager[1744]: <debug> [1308077457.377123] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.255.255.255/32
NetworkManager[1744]: <debug> [1308077457.377138] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/32
NetworkManager[1744]: <debug> [1308077457.377147] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.0.0.1/32
NetworkManager[1744]: <debug> [1308077457.377156] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/8
NetworkManager[1744]: <debug> [1308077457.377168] [nm-system.c:1277] dump_route():   route idx 1 family INET6 (10) addr 0:0:4100::/0
NetworkManager[1744]: <debug> [1308077457.377180] [nm-system.c:1277] dump_route():   route idx 1 family INET6 (10) addr ::1/128
NetworkManager[1744]: <debug> [1308077457.377192] [nm-system.c:1277] dump_route():   route idx 1 family INET6 (10) addr 0:0:1105::1882:24eb/0
NetworkManager[1744]: <debug> [1308077457.377276] [nm-system.c:222] sync_addresses(): (eth0): syncing addresses (family 2)
NetworkManager[1744]: <debug> [1308077457.377417] [nm-device.c:3792] nm_device_state_changed(): (eth0): device not yet available for transition to DISCONNECTED
NetworkManager[1744]: <info> Added default wired connection 'Auto eth0' for /sys/devices/pci0000:00/0000:00:1c.0/0000:07:00.0/net/eth0
NetworkManager[1744]: <debug> [1308077457.377780] [nm-sysconfig-settings.c:556] claim_connection(): failed to read connection timestamp for 'fd29630f-27f4-4df1-81d2-aa8fd0dcffa0': (3) Key file does not have key 'fd29630f-27f4-4df1-81d2-aa8fd0dcffa0'
NetworkManager[1744]: <debug> [1308077457.378277] [nm-device-wifi.c:3136] real_update_initial_hw_address(): (wlan0): read initial MAC address AC:81:12:4B:AA:52
NetworkManager[1744]: <debug> [1308077457.378329] [nm-device-wifi.c:587] constructor(): (wlan0): kernel ifindex 3
NetworkManager[1744]: <info> (wlan0): driver supports SSID scans (scan_capa 0x01).
NetworkManager[1744]: <debug> [1308077457.378488] [nm-manager.c:1885] manager_rfkill_update_one_type(): WiFi hw-enabled 1 sw-enabled 1
NetworkManager[1744]: <info> (wlan0): new 802.11 WiFi device (driver: 'brcm80211' ifindex: 3)
NetworkManager[1744]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
NetworkManager[1744]: <info> (wlan0): now managed
NetworkManager[1744]: <info> (wlan0): device state change: 1 -> 2 (reason 2)
NetworkManager[1744]: <info> (wlan0): bringing up device.
NetworkManager[1744]: <info> (wlan0): deactivating device (reason: 2).
NetworkManager[1744]: <debug> [1308077457.378668] [nm-device-wifi.c:1165] _set_hw_addr(): (wlan0): no MAC address change needed
NetworkManager[1744]: <debug> [1308077457.378681] [nm-system.c:1362] flush_routes(): (wlan0): flushing routes ifindex 3 family INET (2)
NetworkManager[1744]: <debug> [1308077457.378741] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.255.255.255/32
NetworkManager[1744]: <debug> [1308077457.378754] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/32
NetworkManager[1744]: <debug> [1308077457.378766] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.0.0.1/32
NetworkManager[1744]: <debug> [1308077457.378775] [nm-system.c:1277] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/8
NetworkManager[1744]: <debug> [1308077457.378787] [nm-system.c:1277] dump_route():   route idx 1 family INET6 (10) addr 0:0:a100::a882:24eb/0
NetworkManager[1744]: <debug> [1308077457.378798] [nm-system.c:1277] dump_route():   route idx 1 family INET6 (10) addr ::1/128
NetworkManager[1744]: <debug> [1308077457.378809] [nm-system.c:1277] dump_route():   route idx 1 family INET6 (10) addr 0:0:7103::1882:24eb/0
NetworkManager[1744]: <debug> [1308077457.378882] [nm-system.c:222] sync_addresses(): (wlan0): syncing addresses (family 2)
NetworkManager[1744]: <debug> [1308077457.378994] [nm-device-wifi.c:1331] real_is_available(): (wlan0): not available because not enabled
NetworkManager[1744]: <debug> [1308077457.379010] [nm-device.c:3792] nm_device_state_changed(): (wlan0): device not yet available for transition to DISCONNECTED
NetworkManager[1744]: <debug> [1308077457.379073] [nm-udev-manager.c:412] net_add(): ignoring interface with type 772
NetworkManager[1744]: <warn> /sys/devices/virtual/net/vboxnet0: couldn't determine device driver; ignoring...
/sbin/ifup: interface lo already configured
NetworkManager[1744]: <debug> [1308077457.380649] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 2 flags 0x1003
NetworkManager[1744]: <debug> [1308077457.380897] [nm-manager.c:1304] user_settings_authorized(): User connections permissions: net 1, con 1
NetworkManager[1744]: <debug> [1308077457.380929] [nm-manager.c:1346] user_proxy_auth_done(): Requesting user connections...
NetworkManager[1744]: <warn> bluez error getting default adapter: The name org.bluez was not provided by any .service files
NetworkManager[1744]: <debug> [1308077457.381413] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 1 flags 0x10049
NetworkManager[1744]: <debug> [1308077457.381435] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 2 flags 0x1003
NetworkManager[1744]: <debug> [1308077457.381452] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 3 flags 0x1002
NetworkManager[1744]: <debug> [1308077457.381466] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 4 flags 0x1002
NetworkManager[1744]: <warn> (ttyUSB2): failed to look up interface index
NetworkManager[1744]: <debug> [1308077593.563456] [NetworkManagerUtils.c:721] nm_utils_get_proc_sys_net_value(): (ttyUSB2): error reading /proc/sys/net/ipv6/conf/ttyUSB2/accept_ra: (4) Failed to open file '/proc/sys/net/ipv6/conf/ttyUSB2/accept_ra': No such file or directory
NetworkManager[1744]: <debug> [1308077593.563541] [nm-manager.c:1882] manager_rfkill_update_one_type(): WWAN hw-enabled 1 sw-enabled 1 daemon-enabled 0
NetworkManager[1744]: <info> (ttyUSB2): new GSM device (driver: 'option1' ifindex: -1)
NetworkManager[1744]: <info> (ttyUSB2): exported as /org/freedesktop/NetworkManager/Devices/2
NetworkManager[1744]: <info> (ttyUSB2): now managed
NetworkManager[1744]: <info> (ttyUSB2): device state change: 1 -> 2 (reason 2)
NetworkManager[1744]: <info> (ttyUSB2): deactivating device (reason: 2).
NetworkManager[1744]: <debug> [1308077593.607692] [nm-system.c:1349] flush_routes(): (ttyUSB2) failed to lookup interface index
NetworkManager[1744]: <debug> [1308077593.609843] [nm-device.c:3788] nm_device_state_changed(): (ttyUSB2): device is available, will transition to DISCONNECTED
NetworkManager[1744]: <debug> [1308077593.609960] [nm-manager.c:1882] manager_rfkill_update_one_type(): WWAN hw-enabled 1 sw-enabled 1 daemon-enabled 0
NetworkManager[1744]: <debug> [1308077593.610094] [nm-device.c:3682] unavailable_to_disconnected(): (ttyUSB2): running unavailable->disconnected transition
NetworkManager[1744]: <info> (ttyUSB2): device state change: 2 -> 3 (reason 0)
NetworkManager[1744]: <info> Activation (ttyUSB2) starting connection 'MOBILE BROADBAND'
NetworkManager[1744]: <info> (ttyUSB2): device state change: 3 -> 4 (reason 0)
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started...
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete.
NetworkManager[1744]: <info> WWAN now enabled by management service
NetworkManager[1744]: <debug> [1308077610.560736] [nm-manager.c:1882] manager_rfkill_update_one_type(): WWAN hw-enabled 1 sw-enabled 1 daemon-enabled 1
NetworkManager[1744]: <debug> [1308077610.560767] [nm-manager.c:1705] manager_update_radio_enabled(): (ttyUSB2): setting radio enabled
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) starting...
NetworkManager[1744]: <info> (ttyUSB2): device state change: 4 -> 5 (reason 0)
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) successful.
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) complete.
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[1744]: <info> (ttyUSB2): device state change: 5 -> 7 (reason 0)
NetworkManager[1744]: <info> starting PPP connection
NetworkManager[1744]: <debug> [1308077613.13298] [nm-ppp-manager.c:943] nm_ppp_manager_start(): command line: /usr/sbin/pppd nodetach lock nodefaultroute ttyUSB2 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/0 plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so
NetworkManager[1744]: <info> pppd started with pid 1866
NetworkManager[1744]: <debug> [1308077613.36979] [NetworkManagerUtils.c:721] nm_utils_get_proc_sys_net_value(): (ttyUSB2): error reading /proc/sys/net/ipv6/conf/ttyUSB2/accept_ra: (4) Failed to open file '/proc/sys/net/ipv6/conf/ttyUSB2/accept_ra': No such file or directory
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) complete.
Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
** Message: nm-ppp-plugin: (plugin_init): initializing
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
NetworkManager[1744]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Using interface ppp0
NetworkManager[1744]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
NetworkManager[1744]: <debug> [1308077613.314475] [nm-udev-manager.c:477] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'ppp0'
Connect: ppp0 <--> /dev/ttyUSB2
NetworkManager[1744]: <debug> [1308077613.314511] [nm-udev-manager.c:412] net_add(): ignoring interface with type 512
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
NetworkManager[1744]: <debug> [1308077613.314665] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 5 flags 0x1090
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
** Message: nm-ppp-plugin: (get_credentials): passwd-hook, requesting credentials...
** Message: nm-ppp-plugin: (get_credentials): got credentials from NetworkManager
CHAP authentication succeeded
CHAP authentication succeeded
** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Could not determine remote IP address: defaulting to XYZ.XYZ.XYZ.XYZ
NetworkManager[1744]: <debug> [1308077620.640838] [nm-netlink-monitor.c:117] link_msg_handler(): netlink link message: iface idx 5 flags 0x110D1
local  IP address XYZ.XYZ.XYZ.XYZ
remote IP address XYZ.XYZ.XYZ.XYZ
primary   DNS address XYZ.XYZ.XYZ.XYZ
secondary DNS address XYZ.XYZ.XYZ.XYZ
** Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
** Message: nm-ppp-plugin: (nm_ip_up): ip-up event
** Message: nm-ppp-plugin: (nm_ip_up): sending Ip4Config to NetworkManager...
NetworkManager[1744]: <info> PPP manager(IP Config Get) reply received.
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure Get) scheduled...
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure Get) started...
NetworkManager[1744]: <info> Scheduling stage 5
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager[1744]: <info> Done scheduling stage 5
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure Get) complete.
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 5 of 5 (IP Configure Commit) started...
NetworkManager[1744]: <debug> [1308077620.642197] [nm-system.c:222] sync_addresses(): (ppp0): syncing addresses (family 2)
NetworkManager[1744]: <info> (ttyUSB2): device state change: 7 -> 8 (reason 0)
NetworkManager[1744]: <info> Policy set 'MOBILE BROADBAND' (ppp0) as default for IPv4 routing and DNS.
NetworkManager[1744]: <info> Activation (ttyUSB2) successful, device activated.
NetworkManager[1744]: <info> Activation (ttyUSB2) Stage 5 of 5 (IP Configure Commit) complete.

ONLINE REFERENCE FOR THIS FILE: http://pastebin.ubuntu.com/625429/



Jun 12 22:06:14 tk usb_modeswitch: switching 19d2:2000 (ONDA,Incorporated: ONDA WCDMA Technologies MSM)

[cut]

Jun 12 22:06:42 tk modem-manager[853]: <info>  (ttyUSB0) opening serial port...
Jun 12 22:07:31 tk modem-manager[853]: <info>  (ttyUSB2) closing serial port...
Jun 12 22:07:31 tk modem-manager[853]: <info>  (ttyUSB2) serial port closed
Jun 12 22:07:31 tk modem-manager[853]: <info>  (ttyUSB1) closing serial port...
Jun 12 22:07:36 tk modem-manager[853]: <info>  (ttyUSB1) serial port closed
Jun 12 22:07:36 tk modem-manager[853]: <info>  (ttyUSB2) opening serial port...
Jun 12 22:07:36 tk modem-manager[853]: <info>  (ZTE): GSM modem /sys/devices/pci0000:00/0000:00:1c.3/0000:19:00.0/usb3/3-3 claimed port ttyUSB2
Jun 12 22:07:36 tk modem-manager[853]: <info>  (ZTE): GSM modem /sys/devices/pci0000:00/0000:00:1c.3/0000:19:00.0/usb3/3-3 claimed port ttyUSB1
Jun 12 22:07:39 tk modem-manager[853]: <info>  (ttyUSB2) closing serial port...
Jun 12 22:07:39 tk modem-manager[853]: <info>  (ttyUSB2) serial port closed
Jun 12 22:07:53 tk modem-manager[853]: <info>  (ttyUSB0) closing serial port...
Jun 12 22:07:58 tk modem-manager[853]: <info>  (ttyUSB0) serial port closed
Jun 12 22:07:58 tk modem-manager[853]: <info>  (ttyUSB0) opening serial port...
Jun 12 22:08:16 tk modem-manager[853]: <info>  (ttyUSB0) closing serial port...
Jun 12 22:08:21 tk modem-manager[853]: <info>  (ttyUSB0) serial port closed
Jun 12 22:08:21 tk modem-manager[853]: <info>  (ZTE): GSM modem /sys/devices/pci0000:00/0000:00:1c.3/0000:19:00.0/usb3/3-3 claimed port ttyUSB0
Jun 12 22:08:21 tk NetworkManager[844]: <warn> (ttyUSB2): failed to look up interface index
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): new GSM device (driver: 'option1' ifindex: -1)
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): exported as /org/freedesktop/NetworkManager/Devices/2
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): now managed
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 1 -> 2 (reason 2)
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): deactivating device (reason: 2).
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 2 -> 3 (reason 0)
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) starting connection 'XXXXXXXXXXXXXXX'
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 3 -> 4 (reason 0)
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled...
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started...
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete.

********* LINE 75

Jun 12 22:08:21 tk NetworkManager[844]: <warn> GSM modem enable failed: (32) SIM PIN required
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 4 -> 6 (reason 0)
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled...
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started...
Jun 12 22:08:21 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 6 -> 4 (reason 0)
Jun 12 22:08:21 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete.

^-- 6 lines above are repeated MANY times.

********* LINE 156000
 
Jun 12 22:08:42 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: unlock no longer required
Jun 12 22:08:42 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: # unlock retries is 0
Jun 12 22:08:42 tk NetworkManager[844]: <warn> GSM modem enable failed: (32) SIM PIN required
Jun 12 22:08:42 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 4 -> 6 (reason 0)
Jun 12 22:08:42 tk modem-manager[853]: <info>  (ttyUSB2) closing serial port...
Jun 12 22:08:42 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled...
Jun 12 22:08:42 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started...
Jun 12 22:08:42 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 6 -> 4 (reason 0)
Jun 12 22:08:42 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete.
Jun 12 22:08:42 tk modem-manager[853]: <info>  (ttyUSB2) serial port closed
Jun 12 22:08:42 tk modem-manager[853]: <info>  (ttyUSB2) opening serial port...
Jun 12 22:08:42 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabled -> enabling)
Jun 12 22:08:45 tk modem-manager[853]: <info>  (ttyUSB1) opening serial port...
Jun 12 22:09:01 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabling -> enabled)
Jun 12 22:09:01 tk NetworkManager[844]: <info> WWAN now enabled by management service
Jun 12 22:09:02 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabled -> registered)
Jun 12 22:09:04 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
Jun 12 22:09:04 tk modem-manager[853]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) scheduled...
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) starting...
Jun 12 22:09:04 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 4 -> 5 (reason 0)
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) successful.
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) scheduled.
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) complete.
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) started...
Jun 12 22:09:04 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 5 -> 7 (reason 0)
Jun 12 22:09:04 tk NetworkManager[844]: <info> starting PPP connection
Jun 12 22:09:04 tk NetworkManager[844]: <info> pppd started with pid 2405
Jun 12 22:09:04 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) complete.
Jun 12 22:09:04 tk pppd[2405]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Jun 12 22:09:04 tk pppd[2405]: pppd 2.4.5 started by root, uid 0
Jun 12 22:09:04 tk pppd[2405]: Using interface ppp0
Jun 12 22:09:04 tk NetworkManager[844]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Jun 12 22:09:04 tk pppd[2405]: Connect: ppp0 <--> /dev/ttyUSB2
Jun 12 22:09:04 tk NetworkManager[844]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
Jun 12 22:09:04 tk pppd[2405]: CHAP authentication succeeded
Jun 12 22:09:04 tk pppd[2405]: CHAP authentication succeeded
Jun 12 22:09:04 tk kernel: [  294.918251] PPP BSD Compression module registered
Jun 12 22:09:04 tk kernel: [  294.928756] PPP Deflate Compression module registered
Jun 12 22:09:11 tk pppd[2405]: Could not determine remote IP address: defaulting to XYZ.XYZ.XYZ.XYZ
Jun 12 22:09:11 tk pppd[2405]: local  IP address XYZ.XYZ.XYZ.XYZ
Jun 12 22:09:11 tk pppd[2405]: remote IP address XYZ.XYZ.XYZ.XYZ
Jun 12 22:09:11 tk pppd[2405]: primary   DNS address XYZ.XYZ.XYZ.XYZ
Jun 12 22:09:11 tk pppd[2405]: secondary DNS address XYZ.XYZ.XYZ.XYZ
Jun 12 22:09:11 tk NetworkManager[844]: <info> PPP manager(IP Config Get) reply received.
Jun 12 22:09:11 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure Get) scheduled...
Jun 12 22:09:11 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure Get) started...
Jun 12 22:09:11 tk NetworkManager[844]: <info> Scheduling stage 5
Jun 12 22:09:11 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 5 of 5 (IP Configure Commit) scheduled...
Jun 12 22:09:11 tk NetworkManager[844]: <info> Done scheduling stage 5
Jun 12 22:09:11 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure Get) complete.
Jun 12 22:09:11 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 5 of 5 (IP Configure Commit) started...
Jun 12 22:09:12 tk NetworkManager[844]: <info> (ttyUSB2): device state change: 7 -> 8 (reason 0)
Jun 12 22:09:12 tk NetworkManager[844]: <info> Policy set '3 Abbonamento' (ppp0) as default for IPv4 routing and DNS.
Jun 12 22:09:12 tk NetworkManager[844]: <info> Activation (ttyUSB2) successful, device activated.
Jun 12 22:09:12 tk NetworkManager[844]: <info> Activation (ttyUSB2) Stage 5 of 5 (IP Configure Commit) complete.
Jun 12 22:09:22 tk ntpdate[2504]: step time server XYZ.XYZ.XYZ.XYZ offset 0.580150