Re: problems with 3g based connections

[van Schelve <public van-schelve de>]

Am Donnerstag, den 22.07.2010, 16:29 +0200 schrieb Dan Williams
<dcbw redhat com>:
> On Fri, 2010-07-16 at 12:16 +0200, van Schelve wrote:
>> Am Donnerstag, den 15.07.2010, 02:00 +0200 schrieb Dan Williams
>> <dcbw redhat com>:
>> > On Mon, 2010-07-05 at 08:42 +0200, van Schelve wrote:
>> >> >> Hi,
>> >> >>
>> >> >> some days ago I have reported a curious issue with modem-manager.
>> >> >> My main Problem is that I'm sometimes not able to dialup a modem
>> based
>> >> 3g
>> >> >> connection. The connection is not listed in nm-applet in this case
>> and
>> >> in
>> >> >> syslog I have entries like this one:
>> >> >>
>> >> >> ...
>> >> >> May 21 10:055:28 nc0631 modem-manager: (tty/ttyUSB0): outstanding
>> >> support
>> >> >> task prevents export of
>> /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
>> >> >> ...
>> >> >
>> >> > This means that some ports of the modem are still being detected and
>> >> > probed.  The modem cannot be used until all ports have completed
>> >> > detection.
>> >> >
>> >> >> @Dan, you asked me to bring more debug but I'm not able to reproduce
>> >> this
>> >> >> issue while manually starting nm / mm in debug mode.
>> >> >> Therefore: is it possible to run network-manager / modem-manager per
>> >> >> default in debug mode while starting over upstart?
>> >> >
>> >> > Possibly, but the debug output doesn't go to syslog, so unless it
>> gets
>> >> > stored somewhere by upstart it'll get lost.
>> >>
>> >> We were able to capture the debug output. Without debug we run 6 of 10
>> >> times into
>> >> this problem. Running mm in debug mode we were able to reproduce it 3
>> of
>> >> 10 times.
>> >>
>> >> http://pastebin.com/RS5vDxwJ
>> >> http://pastebin.com/FmZbkJnc
>> >> http://pastebin.com/97GPPbZW
>> >
>> > This is good stuff; near the end of the log entries you'll see:
>> >
>> > ** (modem-manager:1054): DEBUG: <1278077341.1209> (ttyUSB1): --> 00 78
>> f0
>> > 7e
>> > ** (modem-manager:1054): DEBUG: <1278077342.610807> (ttyUSB1): <-- 7e 00
>> > 0a 6b 24 00 00 07 00 00 00 00 00 00 00 7e
>> > ** (modem-manager:1054): DEBUG: <1278077349.610774> (ttyUSB1): <-- 7e 00
>> > 0a 6b 25 00 00 07 00 00 00 00 00 00 00 7e
>> > ** (modem-manager:1054): DEBUG: <1278077356.610695> (ttyUSB1): <-- 7e 00
>> > 0a 6b 26 00 00 07 00 00 00 00 00 00 00 7e
>> > ** (modem-manager:1054): DEBUG: <1278077363.610729> (ttyUSB1): <-- 7e 00
>> > 0a 6b 27 00 00 07 00 00 00 00 00 00 00 7e
>> > ** (modem-manager:1054): DEBUG: <1278077370.610737> (ttyUSB1): <-- 7e 00
>> > 0a 6b 28 00 00 07 00 00 00 00 00 00 00 7e
>> > ** (modem-manager:1054): DEBUG: <1278077377.606758> (ttyUSB1): <-- 7e 00
>> > 0a 6b 29 00 00 07 00 00 00 00 00 00 00 7e
>> >
>> > so ttyUSB1 is a Sierra CnS port (their "Control and Status" protocol)
>> > and MM isn't correctly failing out the QCDM probe.  What modem is this
>> > again?

Manufacturer: Sierra Wireless, Inc.
Model: MC8775
Revision: H1_1_8_3MCAP C:/WS/FW/H1_1_8_3MCAP/MSM6280/SRC 2007/03/08
18:17:59
IMEI: 352678013570525
IMEI SV: 6
FSN: D280428046710
3GPP Release 5
+GCAP: +CGSM,+DS,+ES


