Problems initializing the modem

[van Schelve <public van-schelve de>]

Hi.

I was able to reproduce a problem where I get many issue tickets from 
our users in the field for.

The problem from user side is that the system is offline after login 
and they are not able to connect manually until they have used the 
rfkill swich. We have a session autostart to bring up a 3g based 
systemconnection in the case that the system is offline. If that fails 
the user can start the connection by hand using nm-applet. But if the 
modem-manager fails to initialize the modem the user cannot start the 
connection because there is no entry in the list. This problem occurs 
very often.

I was able to reproduce the issue - which was very difficult - while 
running modem-manager in debug mode and capture some logs and I really 
hope they are useful.

Some user reports that they run into this issue very often, some 
others never have seen this. They all have the same components and 
identical hardware / bios / firmware etc.

The attached syslog.stripped only contains the NetworkManager 
messages. There was no modem-manager logs in the original file maybe 
because modem-manager was started with --debug option.

HG

** (modem-manager:1202): DEBUG: (tty/ttyS1): port's parent platform driver is not whitelisted
** (modem-manager:1202): DEBUG: (tty/ttyS2): port's parent platform driver is not whitelisted
** (modem-manager:1202): DEBUG: (tty/ttyS3): port's parent platform driver is not whitelisted
** (modem-manager:1202): DEBUG: <1286544679.57594> (ttyS0) device open count is 1 (open)
** (modem-manager:1202): DEBUG: (ttyS0): probe requested by plugin 'Generic'
** (modem-manager:1202): DEBUG: <1286544679.62350> (ttyUSB0) device open count is 1 (open)
** (modem-manager:1202): DEBUG: (ttyUSB0): probe requested by plugin 'Sierra'
** (modem-manager:1202): DEBUG: <1286544679.70352> (ttyUSB1) device open count is 1 (open)
** (modem-manager:1202): DEBUG: (ttyUSB1): probe requested by plugin 'Sierra'
** (modem-manager:1202): DEBUG: <1286544679.75353> (ttyUSB2) device open count is 1 (open)
** (modem-manager:1202): DEBUG: (ttyUSB2): probe requested by plugin 'Sierra'
** (modem-manager:1202): DEBUG: <1286544679.157071> (ttyS0): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544679.962648> (ttyUSB0): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544680.770868> (ttyUSB1): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544681.689444> (ttyUSB2): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: (net/pan0): could not get port's parent device
** (modem-manager:1202): DEBUG: <1286544682.491039> (ttyUSB0): <-- '<CR><LF>+GCAP: +CGSM,+DS,+ES<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544682.491110> (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544682.491493> (ttyUSB0) device open count is 0 (close)
** (modem-manager:1202): DEBUG: <1286544682.503657> (ttyUSB2): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544683.304696> (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544683.309378> (ttyUSB0) device open count is 1 (open)
** (modem-manager:1202): DEBUG: <1286544683.309409> (ttyUSB0) device open count is 2 (open)
** (modem-manager:1202): DEBUG: Added modem /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:1202): DEBUG: (tty/ttyUSB0): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:1202): DEBUG: (tty/ttyUSB1): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:1202): DEBUG: <1286544683.309593> (ttyUSB0): --> 'AT+CPIN?<CR>'
** (modem-manager:1202): DEBUG: <1286544683.319579> (ttyUSB2): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544684.196160> (ttyS0): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544684.997272> (ttyUSB1): <-- '~\0<LF>kk\0\0\7\0\0\0\0\0\0\0~'
** (modem-manager:1202): DEBUG: <1286544684.997314> (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544684.997351> (ttyUSB0): <-- '<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544684.997419> (ttyUSB0) device open count is 1 (close)
** (modem-manager:1202): DEBUG: (tty/ttyUSB1): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:1202): DEBUG: <1286544684.997501> (ttyUSB0): --> 'ATE0<CR>'
** (modem-manager:1202): DEBUG: <1286544685.3103> (ttyUSB2): --> 'ATI<CR>'
** (modem-manager:1202): DEBUG: <1286544685.403644> (ttyUSB2): <-- 'Sierra Wireless, Inc.<LF><CR>MC8775<LF><CR>APP1<LF><CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544685.403689> (ttyUSB0): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544685.403743> (ttyUSB1): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544686.204750> (ttyUSB0): --> 'AT+CGSN<CR>'
** (modem-manager:1202): DEBUG: <1286544686.214004> (ttyUSB2) device open count is 0 (close)
** (modem-manager:1202): DEBUG: (tty/ttyUSB1): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.1/usb6/6-1
** (modem-manager:1202): DEBUG: <1286544686.223494> (ttyUSB0): <-- '<CR><LF>352678013064321<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:1202): DEBUG: <1286544686.223576> (ttyUSB0) device open count is 0 (close)
** (modem-manager:1202): DEBUG: <1286544688.1362> (ttyS0): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544689.714> (ttyUSB1): --> 'AT+GCAP<CR>'
** (modem-manager:1202): DEBUG: <1286544691.866581> (ttyUSB1): <-- '~\0<LF>kl\0\0\7\0\0\0\0\0\0\0~'
** (modem-manager:1202): DEBUG: <1286544691.999897> (ttyS0) device open count is 0 (close)
** (modem-manager:1202): DEBUG: <1286544692.91> (ttyS0) device open count is 1 (open)
** (modem-manager:1202): DEBUG: <1286544692.135> (ttyS0): --> 00 78 f0 7e
** (modem-manager:1202): DEBUG: <1286544693.739> (ttyUSB1) device open count is 0 (close)
** (modem-manager:1202): DEBUG: <1286544693.15386> (ttyUSB1) device open count is 1 (open)
** (modem-manager:1202): DEBUG: <1286544693.15443> (ttyUSB1): --> 00 78 f0 7e
** (modem-manager:1202): DEBUG: <1286544695.1066> (ttyS0): --> 00 78 f0 7e
** (modem-manager:1202): DEBUG: <1286544696.926> (ttyUSB1): --> 00 78 f0 7e
** (modem-manager:1202): DEBUG: <1286544698.512> (ttyS0) device open count is 0 (close)
** (modem-manager:1202): DEBUG: <1286544698.867589> (ttyUSB1): <-- 7e 00 0a 6b 6d 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544705.866571> (ttyUSB1): <-- 7e 00 0a 6b 6e 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544712.866559> (ttyUSB1): <-- 7e 00 0a 6b 6f 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544719.866579> (ttyUSB1): <-- 7e 00 0a 6b 70 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544726.866592> (ttyUSB1): <-- 7e 00 0a 6b 71 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544733.866598> (ttyUSB1): <-- 7e 00 0a 6b 72 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544740.866563> (ttyUSB1): <-- 7e 00 0a 6b 73 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544747.866673> (ttyUSB1): <-- 7e 00 0a 6b 74 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544754.866662> (ttyUSB1): <-- 7e 00 0a 6b 75 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544761.866651> (ttyUSB1): <-- 7e 00 0a 6b 76 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544768.870659> (ttyUSB1): <-- 7e 00 0a 6b 77 00 00 07 00 00 00 00 00 00 00 7e
** (modem-manager:1202): DEBUG: <1286544775.870640> (ttyUSB1): <-- 7e 00 0a 6b 78 00 00 07 00 00 00 00 00 00 00 7e

Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> NetworkManager (version 0.8.0.997) is starting...
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> modem-manager is now available
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: init!
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: update_system_hostname
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPluginIfupdown: management mode: unmanaged
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:19.0/net/eth0, iface: eth0)
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:19.0/net/eth0, iface: eth0): no ifupdown configuration found.
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/lo, iface: lo)
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/lo, iface: lo): no ifupdown configuration found.
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: end _init.
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> Loaded plugin ifupdown: (C) 2008 Canonical Ltd.  To report bugs please use the NetworkManager mailing list.
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> Loaded plugin keyfile: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Oct  8 15:31:19 c384074 NetworkManager[1208]:    Ifupdown: get unmanaged devices count: 0
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: (143199008) ... get_connections.
Oct  8 15:31:19 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: (143199008) ... get_connections (managed=false): return empty list.
Oct  8 15:31:19 c384074 NetworkManager[1208]:    Ifupdown: get unmanaged devices count: 0
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> found WWan radio killswitch rfkill2 (at /sys/devices/platform/thinkpad_acpi/rfkill/rfkill2) (driver thinkpad_acpi)
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> WiFi enabled by radio killswitch; enabled by state file
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> WWAN enabled by radio killswitch; disabled by state file
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> WiMAX enabled by radio killswitch; enabled by state file
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> Networking is enabled by state file
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): carrier is OFF
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): new Ethernet device (driver: 'e1000e' ifindex: 2)
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): now managed
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): device state change: 1 -> 2 (reason 2)
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): bringing up device.
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): preparing device.
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> (eth0): deactivating device (reason: 2).
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> Added default wired connection 'Auto eth0' for /sys/devices/pci0000:00/0000:00:19.0/net/eth0
Oct  8 15:31:19 c384074 NetworkManager[1208]: <warn> bluez error getting default adapter: The name org.bluez was not provided by any .service files
Oct  8 15:31:19 c384074 NetworkManager[1208]: <info> Trying to start the supplicant...
Oct  8 15:31:20 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/pan0, iface: pan0)
Oct  8 15:31:20 c384074 NetworkManager[1208]:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/pan0, iface: pan0): no ifupdown configuration found.
Oct  8 15:31:20 c384074 NetworkManager[1208]: <warn> /sys/devices/virtual/net/pan0: couldn't determine device driver; ignoring...