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...
_______________________________________________
networkmanager-list mailing list
networkmanager-list@gnome.org
http://mail.gnome.org/mailman/listinfo/networkmanager-list