>> >
>> Dan, you're right. It is the CnS port of the Sierra Wireless MC8775.
>> And I think we found the reason for the problem. In addition to all the
>> networkmanager components we have a special application, called wsm, that
>> displays several informations from the modem like signal strenth, cell
>> information
>> active band, firmware version, hardware version.

I tested with a 0.4 version of modem-manager but we are still having
the issue.
For ttyUSB1 I can follow you. But why do we see this for ttyUSB0 in the
logs as
well?

I have attached the logs to this mail. Hope it's OK.

>>
>> These information are taken via CnS. We have disabled this tool and did
>> some further
>> tests with the result that in 50 / 50 tries everything works fine.
>>
>> So we decided to remove the wsm tool from users autostart and hope that we
>> will get
>> the cell information in the future direct from nm-applet.
>>
>> But if you are intereted in our tool, I can send it to you via pm. It's
>> GPL code.
> 
> Yes, I'm quite interested.  I have CnS documentation for CDMA devices
> already, but havne't gotten around to implementing it quite yet.  But
> I'd love to work on it in the near future.  The idea was to create a
> 'libsierracns' like I already wrote 'libqcdm' and integrate that into
> ModemManager and the Sierra plugin.
> 

I have written a pm to you some times ago. Did you got it?

> Dan

NetworkManager[5233]: <info> NetworkManager (version 0.8.0.997) is starting...
NetworkManager[5233]: <info> modem-manager is now available
NetworkManager[5233]:    SCPlugin-Ifupdown: init!
NetworkManager[5233]:    SCPlugin-Ifupdown: update_system_hostname
NetworkManager[5233]:    SCPluginIfupdown: management mode: unmanaged
NetworkManager[5233]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:19.0/net/eth0, iface: eth0)
NetworkManager[5233]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:19.0/net/eth0, iface: eth0): no ifupdown configuration found.
NetworkManager[5233]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/lo, iface: lo)
NetworkManager[5233]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/lo, iface: lo): no ifupdown configuration found.
NetworkManager[5233]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/pan0, iface: pan0)
NetworkManager[5233]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/pan0, iface: pan0): no ifupdown configuration found.
NetworkManager[5233]:    SCPlugin-Ifupdown: end _init.
NetworkManager[5233]: <info> Loaded plugin ifupdown: (C) 2008 Canonical Ltd.  To report bugs please use the NetworkManager mailing list.
NetworkManager[5233]: <info> Loaded plugin keyfile: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
NetworkManager[5233]:    Ifupdown: get unmanaged devices count: 0
NetworkManager[5233]:    SCPlugin-Ifupdown: (138702624) ... get_connections.
NetworkManager[5233]:    SCPlugin-Ifupdown: (138702624) ... get_connections (managed=false): return empty list.
NetworkManager[5233]:    Ifupdown: get unmanaged devices count: 0
NetworkManager[5233]: <info> found WWan radio killswitch rfkill2 (at /sys/devices/platform/thinkpad_acpi/rfkill/rfkill2) (driver thinkpad_acpi)
NetworkManager[5233]: <info> WiFi enabled by radio killswitch; enabled by state file
NetworkManager[5233]: <info> WWAN enabled by radio killswitch; enabled by state file
NetworkManager[5233]: <info> WiMAX enabled by radio killswitch; enabled by state file
NetworkManager[5233]: <info> Networking is enabled by state file
NetworkManager[5233]: <info> (eth0): carrier is OFF
NetworkManager[5233]: <info> (eth0): new Ethernet device (driver: 'e1000e' ifindex: 2)
NetworkManager[5233]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
NetworkManager[5233]: <info> (eth0): now managed
NetworkManager[5233]: <info> (eth0): device state change: 1 -> 2 (reason 2)
NetworkManager[5233]: <info> (eth0): bringing up device.
NetworkManager[5233]: <info> (eth0): preparing device.
NetworkManager[5233]: <info> (eth0): deactivating device (reason: 2).
NetworkManager[5233]: <info> Added default wired connection 'Auto eth0' for /sys/devices/pci0000:00/0000:00:19.0/net/eth0
NetworkManager[5233]: <warn> /sys/devices/virtual/net/pan0: couldn't determine device driver; ignoring...
/sbin/ifup: interface lo already configured
NetworkManager[5233]: <warn> (ttyUSB0): failed to look up interface index
NetworkManager[5233]: <info> (ttyUSB0): new GSM device (driver: 'sierra' ifindex: -1)
NetworkManager[5233]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/1
NetworkManager[5233]: <info> (ttyUSB0): now managed
NetworkManager[5233]: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
NetworkManager[5233]: <info> (ttyUSB0): deactivating device (reason: 2).
NetworkManager[5233]: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)
NetworkManager[5233]: <info> (ttyUSB0): now unmanaged
NetworkManager[5233]: <info> (ttyUSB0): device state change: 3 -> 1 (reason 36)
NetworkManager[5233]: <info> (ttyUSB0): cleaning up...
NetworkManager[5233]: <info> (ttyUSB0): taking down device.
NetworkManager[5233]: <info> the modem manager disappeared
NetworkManager[5233]: <info> trying to start the modem manager...
NetworkManager[5233]: <info> modem-manager is now available
NetworkManager[5233]: <warn> (ttyUSB0): failed to look up interface index
NetworkManager[5233]: <info> (ttyUSB0): new GSM device (driver: 'sierra' ifindex: -1)
NetworkManager[5233]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/2
NetworkManager[5233]: <info> (ttyUSB0): now managed
NetworkManager[5233]: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
NetworkManager[5233]: <info> (ttyUSB0): deactivating device (reason: 2).
NetworkManager[5233]: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)
NetworkManager[5233]: <info> (eth0): carrier now ON (device state 2)
NetworkManager[5233]: <info> (eth0): device state change: 2 -> 3 (reason 40)
NetworkManager[5233]: <info> Activation (eth0) starting connection 'Auto eth0'
NetworkManager[5233]: <info> (eth0): device state change: 3 -> 4 (reason 0)
NetworkManager[5233]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager[5233]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
NetworkManager[5233]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager[5233]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager[5233]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
NetworkManager[5233]: <info> (eth0): device state change: 4 -> 5 (reason 0)
NetworkManager[5233]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful.
NetworkManager[5233]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[5233]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
NetworkManager[5233]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[5233]: <info> (eth0): device state change: 5 -> 7 (reason 0)
NetworkManager[5233]: <info> Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
NetworkManager[5233]: <info> dhclient started with pid 5369
NetworkManager[5233]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Internet Systems Consortium DHCP Client V3.1.3
Copyright 2004-2009 Internet Systems Consortium.
All rights reserved.
For info, please visit https://www.isc.org/software/dhcp/

