Re: problems with 3g based connections Correct Logs attached

[wp1191918-hgvs <hg van-schelve de>]

Am Donnerstag, den 07.10.2010, 15:33 +0200 schrieb 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.

Sorry, I have attached the wrong logs. Find the right one now attached.

NetworkManager[4918]: <info> NetworkManager (version 0.8.0.997) is starting...
NetworkManager[4918]: <info> modem-manager is now available
NetworkManager[4918]:    SCPlugin-Ifupdown: init!
NetworkManager[4918]:    SCPlugin-Ifupdown: update_system_hostname
NetworkManager[4918]:    SCPluginIfupdown: management mode: unmanaged
NetworkManager[4918]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:19.0/net/eth0, iface: eth0)
NetworkManager[4918]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:19.0/net/eth0, iface: eth0): no ifupdown configuration found.
NetworkManager[4918]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/lo, iface: lo)
NetworkManager[4918]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/lo, iface: lo): no ifupdown configuration found.
NetworkManager[4918]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/pan0, iface: pan0)
NetworkManager[4918]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/pan0, iface: pan0): no ifupdown configuration found.
NetworkManager[4918]:    SCPlugin-Ifupdown: end _init.
NetworkManager[4918]: <info> Loaded plugin ifupdown: (C) 2008 Canonical Ltd.  To report bugs please use the NetworkManager mailing list.
NetworkManager[4918]: <info> Loaded plugin keyfile: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
NetworkManager[4918]:    Ifupdown: get unmanaged devices count: 0
NetworkManager[4918]:    SCPlugin-Ifupdown: (145690400) ... get_connections.
NetworkManager[4918]:    SCPlugin-Ifupdown: (145690400) ... get_connections (managed=false): return empty list.
NetworkManager[4918]:    Ifupdown: get unmanaged devices count: 0
NetworkManager[4918]: <info> found WWan radio killswitch rfkill2 (at /sys/devices/platform/thinkpad_acpi/rfkill/rfkill2) (driver thinkpad_acpi)
NetworkManager[4918]: <info> WiFi enabled by radio killswitch; enabled by state file
NetworkManager[4918]: <info> WWAN enabled by radio killswitch; disabled by state file
NetworkManager[4918]: <info> WiMAX enabled by radio killswitch; enabled by state file
NetworkManager[4918]: <info> Networking is enabled by state file
NetworkManager[4918]: <info> (eth0): carrier is ON
NetworkManager[4918]: <info> (eth0): new Ethernet device (driver: 'e1000e' ifindex: 2)
NetworkManager[4918]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
NetworkManager[4918]: <info> (eth0): now managed
NetworkManager[4918]: <info> (eth0): device state change: 1 -> 2 (reason 2)
NetworkManager[4918]: <info> (eth0): preparing device.
NetworkManager[4918]: <info> (eth0): deactivating device (reason: 2).
NetworkManager[4918]: <error> [1286462000.443491] [nm-system.c:1229] check_one_route(): (eth0): error -34 returned from rtnl_route_del(): Netlink Error (errno = Numerical result out of range)
NetworkManager[4918]: <info> Added default wired connection 'Auto eth0' for /sys/devices/pci0000:00/0000:00:19.0/net/eth0
NetworkManager[4918]: <warn> /sys/devices/virtual/net/pan0: couldn't determine device driver; ignoring...
/sbin/ifup: interface lo already configured
NetworkManager[4918]: <info> (eth0): device state change: 2 -> 3 (reason 0)
NetworkManager[4918]: <info> Activation (eth0) starting connection 'Auto eth0'
NetworkManager[4918]: <info> (eth0): device state change: 3 -> 4 (reason 0)
NetworkManager[4918]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager[4918]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
NetworkManager[4918]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager[4918]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager[4918]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
NetworkManager[4918]: <info> (eth0): device state change: 4 -> 5 (reason 0)
NetworkManager[4918]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful.
NetworkManager[4918]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[4918]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
NetworkManager[4918]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[4918]: <info> (eth0): device state change: 5 -> 7 (reason 0)
NetworkManager[4918]: <info> Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
NetworkManager[4918]: <info> dhclient started with pid 4921
NetworkManager[4918]: <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[4918]: <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 4
DHCPOFFER of 10.180.40.62 from 10.180.40.252
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.251
NetworkManager[4918]: <warn> (ttyUSB0): failed to look up interface index
NetworkManager[4918]: <info> (ttyUSB0): new GSM device (driver: 'sierra' ifindex: -1)
NetworkManager[4918]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/1
NetworkManager[4918]: <info> (ttyUSB0): now managed
NetworkManager[4918]: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
bound to 10.180.40.62 -- renewal in 4816 seconds.
NetworkManager[4918]: <info> (ttyUSB0): deactivating device (reason: 2).
NetworkManager[4918]: <info> (eth0): DHCPv4 state changed preinit -> bound
NetworkManager[4918]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
NetworkManager[4918]: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)
NetworkManager[4918]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
NetworkManager[4918]: <info>   address 10.180.40.62
NetworkManager[4918]: <info>   prefix 24 (255.255.255.0)
NetworkManager[4918]: <info>   gateway 10.180.40.254
NetworkManager[4918]: <info>   hostname 'cl00328.lvm.de'
NetworkManager[4918]: <info>   nameserver '10.225.64.1'
NetworkManager[4918]: <info>   nameserver '10.225.64.126'
NetworkManager[4918]: <info>   domain name 'lvm.de'
NetworkManager[4918]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager[4918]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
NetworkManager[4918]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
NetworkManager[4918]: <info> (eth0): device state change: 7 -> 8 (reason 0)
NetworkManager[4918]: <info> Policy set 'Auto eth0' (eth0) as default for IPv4 routing and DNS.
NetworkManager[4918]: <info> Activation (eth0) successful, device activated.
NetworkManager[4918]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.

** Message: ModemManager (version 0.4) starting...
** Message: Loaded plugin MotoC
** Message: Loaded plugin Huawei
** Message: Loaded plugin Sierra
** Message: Loaded plugin Novatel
** Message: Loaded plugin Generic
** Message: Loaded plugin Longcheer
** Message: Loaded plugin ZTE
** Message: Loaded plugin AnyData
** Message: Loaded plugin SimTech
** Message: Loaded plugin Option High-Speed
** Message: Loaded plugin X22X
** Message: Loaded plugin Option
** Message: Loaded plugin Gobi
** Message: Loaded plugin Ericsson MBM
** Message: Loaded plugin Nokia
** (modem-manager:4841): DEBUG: (tty/ttyS0): port's parent platform driver is not whitelisted
** (modem-manager:4841): DEBUG: (tty/ttyS1): port's parent platform driver is not whitelisted
** (modem-manager:4841): DEBUG: (tty/ttyS2): port's parent platform driver is not whitelisted
** (modem-manager:4841): DEBUG: (tty/ttyS3): port's parent platform driver is not whitelisted
** (modem-manager:4841): DEBUG: (net/pan0): could not get port's parent device
** Message: (ttyUSB0) opening serial device...
** (modem-manager:4841): DEBUG: <1286461984.603673> (ttyUSB0) device open count is 1 (open)
** (modem-manager:4841): DEBUG: (ttyUSB0): probe requested by plugin 'Sierra'
** Message: (ttyUSB1) opening serial device...
** (modem-manager:4841): DEBUG: <1286461984.608676> (ttyUSB1) device open count is 1 (open)
** (modem-manager:4841): DEBUG: (ttyUSB1): probe requested by plugin 'Sierra'
** Message: (ttyUSB2) opening serial device...
** (modem-manager:4841): DEBUG: <1286461984.613668> (ttyUSB2) device open count is 1 (open)
** (modem-manager:4841): DEBUG: (ttyUSB2): probe requested by plugin 'Sierra'
** (modem-manager:4841): DEBUG: <1286461984.704696> (ttyUSB0): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461985.505845> (ttyUSB0): <-- '<CR><LF>+GCAP: +CGSM,+DS,+ES<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461985.507758> (ttyUSB1): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461986.309055> (ttyUSB2): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461987.111422> (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461987.111559> (ttyUSB0) device open count is 0 (close)
** Message: (ttyUSB0) closing serial device...
** Message: (ttyUSB0) type primary claimed by /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** Message: (ttyUSB0) opening serial device...
** (modem-manager:4841): DEBUG: <1286461987.132702> (ttyUSB0) device open count is 1 (open)
** (modem-manager:4841): DEBUG: <1286461987.132768> (ttyUSB0) device open count is 2 (open)
** Message: (Sierra): GSM modem /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1 claimed port ttyUSB0
** (modem-manager:4841): DEBUG: Added modem /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:4841): DEBUG: (tty/ttyUSB0): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:4841): DEBUG: (tty/ttyUSB1): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:4841): DEBUG: <1286461987.133125> (ttyUSB2): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461987.934356> (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461987.934492> (ttyUSB0): --> 'AT+CPIN?<CR>'
** (modem-manager:4841): DEBUG: <1286461987.944758> (ttyUSB2): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461988.746076> (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461988.746192> (ttyUSB0): <-- '<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461988.746360> (ttyUSB0) device open count is 1 (close)
** (modem-manager:4841): DEBUG: (tty/ttyUSB1): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:4841): DEBUG: <1286461988.746567> (ttyUSB0): --> 'ATE0<CR>'
** (modem-manager:4841): DEBUG: <1286461988.752186> (ttyUSB2): --> 'ATI<CR>'
** (modem-manager:4841): DEBUG: <1286461989.152850> (ttyUSB2): <-- 'Sierra Wireless, Inc.<LF><CR>MC8775<LF><CR>APP1<LF><CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461989.152947> (ttyUSB0): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461989.153100> (ttyUSB0): --> 'AT+CGSN<CR>'
** Message: (ttyUSB2) type secondary claimed by /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:4841): DEBUG: <1286461989.162830> (ttyUSB2) device open count is 0 (close)
** Message: (ttyUSB2) closing serial device...
** Message: (Sierra): GSM modem /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1 claimed port ttyUSB2
** (modem-manager:4841): DEBUG: (tty/ttyUSB1): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:4841): DEBUG: <1286461989.172781> (ttyUSB0): <-- '<CR><LF>352678013119372<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:4841): DEBUG: <1286461989.172852> (ttyUSB0) device open count is 0 (close)
** Message: (ttyUSB0) closing serial device...
** (modem-manager:4841): DEBUG: <1286461990.737> (ttyUSB1): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461993.999914> (ttyUSB1): --> 'AT+GCAP<CR>'
** (modem-manager:4841): DEBUG: <1286461997.999823> (ttyUSB1) device open count is 0 (close)
** Message: (ttyUSB1) closing serial device...
** Message: (ttyUSB1) opening serial device...
** (modem-manager:4841): DEBUG: <1286461998.14703> (ttyUSB1) device open count is 1 (open)
** (modem-manager:4841): DEBUG: <1286461998.14826> (ttyUSB1): --> 00 78 f0 7e

** (modem-manager:4841): CRITICAL **: enumerate_devices_cb: assertion `path != NULL' failed
** (modem-manager:4841): DEBUG: <1286462001.1407> (ttyUSB1): --> 00 78 f0 7e
** (modem-manager:4841): DEBUG: <1286462004.3444> (ttyUSB1) device open count is 0 (close)
** Message: (ttyUSB1) closing serial device...
** (modem-manager:4841): DEBUG: (tty/ttyUSB1): ignoring port unsupported by physical modem's plugin
** (modem-manager:4841): DEBUG: Exported modem /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1 as /org/freedesktop/ModemManager/Modems/0
** (modem-manager:4841): DEBUG: (/org/freedesktop/ModemManager/Modems/0): data port is ttyUSB0