NetworkManager[5233]: <info> (eth0): DHCPv4 state changed nbi -> preinit
Listening on LPF/eth0/00:1e:37:1e:06:6f
Sending on   LPF/eth0/00:1e:37:1e:06:6f
Sending on   Socket/fallback
DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 13
DHCPOFFER of 10.180.40.62 from 10.180.40.251
DHCPREQUEST of 10.180.40.62 on eth0 to 255.255.255.255 port 67
DHCPACK of 10.180.40.62 from 10.180.40.252
bound to 10.180.40.62 -- renewal in 5005 seconds.
NetworkManager[5233]: <info> (eth0): DHCPv4 state changed preinit -> bound
NetworkManager[5233]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
NetworkManager[5233]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
NetworkManager[5233]: <info>   address 10.180.40.62
NetworkManager[5233]: <info>   prefix 24 (255.255.255.0)
NetworkManager[5233]: <info>   gateway 10.180.40.254
NetworkManager[5233]: <info>   hostname 'cl00328.lvm.de'
NetworkManager[5233]: <info>   nameserver '10.225.64.1'
NetworkManager[5233]: <info>   nameserver '10.225.64.126'
NetworkManager[5233]: <info>   domain name 'lvm.de'
NetworkManager[5233]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager[5233]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
NetworkManager[5233]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
NetworkManager[5233]: <info> (eth0): device state change: 7 -> 8 (reason 0)
NetworkManager[5233]: <info> Policy set 'Auto eth0' (eth0) as default for IPv4 routing and DNS.
NetworkManager[5233]: <info> Activation (eth0) successful, device activated.
NetworkManager[5233]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.

** Message: ModemManager (version 0.4) starting...

** (modem-manager:5338): WARNING **: Could not acquire the org.freedesktop.ModemManager service as it is already taken. Return: 3