Bug 1281731 - USB GSM Modem stopped working after update from Fedora 22 to 23
USB GSM Modem stopped working after update from Fedora 22 to 23
Status: CLOSED EOL
Product: Fedora
Classification: Fedora
Component: ModemManager (Show other bugs)
23
x86_64 Linux
unspecified Severity high
: ---
: ---
Assigned To: Lubomir Rintel
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-11-13 05:34 EST by Sergey Bostandzhyan
Modified: 2016-12-20 10:48 EST (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-12-20 10:48:44 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
log output of journalctl -f while attempting to connect to the internet (100.78 KB, text/plain)
2016-10-04 15:33 EDT, Sergey Bostandzhyan
no flags Details

  None (edit)
Description Sergey Bostandzhyan 2015-11-13 05:34:57 EST
Description of problem:

I have Huawei 0682 HSPA USB stick which I use for a mobile broadband connection. It worked fine via ModemManager and NetworkManager in Fedora 22. After upgrade to Fedora 23 I can not make a connection anymore, it always fails.

The modem is:
[240954.727001] usb 1-4: New USB device found, idVendor=12d1, idProduct=1446
[240954.727032] usb 1-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
[240954.727037] usb 1-4: Product: HUAWEI Mobile
[240954.727042] usb 1-4: Manufacturer: HUAWEI Technology
...
[240959.504454] option 1-4:1.0: GSM modem (1-port) converter detected
[240959.504662] usb 1-4: GSM modem (1-port) converter now attached to ttyUSB0
[240959.504981] option 1-4:1.1: GSM modem (1-port) converter detected
[240959.506020] usb 1-4: GSM modem (1-port) converter now attached to ttyUSB1
[240959.506304] option 1-4:1.2: GSM modem (1-port) converter detected
[240959.506450] usb 1-4: GSM modem (1-port) converter now attached to ttyUSB2



This is a big problem for me, because I need to go online on the road.

With the first connection attempt I could see the following in the log:

Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Simple connect started...
Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Simple connect state (4/8): Wait to get fully enabled
Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Simple connect state (5/8): Register
Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Simple connect state (6/8): Bearer
Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Simple connect state (7/8): Connect
Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Nov 12 14:43:38 469.lan NetworkManager[1410]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Nov 12 14:43:38 469.lan ModemManager[1211]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Nov 12 14:43:38 469.lan NetworkManager[1410]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): Activation: starting connection 'HoT' (ed6847e9-9691-42b5-981b-d907db8c1e1c)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  NetworkManager state is now CONNECTING
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect started...
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (4/8): Wait to get fully enabled
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (5/8): Register
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (6/8): Bearer
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (7/8): Connect
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect started...
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (4/8): Wait to get fully enabled
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (5/8): Register
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (6/8): Bearer
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Simple connect state (7/8): Connect
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Nov 12 14:43:52 469.lan ModemManager[1211]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Nov 12 14:43:52 469.lan NetworkManager[1410]: <warn>  (ttyUSB2): failed to connect modem: No cause information available
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): device state change: prepare -> failed (reason 'modem-no-carrier') [40 120 25]
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  NetworkManager state is now DISCONNECTED
Nov 12 14:43:52 469.lan NetworkManager[1410]: <warn>  (ttyUSB2): Activation: failed for connection 'HoT'
Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Nov 12 14:43:52 469.lan /firewalld[1193]: 2015-11-12 14:43:52 ERROR: UNKNOWN_INTERFACE: 'ttyUSB2' is not in any zone




I then disabled firewalld, it looked like it would go better (the NM lights turned green), but the attempt did not succeed, here is the log:

Nov 12 15:02:28 469.lan NetworkManager[13343]: <info>  startup complete
Nov 12 15:02:39 469.lan kernel: usb 2-4: new high-speed USB device number 23 using ehci-pci
Nov 12 15:02:39 469.lan kernel: usb 2-4: New USB device found, idVendor=12d1, idProduct=1446
Nov 12 15:02:39 469.lan kernel: usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Nov 12 15:02:39 469.lan kernel: usb 2-4: Product: HUAWEI Mobile
Nov 12 15:02:39 469.lan kernel: usb 2-4: Manufacturer: HUAWEI Technology
Nov 12 15:02:39 469.lan kernel: usb-storage 2-4:1.0: USB Mass Storage device detected
Nov 12 15:02:39 469.lan kernel: scsi host49: usb-storage 2-4:1.0
Nov 12 15:02:39 469.lan kernel: usb-storage 2-4:1.1: USB Mass Storage device detected
Nov 12 15:02:39 469.lan kernel: scsi host50: usb-storage 2-4:1.1
Nov 12 15:02:39 469.lan mtp-probe[13395]: checking bus 2, device 23: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4"
Nov 12 15:02:39 469.lan mtp-probe[13395]: bus: 2, device: 23 was not an MTP device
Nov 12 15:02:40 469.lan root[13406]: usb_modeswitch: use overriding config file /etc/usb_modeswitch.d/12d1:1446; make sure this is intended
Nov 12 15:02:40 469.lan root[13407]: usb_modeswitch: please report any new or corrected settings; otherwise, check for outdated files
Nov 12 15:02:40 469.lan usb_modeswitch[13409]: switch device 12d1:1446 on 002/023
Nov 12 15:02:40 469.lan kernel: usb 2-4: USB disconnect, device number 23
Nov 12 15:02:44 469.lan kernel: usb 2-4: new high-speed USB device number 24 using ehci-pci
Nov 12 15:02:44 469.lan kernel: usb 2-4: New USB device found, idVendor=12d1, idProduct=1001
Nov 12 15:02:44 469.lan kernel: usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Nov 12 15:02:44 469.lan kernel: usb 2-4: Product: HUAWEI Mobile
Nov 12 15:02:44 469.lan kernel: usb 2-4: Manufacturer: HUAWEI Technology
Nov 12 15:02:44 469.lan kernel: usb-storage 2-4:1.0: USB Mass Storage device detected
Nov 12 15:02:44 469.lan kernel: option 2-4:1.0: GSM modem (1-port) converter detected
Nov 12 15:02:44 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB0
Nov 12 15:02:44 469.lan kernel: usb-storage 2-4:1.1: USB Mass Storage device detected
Nov 12 15:02:44 469.lan kernel: option 2-4:1.1: GSM modem (1-port) converter detected
Nov 12 15:02:44 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
Nov 12 15:02:44 469.lan kernel: usb-storage 2-4:1.2: USB Mass Storage device detected
Nov 12 15:02:44 469.lan kernel: option 2-4:1.2: GSM modem (1-port) converter detected
Nov 12 15:02:44 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB2
Nov 12 15:02:44 469.lan kernel: usb-storage 2-4:1.3: USB Mass Storage device detected
Nov 12 15:02:44 469.lan kernel: scsi host54: usb-storage 2-4:1.3
Nov 12 15:02:44 469.lan kernel: usb-storage 2-4:1.4: USB Mass Storage device detected
Nov 12 15:02:44 469.lan kernel: scsi host55: usb-storage 2-4:1.4
Nov 12 15:02:45 469.lan root[13423]: usb_modeswitch: switched to 12d1:1001 on 002/024
Nov 12 15:02:45 469.lan kernel: scsi 54:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Nov 12 15:02:45 469.lan kernel: scsi 55:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
Nov 12 15:02:45 469.lan kernel: sr 54:0:0:0: [sr1] scsi-1 drive
Nov 12 15:02:45 469.lan kernel: sr 54:0:0:0: Attached scsi CD-ROM sr1
Nov 12 15:02:45 469.lan kernel: sr 54:0:0:0: Attached scsi generic sg3 type 5
Nov 12 15:02:45 469.lan kernel: sd 55:0:0:0: Attached scsi generic sg4 type 0
Nov 12 15:02:45 469.lan kernel: sd 55:0:0:0: [sdc] Attached SCSI removable disk
Nov 12 15:02:46 469.lan mtp-probe[13429]: checking bus 2, device 24: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4"
Nov 12 15:02:46 469.lan mtp-probe[13429]: bus: 2, device: 24 was not an MTP device
Nov 12 15:02:46 469.lan ModemManager[13268]: <warn>  (ttyUSB1): port attributes not fully set
Nov 12 15:02:46 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 12 15:02:55 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 12 15:02:56 469.lan kernel: sd 55:0:0:0: [sdc] 3854336 512-byte logical blocks: (1.97 GB/1.83 GiB)
Nov 12 15:02:56 469.lan kernel: sd 55:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Nov 12 15:02:56 469.lan kernel:  sdc: sdc1 sdc2
Nov 12 15:02:58 469.lan ModemManager[13268]: <info>  Creating modem with plugin 'Generic' and '3' ports
Nov 12 15:02:58 469.lan ModemManager[13268]: <warn>  Could not grab port (tty/ttyUSB0): 'Cannot add port 'tty/ttyUSB0', unhandled serial type'
Nov 12 15:02:58 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 12 15:02:58 469.lan ModemManager[13268]: <info>  Modem for device at '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4' successfully created
Nov 12 15:02:59 469.lan ModemManager[13268]: <info>  Modem: state changed (unknown -> disabled)
Nov 12 15:02:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Nov 12 15:02:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): new Broadband device (carrier: UNKNOWN, driver: 'option1', ifindex: 0)
Nov 12 15:02:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Nov 12 15:02:59 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (disabled -> enabling)
Nov 12 15:02:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state 'enabling'
Nov 12 15:02:59 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 12 15:02:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Nov 12 15:02:59 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: 3GPP Registration state changed (unknown -> searching)
Nov 12 15:02:59 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (enabling -> searching)
Nov 12 15:02:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'enabling' --> 'searching' (reason: user-requested)
Nov 12 15:03:08 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: 3GPP Registration state changed (searching -> registering)
Nov 12 15:03:08 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: 3GPP Registration state changed (registering -> roaming)
Nov 12 15:03:08 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (searching -> registered)
Nov 12 15:03:08 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'searching' --> 'registered' (reason: unknown)
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): Activation: starting connection 'HoT' (ed6847e9-9691-42b5-981b-d907db8c1e1c)
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  NetworkManager state is now CONNECTING
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Simple connect started...
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Simple connect state (4/8): Wait to get fully enabled
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Simple connect state (5/8): Register
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: 3GPP Registration state changed (roaming -> searching)
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: 3GPP Registration state changed (searching -> registering)
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Simple connect state (6/8): Bearer
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Simple connect state (7/8): Connect
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (registered -> connecting)
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: 3GPP Registration state changed (registering -> roaming)
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (connecting -> connected)
Nov 12 15:03:13 469.lan ModemManager[13268]: <info>  Simple connect state (8/8): All done
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Nov 12 15:03:13 469.lan NetworkManager[13343]: <warn>  (ttyUSB2): failed to look up interface index
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 12 15:03:13 469.lan NetworkManager[13343]: <warn>  (ttyUSB2): interface ttyUSB2 not up for IP configuration
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): using modem-specified IP timeout: 20 seconds
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  starting PPP connection
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  pppd started with pid 13472
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ttyUSB2): IPv6 configuration disabled
Nov 12 15:03:13 469.lan pppd[13472]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Nov 12 15:03:13 469.lan NetworkManager[13343]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Nov 12 15:03:13 469.lan NetworkManager[13343]: nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
Nov 12 15:03:13 469.lan pppd[13472]: pppd 2.4.7 started by root, uid 0
Nov 12 15:03:13 469.lan NetworkManager[13343]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Nov 12 15:03:13 469.lan pppd[13472]: Using interface ppp0
Nov 12 15:03:13 469.lan NetworkManager[13343]: Using interface ppp0
Nov 12 15:03:13 469.lan pppd[13472]: Connect: ppp0 <--> /dev/ttyUSB2
Nov 12 15:03:13 469.lan NetworkManager[13343]: Connect: ppp0 <--> /dev/ttyUSB2
Nov 12 15:03:13 469.lan NetworkManager[13343]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Nov 12 15:03:13 469.lan NetworkManager[13343]: <info>  (ppp0): new Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 10)
Nov 12 15:03:34 469.lan NetworkManager[13343]: <warn>  pppd timed out or didn't initialize our dbus module
Nov 12 15:03:34 469.lan pppd[13472]: Terminating on signal 15
Nov 12 15:03:34 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Nov 12 15:03:34 469.lan NetworkManager[13343]: <info>  NetworkManager state is now DISCONNECTED
Nov 12 15:03:34 469.lan NetworkManager[13343]: Terminating on signal 15
Nov 12 15:03:34 469.lan NetworkManager[13343]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
Nov 12 15:03:34 469.lan NetworkManager[13343]: <warn>  (ttyUSB2): Activation: failed for connection 'HoT'
Nov 12 15:03:34 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Nov 12 15:03:34 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (connected -> disconnecting)
Nov 12 15:03:34 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'connected' --> 'disconnecting' (reason: user-requested)
Nov 12 15:03:35 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 12 15:03:36 469.lan NetworkManager[13343]: <warn>  (ppp0): failed to disable userspace IPv6LL address handling
Nov 12 15:03:56 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (disconnecting -> registered)
Nov 12 15:03:56 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'disconnecting' --> 'registered' (reason: user-requested)



Follow up connection attempts failed immediately (no green lights in NM applet):

Nov 12 15:04:39 469.lan NetworkManager[13343]: <info>  (ttyUSB2): Activation: starting connection 'HoT' (ed6847e9-9691-42b5-981b-d907db8c1e1c)
Nov 12 15:04:39 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 12 15:04:39 469.lan NetworkManager[13343]: <info>  NetworkManager state is now CONNECTING
Nov 12 15:04:39 469.lan ModemManager[13268]: <info>  Simple connect started...
Nov 12 15:04:39 469.lan ModemManager[13268]: <info>  Simple connect state (4/8): Wait to get fully enabled
Nov 12 15:04:39 469.lan ModemManager[13268]: <info>  Simple connect state (5/8): Register
Nov 12 15:04:39 469.lan ModemManager[13268]: <info>  Simple connect state (6/8): Bearer
Nov 12 15:04:39 469.lan ModemManager[13268]: <info>  Simple connect state (7/8): Connect
Nov 12 15:04:39 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (registered -> connecting)
Nov 12 15:04:39 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Nov 12 15:04:52 469.lan ModemManager[13268]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (connecting -> registered)
Nov 12 15:04:52 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Simple connect started...
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Simple connect state (4/8): Wait to get fully enabled
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Simple connect state (5/8): Register
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Simple connect state (6/8): Bearer
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Simple connect state (7/8): Connect
Nov 12 15:04:52 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (registered -> connecting)
Nov 12 15:04:52 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Nov 12 15:04:59 469.lan ModemManager[13268]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
Nov 12 15:04:59 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (connecting -> registered)
Nov 12 15:04:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Nov 12 15:04:59 469.lan NetworkManager[13343]: <warn>  (ttyUSB2): failed to connect modem: Sending command failed: 'Resource temporarily unavailable'
Nov 12 15:04:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: prepare -> failed (reason 'unknown') [40 120 1]
Nov 12 15:04:59 469.lan NetworkManager[13343]: <info>  NetworkManager state is now DISCONNECTED
Nov 12 15:04:59 469.lan NetworkManager[13343]: <warn>  (ttyUSB2): Activation: failed for connection 'HoT'
Nov 12 15:04:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]



Version-Release number of selected component (if applicable):

NetworkManager-1.0.6-8.fc23.x86_64
ModemManager-1.4.10-2.fc23.x86_64


How reproducible:

Insert the modem into the USB port, wait for it to scan the GSM networks, select your preconfigured mobile broadband connection (just the dial number and APN).

Steps to Reproduce:
1. Setup mobile broadband connection in NM with data from your ISP
2. Connect modem and wait for it to find the GSM network
3. Click on the connection in the NetworkManager to activate it

Actual results:

Connection fails.


Expected results:

Working mobile broadband connection, just like it was in Fedora 22 :)


Let me know if you need me to test something special.
Comment 1 Dan Williams 2015-11-13 14:30:04 EST
Can you grab the output of:

lsusb -v -d 12d1:1446
Comment 2 Sergey Bostandzhyan 2015-11-13 14:42:54 EST
Wanted to run the above, but noticed one weird thing with the id's.. it presents itself once with product id 1446 and then with product id 1001:


[275910.115189] usb 2-4: new high-speed USB device number 28 using ehci-pci
[275910.232345] usb 2-4: New USB device found, idVendor=12d1, idProduct=1446
[275910.232357] usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
[275910.232365] usb 2-4: Product: HUAWEI Mobile
[275910.232372] usb 2-4: Manufacturer: HUAWEI Technology
[275910.234834] usb-storage 2-4:1.0: USB Mass Storage device detected
[275910.235520] scsi host77: usb-storage 2-4:1.0
[275910.235771] usb-storage 2-4:1.1: USB Mass Storage device detected
[275910.235915] scsi host78: usb-storage 2-4:1.1
[275910.797879] usb 2-4: USB disconnect, device number 28
[275914.900175] usb 2-4: new high-speed USB device number 29 using ehci-pci
[275915.016809] usb 2-4: New USB device found, idVendor=12d1, idProduct=1001
[275915.016818] usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
[275915.016823] usb 2-4: Product: HUAWEI Mobile
[275915.016828] usb 2-4: Manufacturer: HUAWEI Technology
[275915.019561] usb-storage 2-4:1.0: USB Mass Storage device detected
[275915.019922] option 2-4:1.0: GSM modem (1-port) converter detected
[275915.021190] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB0
[275915.021410] usb-storage 2-4:1.1: USB Mass Storage device detected
[275915.021630] option 2-4:1.1: GSM modem (1-port) converter detected
[275915.021993] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
[275915.022204] usb-storage 2-4:1.2: USB Mass Storage device detected
[275915.023113] option 2-4:1.2: GSM modem (1-port) converter detected
[275915.023896] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB2
[275915.024093] usb-storage 2-4:1.3: USB Mass Storage device detected


Anyway, lsusb for 1446 does not return anything, lsusb for 1001 returns:

# lsusb -v -d 12d1:1001

Bus 002 Device 029: ID 12d1:1001 Huawei Technologies Co., Ltd. E169/E620/E800 HSDPA Modem
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  idVendor           0x12d1 Huawei Technologies Co., Ltd.
  idProduct          0x1001 E169/E620/E800 HSDPA Modem
  bcdDevice            0.00
  iManufacturer           3 HUAWEI Technology
  iProduct                2 HUAWEI Mobile
  iSerial                 0 
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength          131
    bNumInterfaces          5
    bConfigurationValue     1
    iConfiguration          1 Huawei   Configuration
    bmAttributes         0xe0
      Self Powered
      Remote Wakeup
    MaxPower              500mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           3
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass    255 Vendor Specific Subclass
      bInterfaceProtocol    255 Vendor Specific Protocol
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval               5
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval              32
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval              32
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass    255 Vendor Specific Subclass
      bInterfaceProtocol    255 Vendor Specific Protocol
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x83  EP 3 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval              32
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval              32
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        2
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass    255 Vendor Specific Subclass
      bInterfaceProtocol    255 Vendor Specific Protocol
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x84  EP 4 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval              32
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x03  EP 3 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval              32
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        3
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x85  EP 5 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x04  EP 4 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        4
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x05  EP 5 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x86  EP 6 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  bNumConfigurations      1
can't get debug descriptor: Resource temporarily unavailable
Device Status:     0x0003
  Self Powered
  Remote Wakeup Enabled
Comment 3 Dan Williams 2015-11-13 15:12:29 EST
(In reply to Sergey Bostandzhyan from comment #2)
> Wanted to run the above, but noticed one weird thing with the id's.. it
> presents itself once with product id 1446 and then with product id 1001:

It's getting mode-switched from "driver mode" (1446) where it presents a fake CDROM with the drivers on it, to modem mode (1001).

USB interface #0 (which corresponds to ttyUSB0) is the actual data port for PPP as shown by the lsusb output (since it has an interrupt endpoint), but it appears that ModemManager is selecting ttyUSB2 for the data port instead.

In any case, until MM can better figure out the port layout, try dropping the following into a file in /etc/udev/rules.d/77-huawei-ce0682.rules, and then unplugging and replugging the device:

ACTION!="add|change|move", GOTO="mm_huawei_ce0682_port_types_end"
SUBSYSTEM!="tty", GOTO="mm_huawei_ce0682_port_types_end"

SUBSYSTEMS=="usb", ATTRS{idVendor}=="12d1", GOTO="mm_huawei_ce0682_port_types_vendorcheck"
GOTO="mm_huawei_ce0682_port_types_end"

LABEL="mm_huawei_ce0682_port_types_vendorcheck"
SUBSYSTEMS=="usb", ATTRS{bInterfaceNumber}=="?*", ENV{.MM_USBIFNUM}="$attr{bInterfaceNumber}"

ATTRS{idVendor}=="12d1", ATTRS{idProduct}=="1001", ENV{.MM_USBIFNUM}=="00", ENV{ID_MM_HUAWEI_MODEM_PORT}="1"

LABEL="mm_huawei_ce0682_port_types_end"
Comment 4 Sergey Bostandzhyan 2015-11-13 15:26:28 EST
OK, but I will only be able to check the connection tomorrow (sim card is for another country, going there tomorrow again). Right now, with the above rules the log of plugging it in looks like this:

Nov 13 21:22:11 469.lan kernel: usb 2-4: new high-speed USB device number 34 using ehci-pci
Nov 13 21:22:11 469.lan kernel: usb 2-4: New USB device found, idVendor=12d1, idProduct=1446
Nov 13 21:22:11 469.lan kernel: usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Nov 13 21:22:11 469.lan kernel: usb 2-4: Product: HUAWEI Mobile
Nov 13 21:22:11 469.lan kernel: usb 2-4: Manufacturer: HUAWEI Technology
Nov 13 21:22:11 469.lan kernel: usb-storage 2-4:1.0: USB Mass Storage device detected
Nov 13 21:22:11 469.lan kernel: scsi host98: usb-storage 2-4:1.0
Nov 13 21:22:11 469.lan kernel: usb-storage 2-4:1.1: USB Mass Storage device detected
Nov 13 21:22:11 469.lan kernel: scsi host99: usb-storage 2-4:1.1
Nov 13 21:22:11 469.lan mtp-probe[8242]: checking bus 2, device 34: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4"
Nov 13 21:22:11 469.lan mtp-probe[8242]: bus: 2, device: 34 was not an MTP device
Nov 13 21:22:11 469.lan root[8253]: usb_modeswitch: use overriding config file /etc/usb_modeswitch.d/12d1:1446; make sure this is intended
Nov 13 21:22:11 469.lan root[8254]: usb_modeswitch: please report any new or corrected settings; otherwise, check for outdated files
Nov 13 21:22:11 469.lan usb_modeswitch[8256]: switch device 12d1:1446 on 002/034
Nov 13 21:22:11 469.lan kernel: usb 2-4: USB disconnect, device number 34
Nov 13 21:22:16 469.lan kernel: usb 2-4: new high-speed USB device number 35 using ehci-pci
Nov 13 21:22:16 469.lan kernel: usb 2-4: New USB device found, idVendor=12d1, idProduct=1001
Nov 13 21:22:16 469.lan kernel: usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Nov 13 21:22:16 469.lan kernel: usb 2-4: Product: HUAWEI Mobile
Nov 13 21:22:16 469.lan kernel: usb 2-4: Manufacturer: HUAWEI Technology
Nov 13 21:22:16 469.lan kernel: usb-storage 2-4:1.0: USB Mass Storage device detected
Nov 13 21:22:16 469.lan kernel: option 2-4:1.0: GSM modem (1-port) converter detected
Nov 13 21:22:16 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB0
Nov 13 21:22:16 469.lan kernel: usb-storage 2-4:1.1: USB Mass Storage device detected
Nov 13 21:22:16 469.lan kernel: option 2-4:1.1: GSM modem (1-port) converter detected
Nov 13 21:22:16 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
Nov 13 21:22:16 469.lan kernel: usb-storage 2-4:1.2: USB Mass Storage device detected
Nov 13 21:22:16 469.lan kernel: option 2-4:1.2: GSM modem (1-port) converter detected
Nov 13 21:22:16 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB2
Nov 13 21:22:16 469.lan kernel: usb-storage 2-4:1.3: USB Mass Storage device detected
Nov 13 21:22:16 469.lan kernel: scsi host103: usb-storage 2-4:1.3
Nov 13 21:22:16 469.lan kernel: usb-storage 2-4:1.4: USB Mass Storage device detected
Nov 13 21:22:16 469.lan kernel: scsi host104: usb-storage 2-4:1.4
Nov 13 21:22:17 469.lan root[8270]: usb_modeswitch: switched to 12d1:1001 on 002/035
Nov 13 21:22:17 469.lan kernel: scsi 103:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Nov 13 21:22:17 469.lan kernel: scsi 104:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
Nov 13 21:22:17 469.lan kernel: sr 103:0:0:0: [sr1] scsi-1 drive
Nov 13 21:22:17 469.lan kernel: sr 103:0:0:0: Attached scsi CD-ROM sr1
Nov 13 21:22:17 469.lan kernel: sr 103:0:0:0: Attached scsi generic sg3 type 5
Nov 13 21:22:17 469.lan kernel: sd 104:0:0:0: Attached scsi generic sg4 type 0
Nov 13 21:22:17 469.lan kernel: sd 104:0:0:0: [sdc] Attached SCSI removable disk
Nov 13 21:22:18 469.lan mtp-probe[8277]: checking bus 2, device 35: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4"
Nov 13 21:22:18 469.lan mtp-probe[8277]: bus: 2, device: 35 was not an MTP device
Nov 13 21:22:18 469.lan ModemManager[13268]: <warn>  (ttyUSB1): port attributes not fully set
Nov 13 21:22:18 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 13 21:22:27 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 13 21:22:28 469.lan kernel: sd 104:0:0:0: [sdc] 3854336 512-byte logical blocks: (1.97 GB/1.83 GiB)
Nov 13 21:22:28 469.lan kernel: sd 104:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Nov 13 21:22:28 469.lan kernel:  sdc: sdc1 sdc2
Nov 13 21:22:30 469.lan ModemManager[13268]: <info>  Creating modem with plugin 'Generic' and '3' ports
Nov 13 21:22:30 469.lan ModemManager[13268]: <warn>  Could not grab port (tty/ttyUSB0): 'Cannot add port 'tty/ttyUSB0', unhandled serial type'
Nov 13 21:22:30 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 13 21:22:30 469.lan ModemManager[13268]: <info>  Modem for device at '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4' successfully created
Nov 13 21:22:30 469.lan ModemManager[13268]: <info>  Modem: state changed (unknown -> disabled)
Nov 13 21:22:30 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Nov 13 21:22:30 469.lan NetworkManager[13343]: <info>  (ttyUSB2): new Broadband device (carrier: UNKNOWN, driver: 'option1', ifindex: 0)
Nov 13 21:22:30 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/8: state changed (disabled -> enabling)
Nov 13 21:22:30 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Nov 13 21:22:30 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state 'enabling'
Nov 13 21:22:30 469.lan NetworkManager[13343]: <info>  (ttyUSB2): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Nov 13 21:22:30 469.lan ModemManager[13268]: <warn>  (ttyUSB2): port attributes not fully set
Nov 13 21:22:31 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/8: 3GPP Registration state changed (unknown -> registering)
Nov 13 21:22:31 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/8: 3GPP Registration state changed (registering -> roaming)
Nov 13 21:22:31 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/8: state changed (enabling -> registered)
Nov 13 21:22:31 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'enabling' --> 'registered' (reason: user-requested)

By the way I noticed the lines:
Nov 13 21:22:11 469.lan root[8253]: usb_modeswitch: use overriding config file /etc/usb_modeswitch.d/12d1:1446; make sure this is intended
Nov 13 21:22:11 469.lan root[8254]: usb_modeswitch: please report any new or corrected settings; otherwise, check for outdated files

Can the problem be related to that?
Comment 5 Dan Williams 2015-11-13 16:05:54 EST
Probably unrelated.

I forgot one thing:

sudo udevadm control --reload

which will actually make udev aware of the new rules.  Can you run that command and then unplug/replug and see what NetworkManager says the control port is again?
Comment 6 Sergey Bostandzhyan 2015-11-13 16:20:53 EST
I used udevadm control --reload-rules before generating the above log, I repeated it now with --reload and the log looks pretty much the same. 

I had the impression that the rule did not really work out since its still referring to /dev/ttyUSB2?
Comment 7 Sergey Bostandzhyan 2015-11-14 18:50:16 EST
OK, so tried connecting with the udev rules in place, tested after a clean boot. Unfortunately it still did not work... the logs are below.

Connecting first time after inserting modem:

Dec 27 00:06:22 469.lan kernel: usb 2-4: new high-speed USB device number 8 using ehci-pci
Dec 27 00:06:22 469.lan kernel: usb 2-4: New USB device found, idVendor=12d1, idProduct=1446
Dec 27 00:06:22 469.lan kernel: usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Dec 27 00:06:22 469.lan kernel: usb 2-4: Product: HUAWEI Mobile
Dec 27 00:06:22 469.lan kernel: usb 2-4: Manufacturer: HUAWEI Technology
Dec 27 00:06:22 469.lan kernel: usb-storage 2-4:1.0: USB Mass Storage device detected
Dec 27 00:06:22 469.lan kernel: scsi host19: usb-storage 2-4:1.0
Dec 27 00:06:22 469.lan kernel: usb-storage 2-4:1.1: USB Mass Storage device detected
Dec 27 00:06:22 469.lan kernel: scsi host20: usb-storage 2-4:1.1
Dec 27 00:06:22 469.lan mtp-probe[3681]: checking bus 2, device 8: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4"
Dec 27 00:06:22 469.lan mtp-probe[3681]: bus: 2, device: 8 was not an MTP device
Dec 27 00:06:23 469.lan root[3693]: usb_modeswitch: use overriding config file /etc/usb_modeswitch.d/12d1:1446; make sure this is intended
Dec 27 00:06:23 469.lan root[3694]: usb_modeswitch: please report any new or corrected settings; otherwise, check for outdated files
Dec 27 00:06:23 469.lan usb_modeswitch[3696]: switch device 12d1:1446 on 002/008
Dec 27 00:06:23 469.lan kernel: usb 2-4: USB disconnect, device number 8
Dec 27 00:06:27 469.lan kernel: usb 2-4: new high-speed USB device number 9 using ehci-pci
Dec 27 00:06:27 469.lan kernel: usb 2-4: New USB device found, idVendor=12d1, idProduct=1001
Dec 27 00:06:27 469.lan kernel: usb 2-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Dec 27 00:06:27 469.lan kernel: usb 2-4: Product: HUAWEI Mobile
Dec 27 00:06:27 469.lan kernel: usb 2-4: Manufacturer: HUAWEI Technology
Dec 27 00:06:27 469.lan kernel: usb-storage 2-4:1.0: USB Mass Storage device detected
Dec 27 00:06:27 469.lan kernel: option 2-4:1.0: GSM modem (1-port) converter detected
Dec 27 00:06:27 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB0
Dec 27 00:06:27 469.lan kernel: usb-storage 2-4:1.1: USB Mass Storage device detected
Dec 27 00:06:27 469.lan kernel: option 2-4:1.1: GSM modem (1-port) converter detected
Dec 27 00:06:27 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
Dec 27 00:06:27 469.lan kernel: usb-storage 2-4:1.2: USB Mass Storage device detected
Dec 27 00:06:27 469.lan kernel: option 2-4:1.2: GSM modem (1-port) converter detected
Dec 27 00:06:27 469.lan kernel: usb 2-4: GSM modem (1-port) converter now attached to ttyUSB2
Dec 27 00:06:27 469.lan kernel: usb-storage 2-4:1.3: USB Mass Storage device detected
Dec 27 00:06:27 469.lan kernel: scsi host24: usb-storage 2-4:1.3
Dec 27 00:06:27 469.lan kernel: usb-storage 2-4:1.4: USB Mass Storage device detected
Dec 27 00:06:27 469.lan kernel: scsi host25: usb-storage 2-4:1.4
Dec 27 00:06:28 469.lan root[3714]: usb_modeswitch: switched to 12d1:1001 on 002/009
Dec 27 00:06:28 469.lan kernel: scsi 24:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Dec 27 00:06:28 469.lan kernel: scsi 25:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
Dec 27 00:06:28 469.lan kernel: sr 24:0:0:0: [sr1] scsi-1 drive
Dec 27 00:06:28 469.lan kernel: sr 24:0:0:0: Attached scsi CD-ROM sr1
Dec 27 00:06:28 469.lan kernel: sr 24:0:0:0: Attached scsi generic sg3 type 5
Dec 27 00:06:28 469.lan kernel: sd 25:0:0:0: Attached scsi generic sg4 type 0
Dec 27 00:06:28 469.lan kernel: sd 25:0:0:0: [sdc] Attached SCSI removable disk
Dec 27 00:06:30 469.lan mtp-probe[3722]: checking bus 2, device 9: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4"
Dec 27 00:06:30 469.lan mtp-probe[3722]: bus: 2, device: 9 was not an MTP device
Dec 27 00:06:30 469.lan ModemManager[1156]: <warn>  (ttyUSB1): port attributes not fully set
Dec 27 00:06:30 469.lan ModemManager[1156]: <warn>  (ttyUSB2): port attributes not fully set
Dec 27 00:06:38 469.lan ModemManager[1156]: <warn>  (ttyUSB2): port attributes not fully set
Dec 27 00:06:40 469.lan kernel: sd 25:0:0:0: [sdc] 3854336 512-byte logical blocks: (1.97 GB/1.83 GiB)
Dec 27 00:06:40 469.lan kernel: sd 25:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Dec 27 00:06:40 469.lan kernel:  sdc: sdc1 sdc2
Dec 27 00:06:41 469.lan ModemManager[1156]: <info>  Creating modem with plugin 'Generic' and '3' ports
Dec 27 00:06:41 469.lan ModemManager[1156]: <warn>  Could not grab port (tty/ttyUSB0): 'Cannot add port 'tty/ttyUSB0', unhandled serial type'
Dec 27 00:06:41 469.lan ModemManager[1156]: <warn>  (ttyUSB2): port attributes not fully set
Dec 27 00:06:41 469.lan ModemManager[1156]: <info>  Modem for device at '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4' successfully created
Dec 27 00:06:42 469.lan ModemManager[1156]: <info>  Modem: state changed (unknown -> disabled)
Dec 27 00:06:42 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Dec 27 00:06:42 469.lan NetworkManager[1380]: <info>  (ttyUSB2): new Broadband device (carrier: UNKNOWN, driver: 'option1', ifindex: 0)
Dec 27 00:06:42 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Dec 27 00:06:42 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state 'enabling'
Dec 27 00:06:42 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Dec 27 00:06:42 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (disabled -> enabling)
Dec 27 00:06:42 469.lan ModemManager[1156]: <warn>  (ttyUSB2): port attributes not fully set
Dec 27 00:06:42 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: 3GPP Registration state changed (unknown -> registering)
Dec 27 00:06:42 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: 3GPP Registration state changed (registering -> roaming)
Dec 27 00:06:43 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (enabling -> registered)
Dec 27 00:06:43 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'enabling' --> 'registered' (reason: user-requested)



Connecting again:

Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): Activation: starting connection 'HoT' (ed6847e9-9691-42b5-981b-d907db8c1e1c)
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  NetworkManager state is now CONNECTING
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Simple connect started...
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Simple connect state (4/8): Wait to get fully enabled
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Simple connect state (5/8): Register
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Simple connect state (6/8): Bearer
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Simple connect state (7/8): Connect
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> connected)
Dec 27 00:08:01 469.lan ModemManager[1156]: <info>  Simple connect state (8/8): All done
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Dec 27 00:08:01 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): failed to look up interface index
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: prepare -> config (reason 'none') [40 50 0]
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=filter family=2 entries=82
Dec 27 00:08:01 469.lan audit[3839]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55b14cc6e930 items=0 ppid=1150 pid=3839 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900494E5055545F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=filter family=10 entries=83
Dec 27 00:08:01 469.lan audit[3840]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55d65e4cc7d0 items=0 ppid=1150 pid=3840 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900494E5055545F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=filter family=2 entries=83
Dec 27 00:08:01 469.lan audit[3841]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=559b5a3ccaa0 items=0 ppid=1150 pid=3841 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900464F52574152445F4F55545F5A4F4E45530031002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=filter family=10 entries=84
Dec 27 00:08:01 469.lan audit[3842]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55e2192b79c0 items=0 ppid=1150 pid=3842 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900464F52574152445F4F55545F5A4F4E45530031002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=filter family=2 entries=84
Dec 27 00:08:01 469.lan audit[3843]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55753c88fc20 items=0 ppid=1150 pid=3843 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900464F52574152445F494E5F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=filter family=10 entries=85
Dec 27 00:08:01 469.lan audit[3844]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55a7f602fbb0 items=0 ppid=1150 pid=3844 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900464F52574152445F494E5F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=nat family=2 entries=50
Dec 27 00:08:01 469.lan audit[3845]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55c923d63030 items=0 ppid=1150 pid=3845 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900504F5354524F5554494E475F5A4F4E45530031002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=nat family=10 entries=50
Dec 27 00:08:01 469.lan audit[3846]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55aec602ff50 items=0 ppid=1150 pid=3846 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900504F5354524F5554494E475F5A4F4E45530031002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=nat family=2 entries=51
Dec 27 00:08:01 469.lan audit[3847]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5642ae31b1b0 items=0 ppid=1150 pid=3847 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=nat family=10 entries=51
Dec 27 00:08:01 469.lan audit[3848]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55e970bfe140 items=0 ppid=1150 pid=3848 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=mangle family=2 entries=39
Dec 27 00:08:01 469.lan audit[3849]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55aff321e420 items=0 ppid=1150 pid=3849 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:01 469.lan audit: NETFILTER_CFG table=mangle family=10 entries=39
Dec 27 00:08:01 469.lan audit[3850]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=56340b039fd0 items=0 ppid=1150 pid=3850 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:01 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: config -> ip-config (reason 'none') [50 70 0]
Dec 27 00:08:01 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): interface ttyUSB2 not up for IP configuration
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): using modem-specified IP timeout: 20 seconds
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  starting PPP connection
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  pppd started with pid 3851
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): IPv6 configuration disabled
Dec 27 00:08:01 469.lan pppd[3851]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Dec 27 00:08:01 469.lan NetworkManager[1380]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Dec 27 00:08:01 469.lan NetworkManager[1380]: nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
Dec 27 00:08:01 469.lan pppd[3851]: pppd 2.4.7 started by root, uid 0
Dec 27 00:08:01 469.lan pppd[3851]: Removed stale lock on ttyUSB2 (pid 3196)
Dec 27 00:08:01 469.lan NetworkManager[1380]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Dec 27 00:08:01 469.lan NetworkManager[1380]: Removed stale lock on ttyUSB2 (pid 3196)
Dec 27 00:08:01 469.lan pppd[3851]: Using interface ppp0
Dec 27 00:08:01 469.lan pppd[3851]: Connect: ppp0 <--> /dev/ttyUSB2
Dec 27 00:08:01 469.lan NetworkManager[1380]: <info>  (ppp0): new Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 5)
Dec 27 00:08:01 469.lan NetworkManager[1380]: Using interface ppp0
Dec 27 00:08:01 469.lan NetworkManager[1380]: Connect: ppp0 <--> /dev/ttyUSB2
Dec 27 00:08:01 469.lan NetworkManager[1380]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Dec 27 00:08:21 469.lan NetworkManager[1380]: <warn>  pppd timed out or didn't initialize our dbus module
Dec 27 00:08:21 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Dec 27 00:08:21 469.lan NetworkManager[1380]: <info>  NetworkManager state is now DISCONNECTED
Dec 27 00:08:21 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): Activation: failed for connection 'HoT'
Dec 27 00:08:21 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Dec 27 00:08:21 469.lan pppd[3851]: Terminating on signal 15
Dec 27 00:08:21 469.lan NetworkManager[1380]: Terminating on signal 15
Dec 27 00:08:21 469.lan NetworkManager[1380]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
Dec 27 00:08:21 469.lan dbus[1160]: [system] Rejected send message, 9 matched rules; type="error", sender=":1.10" (uid=0 pid=1380 comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.60" (uid=0 pid=3851 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Dec 27 00:08:21 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connected -> disconnecting)
Dec 27 00:08:21 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'connected' --> 'disconnecting' (reason: user-requested)
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=filter family=2 entries=85
Dec 27 00:08:21 469.lan audit[3883]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55720c552be0 items=0 ppid=1150 pid=3883 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400494E5055545F5A4F4E4553002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=filter family=10 entries=86
Dec 27 00:08:21 469.lan audit[3884]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=558f4e530b70 items=0 ppid=1150 pid=3884 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400494E5055545F5A4F4E4553002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=filter family=2 entries=84
Dec 27 00:08:21 469.lan audit[3885]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=563dc6478a70 items=0 ppid=1150 pid=3885 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400464F52574152445F4F55545F5A4F4E4553002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=filter family=10 entries=85
Dec 27 00:08:21 469.lan audit[3886]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55e28b418980 items=0 ppid=1150 pid=3886 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400464F52574152445F4F55545F5A4F4E4553002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=filter family=2 entries=83
Dec 27 00:08:21 469.lan audit[3887]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=561aa01d48f0 items=0 ppid=1150 pid=3887 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400464F52574152445F494E5F5A4F4E4553002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=filter family=10 entries=84
Dec 27 00:08:21 469.lan audit[3888]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=555f7d33e790 items=0 ppid=1150 pid=3888 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400464F52574152445F494E5F5A4F4E4553002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=nat family=2 entries=52
Dec 27 00:08:21 469.lan audit[3889]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=56191dd9a170 items=0 ppid=1150 pid=3889 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400504F5354524F5554494E475F5A4F4E4553002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=nat family=10 entries=52
Dec 27 00:08:21 469.lan audit[3890]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=557603b85100 items=0 ppid=1150 pid=3890 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400504F5354524F5554494E475F5A4F4E4553002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=nat family=2 entries=51
Dec 27 00:08:21 469.lan audit[3891]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5564501ab000 items=0 ppid=1150 pid=3891 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=nat family=10 entries=51
Dec 27 00:08:21 469.lan audit[3892]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55dc0a49ff10 items=0 ppid=1150 pid=3892 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=mangle family=2 entries=40
Dec 27 00:08:21 469.lan audit[3893]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55d330e113e0 items=0 ppid=1150 pid=3893 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:21 469.lan audit: NETFILTER_CFG table=mangle family=10 entries=40
Dec 27 00:08:21 469.lan audit[3894]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=564d2594ff90 items=0 ppid=1150 pid=3894 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Dec 27 00:08:21 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Dec 27 00:08:22 469.lan ModemManager[1156]: <warn>  (ttyUSB2): port attributes not fully set
Dec 27 00:08:23 469.lan NetworkManager[1380]: <warn>  (ppp0): failed to disable userspace IPv6LL address handling
Dec 27 00:08:44 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (disconnecting -> registered)
Dec 27 00:08:44 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'disconnecting' --> 'registered' (reason: user-requested)


Another attempt:

Dec 27 00:09:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): Activation: starting connection 'HoT' (ed6847e9-9691-42b5-981b-d907db8c1e1c)
Dec 27 00:09:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 27 00:09:01 469.lan NetworkManager[1380]: <info>  NetworkManager state is now CONNECTING
Dec 27 00:09:01 469.lan ModemManager[1156]: <info>  Simple connect started...
Dec 27 00:09:01 469.lan ModemManager[1156]: <info>  Simple connect state (4/8): Wait to get fully enabled
Dec 27 00:09:01 469.lan ModemManager[1156]: <info>  Simple connect state (5/8): Register
Dec 27 00:09:01 469.lan ModemManager[1156]: <info>  Simple connect state (6/8): Bearer
Dec 27 00:09:01 469.lan ModemManager[1156]: <info>  Simple connect state (7/8): Connect
Dec 27 00:09:01 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Dec 27 00:09:01 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Dec 27 00:09:02 469.lan kernel: perf interrupt took too long (2511 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
Dec 27 00:09:08 469.lan ModemManager[1156]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Dec 27 00:09:08 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Simple connect started...
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Simple connect state (4/8): Wait to get fully enabled
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Simple connect state (5/8): Register
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Simple connect state (6/8): Bearer
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Simple connect state (7/8): Connect
Dec 27 00:09:08 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Dec 27 00:09:08 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Dec 27 00:09:15 469.lan ModemManager[1156]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
Dec 27 00:09:15 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Dec 27 00:09:15 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Dec 27 00:09:15 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): failed to connect modem: Sending command failed: 'Resource temporarily unavailable'
Dec 27 00:09:15 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: prepare -> failed (reason 'unknown') [40 120 1]
Dec 27 00:09:15 469.lan NetworkManager[1380]: <info>  NetworkManager state is now DISCONNECTED
Dec 27 00:09:15 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): Activation: failed for connection 'HoT'
Dec 27 00:09:15 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Dec 27 00:09:15 469.lan /firewalld[1150]: 2006-12-27 00:09:15 ERROR: UNKNOWN_INTERFACE: 'ttyUSB2' is not in any zone



Disalbed firewalld, reconnecting:

Dec 27 00:11:36 469.lan NetworkManager[1380]: <info>  (ttyUSB2): Activation: starting connection 'HoT' (ed6847e9-9691-42b5-981b-d907db8c1e1c)
Dec 27 00:11:36 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 27 00:11:36 469.lan NetworkManager[1380]: <info>  NetworkManager state is now CONNECTING
Dec 27 00:11:36 469.lan ModemManager[1156]: <info>  Simple connect started...
Dec 27 00:11:36 469.lan ModemManager[1156]: <info>  Simple connect state (4/8): Wait to get fully enabled
Dec 27 00:11:36 469.lan ModemManager[1156]: <info>  Simple connect state (5/8): Register
Dec 27 00:11:36 469.lan ModemManager[1156]: <info>  Simple connect state (6/8): Bearer
Dec 27 00:11:36 469.lan ModemManager[1156]: <info>  Simple connect state (7/8): Connect
Dec 27 00:11:36 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Dec 27 00:11:36 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Dec 27 00:11:43 469.lan ModemManager[1156]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Dec 27 00:11:43 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Simple connect started...
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Simple connect state (4/8): Wait to get fully enabled
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Simple connect state (5/8): Register
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Simple connect state (6/8): Bearer
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Simple connect state (7/8): Connect
Dec 27 00:11:43 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Dec 27 00:11:43 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Dec 27 00:11:58 469.lan ModemManager[1156]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
Dec 27 00:11:58 469.lan ModemManager[1156]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> registered)
Dec 27 00:11:58 469.lan NetworkManager[1380]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Dec 27 00:11:58 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): failed to connect modem: Sending command failed: 'Resource temporarily unavailable'
Dec 27 00:11:58 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: prepare -> failed (reason 'unknown') [40 120 1]
Dec 27 00:11:58 469.lan NetworkManager[1380]: <info>  NetworkManager state is now DISCONNECTED
Dec 27 00:11:58 469.lan NetworkManager[1380]: <info>  Disabling autoconnect for connection 'HoT'.
Dec 27 00:11:58 469.lan NetworkManager[1380]: <warn>  (ttyUSB2): Activation: failed for connection 'HoT'
Dec 27 00:11:58 469.lan NetworkManager[1380]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Comment 8 Sergey Bostandzhyan 2015-12-10 21:01:04 EST
I made an interesting observation:

today I bought a USB hub and wanted to test it, the closest USB device at hand was the modem. Surprisingly, when the modem was plugged into the USB hub I could connect to the internet via NetworkManager without any problems.

After that I did another test and plugged the modem directly into the notebook and then the internet connection was failing as described in the bug report.

Let me know if you need any logs of that or any further info.
Comment 9 Dan Williams 2015-12-15 10:46:23 EST
What ttyUSBx interface was used for the connection when the device was plugged into the hub?
Comment 10 Sergey Bostandzhyan 2016-01-03 18:15:12 EST
Sorry, I did not realize that my reply was not posted correctly, actually I answered you the same day, but it seems something went wrong, either in my firefox/connection or in bugzilla.

Anyway.

Back then, when I was testing with the USB hub I wanted to recheck regarding what interface was used, to answer your question. To my surprise - it did not work anymore, also not via the hub, this is what I posted back then (the post that got lost).

After I noticed that my answer did not make it to bugzilla I did a retest just now and here are my findings:

the hub itself is not really related to the issue or to the solution, the whole thing is really strange.

I pugged in the modem directly to the notebook and I could immediately go online without any problems via the network manager. I disconnected/connected a couple of times via the NM menu and it all worked just fine.

And here comes the confusing part:

I then unplugged the modem and connected it again at a different USB port - the internet connection did not work anymore. I plugged it back in to the other port where it initially worked - and it also failed there. I guess if I did a fresh boot I'd probably have a one time success again.

I captured the logs. First, plugging in and connecting successfully:

Jan 04 00:02:39 469.lan kernel: usb 1-4: new high-speed USB device number 5 using ehci-pci
Jan 04 00:02:39 469.lan kernel: usb 1-4: New USB device found, idVendor=12d1, idProduct=1446
Jan 04 00:02:39 469.lan kernel: usb 1-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Jan 04 00:02:39 469.lan kernel: usb 1-4: Product: HUAWEI Mobile
Jan 04 00:02:39 469.lan kernel: usb 1-4: Manufacturer: HUAWEI Technology
Jan 04 00:02:39 469.lan kernel: usb-storage 1-4:1.0: USB Mass Storage device detected
Jan 04 00:02:39 469.lan kernel: scsi host33: usb-storage 1-4:1.0
Jan 04 00:02:39 469.lan kernel: usb-storage 1-4:1.1: USB Mass Storage device detected
Jan 04 00:02:39 469.lan kernel: scsi host34: usb-storage 1-4:1.1
Jan 04 00:02:39 469.lan mtp-probe[23434]: checking bus 1, device 5: "/sys/devices/pci0000:00/0000:00:1a.7/usb1/1-4"
Jan 04 00:02:39 469.lan mtp-probe[23434]: bus: 1, device: 5 was not an MTP device
Jan 04 00:02:40 469.lan root[23456]: usb_modeswitch: use overriding config file /etc/usb_modeswitch.d/12d1:1446; make sure this is intended
Jan 04 00:02:40 469.lan root[23457]: usb_modeswitch: please report any new or corrected settings; otherwise, check for outdated files
Jan 04 00:02:40 469.lan usb_modeswitch[23459]: switch device 12d1:1446 on 001/005
Jan 04 00:02:40 469.lan kernel: usb 1-4: USB disconnect, device number 5
Jan 04 00:02:45 469.lan kernel: usb 1-4: new high-speed USB device number 6 using ehci-pci
Jan 04 00:02:45 469.lan kernel: usb 1-4: New USB device found, idVendor=12d1, idProduct=1001
Jan 04 00:02:45 469.lan kernel: usb 1-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Jan 04 00:02:45 469.lan kernel: usb 1-4: Product: HUAWEI Mobile
Jan 04 00:02:45 469.lan kernel: usb 1-4: Manufacturer: HUAWEI Technology
Jan 04 00:02:45 469.lan kernel: usb-storage 1-4:1.0: USB Mass Storage device detected
Jan 04 00:02:45 469.lan kernel: usb-storage 1-4:1.1: USB Mass Storage device detected
Jan 04 00:02:45 469.lan kernel: usb-storage 1-4:1.2: USB Mass Storage device detected
Jan 04 00:02:45 469.lan kernel: usb-storage 1-4:1.3: USB Mass Storage device detected
Jan 04 00:02:45 469.lan kernel: scsi host38: usb-storage 1-4:1.3
Jan 04 00:02:45 469.lan kernel: usb-storage 1-4:1.4: USB Mass Storage device detected
Jan 04 00:02:45 469.lan kernel: scsi host39: usb-storage 1-4:1.4
Jan 04 00:02:45 469.lan root[23474]: usb_modeswitch: switched to 12d1:1001 on 001/006
Jan 04 00:02:46 469.lan kernel: scsi 38:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Jan 04 00:02:46 469.lan kernel: scsi 39:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
Jan 04 00:02:46 469.lan kernel: sr 38:0:0:0: [sr1] scsi-1 drive
Jan 04 00:02:46 469.lan kernel: sr 38:0:0:0: Attached scsi CD-ROM sr1
Jan 04 00:02:46 469.lan kernel: sr 38:0:0:0: Attached scsi generic sg3 type 5
Jan 04 00:02:46 469.lan kernel: sd 39:0:0:0: Attached scsi generic sg4 type 0
Jan 04 00:02:46 469.lan kernel: sd 39:0:0:0: [sdc] Attached SCSI removable disk
Jan 04 00:02:46 469.lan kernel: usbcore: registered new interface driver option
Jan 04 00:02:46 469.lan kernel: usbserial: USB Serial support registered for GSM modem (1-port)
Jan 04 00:02:46 469.lan kernel: option 1-4:1.0: GSM modem (1-port) converter detected
Jan 04 00:02:46 469.lan kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB0
Jan 04 00:02:46 469.lan kernel: option 1-4:1.1: GSM modem (1-port) converter detected
Jan 04 00:02:46 469.lan kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB1
Jan 04 00:02:46 469.lan kernel: option 1-4:1.2: GSM modem (1-port) converter detected
Jan 04 00:02:46 469.lan kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB2
Jan 04 00:02:46 469.lan root[23479]: usb_modeswitch: add device ID 12d1:1001 to driver "option"
Jan 04 00:02:46 469.lan root[23480]: usb_modeswitch: please report the device ID to the Linux USB developers!
Jan 04 00:02:46 469.lan mtp-probe[23492]: checking bus 1, device 6: "/sys/devices/pci0000:00/0000:00:1a.7/usb1/1-4"
Jan 04 00:02:46 469.lan mtp-probe[23492]: bus: 1, device: 6 was not an MTP device
Jan 04 00:02:47 469.lan ModemManager[1393]: <warn>  (ttyUSB1): port attributes not fully set
Jan 04 00:02:47 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:02:47 469.lan ModemManager[1393]: <warn>  (ttyUSB0): port attributes not fully set
Jan 04 00:02:56 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:02:57 469.lan ModemManager[1393]: <warn>  (ttyUSB0): port attributes not fully set
Jan 04 00:02:57 469.lan kernel: sd 39:0:0:0: [sdc] 3854336 512-byte logical blocks: (1.97 GB/1.83 GiB)
Jan 04 00:02:57 469.lan kernel: sd 39:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jan 04 00:02:57 469.lan kernel:  sdc: sdc1 sdc2
Jan 04 00:03:00 469.lan ModemManager[1393]: <info>  Creating modem with plugin 'Generic' and '3' ports
Jan 04 00:03:00 469.lan ModemManager[1393]: <warn>  (ttyUSB0): port attributes not fully set
Jan 04 00:03:00 469.lan ModemManager[1393]: <info>  Modem for device at '/sys/devices/pci0000:00/0000:00:1a.7/usb1/1-4' successfully created
Jan 04 00:03:01 469.lan ModemManager[1393]: <info>  Modem: state changed (unknown -> disabled)
Jan 04 00:03:01 469.lan NetworkManager[1596]: <info>  (ttyUSB0): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Jan 04 00:03:01 469.lan NetworkManager[1596]: <info>  (ttyUSB0): new Broadband device (carrier: UNKNOWN, driver: 'option1', ifindex: 0)
Jan 04 00:03:01 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jan 04 00:03:01 469.lan NetworkManager[1596]: <info>  (ttyUSB0): modem state 'enabling'
Jan 04 00:03:01 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jan 04 00:03:01 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Jan 04 00:03:01 469.lan ModemManager[1393]: <warn>  (ttyUSB0): port attributes not fully set
Jan 04 00:03:01 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:03:01 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
Jan 04 00:03:01 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
Jan 04 00:03:02 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> registered)
Jan 04 00:03:02 469.lan NetworkManager[1596]: <info>  (ttyUSB0): modem state changed, 'enabling' --> 'registered' (reason: user-requested)
Jan 04 00:03:26 469.lan NetworkManager[1596]: <info>  (ttyUSB0): Activation: starting connection 'O2 Internet' (4fc980c2-41ca-409b-9e08-f294058d7e79)
Jan 04 00:03:26 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jan 04 00:03:26 469.lan NetworkManager[1596]: <info>  NetworkManager state is now CONNECTING
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Simple connect started...
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Simple connect state (4/8): Wait to get fully enabled
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Simple connect state (5/8): Register
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Simple connect state (6/8): Bearer
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Simple connect state (7/8): Connect
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jan 04 00:03:26 469.lan NetworkManager[1596]: <info>  (ttyUSB0): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Jan 04 00:03:26 469.lan ModemManager[1393]: <info>  Simple connect state (8/8): All done
Jan 04 00:03:26 469.lan NetworkManager[1596]: <info>  (ttyUSB0): modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Jan 04 00:03:26 469.lan NetworkManager[1596]: <warn>  (ttyUSB0): failed to look up interface index
Jan 04 00:03:26 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: prepare -> config (reason 'none') [40 50 0]
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=mangle family=2 entries=39
Jan 04 00:03:26 469.lan audit[23552]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55c220b48420 items=0 ppid=1396 pid=23552 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006D616E676C65002D690074747955534230002D67005052455F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=mangle family=10 entries=39
Jan 04 00:03:26 469.lan audit[23553]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55d806be4fd0 items=0 ppid=1396 pid=23553 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006D616E676C65002D690074747955534230002D67005052455F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=nat family=2 entries=50
Jan 04 00:03:26 469.lan audit[23554]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5612d4fd1030 items=0 ppid=1396 pid=23554 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900504F5354524F5554494E475F5A4F4E45530031002D74006E6174002D6F0074747955534230002D6700504F53545F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=nat family=10 entries=50
Jan 04 00:03:26 469.lan audit[23555]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=564d14b88f50 items=0 ppid=1396 pid=23555 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900504F5354524F5554494E475F5A4F4E45530031002D74006E6174002D6F0074747955534230002D6700504F53545F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=nat family=2 entries=51
Jan 04 00:03:26 469.lan audit[23556]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55fb423a61b0 items=0 ppid=1396 pid=23556 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006E6174002D690074747955534230002D67005052455F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=nat family=10 entries=51
Jan 04 00:03:26 469.lan audit[23557]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55d0e70a7140 items=0 ppid=1396 pid=23557 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006E6174002D690074747955534230002D67005052455F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=filter family=2 entries=82
Jan 04 00:03:26 469.lan audit[23558]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5593b99da930 items=0 ppid=1396 pid=23558 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900464F52574152445F494E5F5A4F4E45530031002D740066696C746572002D690074747955534230002D6700465744495F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=filter family=10 entries=83
Jan 04 00:03:26 469.lan audit[23559]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=564787a717d0 items=0 ppid=1396 pid=23559 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900464F52574152445F494E5F5A4F4E45530031002D740066696C746572002D690074747955534230002D6700465744495F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=filter family=2 entries=83
Jan 04 00:03:26 469.lan audit[23560]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5604b906eaa0 items=0 ppid=1396 pid=23560 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900494E5055545F5A4F4E45530031002D740066696C746572002D690074747955534230002D6700494E5F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=filter family=10 entries=84
Jan 04 00:03:26 469.lan audit[23561]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=56465ebaf9c0 items=0 ppid=1396 pid=23561 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900494E5055545F5A4F4E45530031002D740066696C746572002D690074747955534230002D6700494E5F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=filter family=2 entries=84
Jan 04 00:03:26 469.lan audit[23562]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5617fc11dc20 items=0 ppid=1396 pid=23562 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900464F52574152445F4F55545F5A4F4E45530031002D740066696C746572002D6F0074747955534230002D67004657444F5F7075626C6963
Jan 04 00:03:26 469.lan audit: NETFILTER_CFG table=filter family=10 entries=85
Jan 04 00:03:26 469.lan audit[23563]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=563d6c6bdbb0 items=0 ppid=1396 pid=23563 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:03:26 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900464F52574152445F4F55545F5A4F4E45530031002D740066696C746572002D6F0074747955534230002D67004657444F5F7075626C6963
Jan 04 00:03:27 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: config -> ip-config (reason 'none') [50 70 0]
Jan 04 00:03:27 469.lan NetworkManager[1596]: <warn>  (ttyUSB0): interface ttyUSB0 not up for IP configuration
Jan 04 00:03:27 469.lan NetworkManager[1596]: <info>  (ttyUSB0): using modem-specified IP timeout: 20 seconds
Jan 04 00:03:27 469.lan NetworkManager[1596]: <info>  starting PPP connection
Jan 04 00:03:27 469.lan NetworkManager[1596]: <info>  pppd started with pid 23564
Jan 04 00:03:27 469.lan NetworkManager[1596]: <info>  (ttyUSB0): IPv6 configuration disabled
Jan 04 00:03:27 469.lan pppd[23564]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Jan 04 00:03:27 469.lan kernel: PPP generic driver version 2.4.2
Jan 04 00:03:27 469.lan pppd[23564]: pppd 2.4.7 started by root, uid 0
Jan 04 00:03:27 469.lan NetworkManager[1596]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Jan 04 00:03:27 469.lan NetworkManager[1596]: Using interface ppp0
Jan 04 00:03:27 469.lan NetworkManager[1596]: Connect: ppp0 <--> /dev/ttyUSB0
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (get_credentials): passwd-hook, requesting credentials...
Jan 04 00:03:27 469.lan pppd[23564]: Using interface ppp0
Jan 04 00:03:27 469.lan pppd[23564]: Connect: ppp0 <--> /dev/ttyUSB0
Jan 04 00:03:27 469.lan NetworkManager[1596]: <info>  (ppp0): new Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 5)
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (get_credentials): got credentials from NetworkManager
Jan 04 00:03:27 469.lan pppd[23564]: CHAP authentication succeeded
Jan 04 00:03:27 469.lan pppd[23564]: CHAP authentication succeeded
Jan 04 00:03:27 469.lan NetworkManager[1596]: CHAP authentication succeeded
Jan 04 00:03:27 469.lan NetworkManager[1596]: CHAP authentication succeeded
Jan 04 00:03:27 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Jan 04 00:03:27 469.lan kernel: PPP BSD Compression module registered
Jan 04 00:03:27 469.lan kernel: PPP Deflate Compression module registered
Jan 04 00:03:29 469.lan pppd[23564]: Could not determine remote IP address: defaulting to 10.64.64.64
Jan 04 00:03:29 469.lan NetworkManager[1596]: Could not determine remote IP address: defaulting to 10.64.64.64
Jan 04 00:03:29 469.lan pppd[23564]: local  IP address 100.121.49.58
Jan 04 00:03:29 469.lan pppd[23564]: remote IP address 10.64.64.64
Jan 04 00:03:29 469.lan pppd[23564]: primary   DNS address 160.218.161.60
Jan 04 00:03:29 469.lan pppd[23564]: secondary DNS address 160.218.167.5
Jan 04 00:03:29 469.lan NetworkManager[1596]: local  IP address 100.121.49.58
Jan 04 00:03:29 469.lan NetworkManager[1596]: remote IP address 10.64.64.64
Jan 04 00:03:29 469.lan NetworkManager[1596]: primary   DNS address 160.218.161.60
Jan 04 00:03:29 469.lan NetworkManager[1596]: secondary DNS address 160.218.167.5
Jan 04 00:03:29 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
Jan 04 00:03:29 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): ip-up event
Jan 04 00:03:29 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): sending IPv4 config to NetworkManager...
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  keyfile: add connection in-memory (952cd8b0-2394-46d3-9f58-690cb722feaa,"ppp0")
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): Activation: starting connection 'ppp0' (952cd8b0-2394-46d3-9f58-690cb722feaa)
Jan 04 00:03:29 469.lan systemd[1]: Starting Network Manager Script Dispatcher Service...
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  PPP manager (IPv4 Config Get) reply received.
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Jan 04 00:03:29 469.lan dbus[1402]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: prepare -> config (reason 'none') [40 50 0]
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: config -> ip-config (reason 'none') [50 70 0]
Jan 04 00:03:29 469.lan dbus[1402]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 04 00:03:29 469.lan systemd[1]: Started Network Manager Script Dispatcher Service.
Jan 04 00:03:29 469.lan audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jan 04 00:03:29 469.lan nm-dispatcher[23604]: Dispatching action 'pre-up' for ppp0
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Jan 04 00:03:29 469.lan nm-dispatcher[23604]: Dispatching action 'pre-up' for ppp0
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ttyUSB0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  NetworkManager state is now CONNECTED_LOCAL
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  Policy set 'ppp0' (ppp0) as default for IPv4 routing and DNS.
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ttyUSB0): Activation: successful, device activated.
Jan 04 00:03:29 469.lan NetworkManager[1596]: <info>  (ppp0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Jan 04 00:03:29 469.lan nm-dispatcher[23604]: Dispatching action 'up' for ppp0
Jan 04 00:03:29 469.lan systemd[1]: iscsi.service: Unit cannot be reloaded because it is inactive.
Jan 04 00:03:29 469.lan nm-dispatcher[23604]: Redirecting to /bin/systemctl restart  ntpd.service
Jan 04 00:03:29 469.lan systemd[1]: Stopping Network Time Service...
Jan 04 00:03:29 469.lan ntpd[14861]: ntpd exiting on signal 15
Jan 04 00:03:29 469.lan audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=ntpd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jan 04 00:03:29 469.lan systemd[1]: Starting Network Time Service...
Jan 04 00:03:29 469.lan ntpd[23651]: ntpd 4.2.6p5@1.2349-o Thu Oct 22 16:09:59 UTC 2015 (1)
Jan 04 00:03:29 469.lan systemd[1]: Started Network Time Service.
Jan 04 00:03:29 469.lan audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=ntpd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jan 04 00:03:29 469.lan ntpd[23652]: proto: precision = 0.698 usec
Jan 04 00:03:29 469.lan ntpd[23652]: 0.0.0.0 c01d 0d kern kernel time sync enabled
Jan 04 00:03:29 469.lan ntpd[23652]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
Jan 04 00:03:29 469.lan ntpd[23652]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Jan 04 00:03:29 469.lan ntpd[23652]: Listen and drop on 1 v6wildcard :: UDP 123
Jan 04 00:03:29 469.lan ntpd[23652]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jan 04 00:03:29 469.lan ntpd[23652]: Listen normally on 3 ppp0 100.121.49.58 UDP 123
Jan 04 00:03:29 469.lan ntpd[23652]: Listen normally on 4 lo ::1 UDP 123
Jan 04 00:03:29 469.lan ntpd[23652]: Listening on routing socket on fd #21 for interface updates
Jan 04 00:03:30 469.lan ntpd[23652]: 0.0.0.0 c016 06 restart
Jan 04 00:03:30 469.lan ntpd[23652]: 0.0.0.0 c012 02 freq_set kernel 6.003 PPM
Jan 04 00:03:30 469.lan ntpd[23652]: 0.0.0.0 c615 05 clock_sync
Jan 04 00:03:40 469.lan audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jan 04 00:03:57 469.lan pppd[23564]: IPV6CP: timeout sending Config-Requests
Jan 04 00:03:57 469.lan NetworkManager[1596]: IPV6CP: timeout sending Config-Requests




And now the attempt after replugging the modem, where the connection fails:

Jan 04 00:06:24 469.lan kernel: usb 2-1: new high-speed USB device number 41 using ehci-pci
Jan 04 00:06:25 469.lan kernel: usb 2-1: New USB device found, idVendor=12d1, idProduct=1446
Jan 04 00:06:25 469.lan kernel: usb 2-1: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Jan 04 00:06:25 469.lan kernel: usb 2-1: Product: HUAWEI Mobile
Jan 04 00:06:25 469.lan kernel: usb 2-1: Manufacturer: HUAWEI Technology
Jan 04 00:06:25 469.lan kernel: usb-storage 2-1:1.0: USB Mass Storage device detected
Jan 04 00:06:25 469.lan kernel: scsi host47: usb-storage 2-1:1.0
Jan 04 00:06:25 469.lan kernel: usb-storage 2-1:1.1: USB Mass Storage device detected
Jan 04 00:06:25 469.lan kernel: scsi host48: usb-storage 2-1:1.1
Jan 04 00:06:25 469.lan mtp-probe[24068]: checking bus 2, device 41: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1"
Jan 04 00:06:25 469.lan mtp-probe[24068]: bus: 2, device: 41 was not an MTP device
Jan 04 00:06:25 469.lan root[24090]: usb_modeswitch: use overriding config file /etc/usb_modeswitch.d/12d1:1446; make sure this is intended
Jan 04 00:06:25 469.lan root[24091]: usb_modeswitch: please report any new or corrected settings; otherwise, check for outdated files
Jan 04 00:06:25 469.lan usb_modeswitch[24093]: switch device 12d1:1446 on 002/041
Jan 04 00:06:25 469.lan kernel: usb 2-1: USB disconnect, device number 41
Jan 04 00:06:29 469.lan kernel: usb 2-1: new high-speed USB device number 42 using ehci-pci
Jan 04 00:06:29 469.lan kernel: usb 2-1: New USB device found, idVendor=12d1, idProduct=1001
Jan 04 00:06:29 469.lan kernel: usb 2-1: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Jan 04 00:06:29 469.lan kernel: usb 2-1: Product: HUAWEI Mobile
Jan 04 00:06:29 469.lan kernel: usb 2-1: Manufacturer: HUAWEI Technology
Jan 04 00:06:29 469.lan kernel: usb-storage 2-1:1.0: USB Mass Storage device detected
Jan 04 00:06:29 469.lan kernel: option 2-1:1.0: GSM modem (1-port) converter detected
Jan 04 00:06:29 469.lan kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB0
Jan 04 00:06:29 469.lan kernel: usb-storage 2-1:1.1: USB Mass Storage device detected
Jan 04 00:06:29 469.lan kernel: option 2-1:1.1: GSM modem (1-port) converter detected
Jan 04 00:06:29 469.lan kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB1
Jan 04 00:06:29 469.lan kernel: usb-storage 2-1:1.2: USB Mass Storage device detected
Jan 04 00:06:29 469.lan kernel: option 2-1:1.2: GSM modem (1-port) converter detected
Jan 04 00:06:29 469.lan kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB2
Jan 04 00:06:29 469.lan kernel: usb-storage 2-1:1.3: USB Mass Storage device detected
Jan 04 00:06:29 469.lan kernel: scsi host52: usb-storage 2-1:1.3
Jan 04 00:06:29 469.lan kernel: usb-storage 2-1:1.4: USB Mass Storage device detected
Jan 04 00:06:29 469.lan kernel: scsi host53: usb-storage 2-1:1.4
Jan 04 00:06:30 469.lan root[24115]: usb_modeswitch: switched to 12d1:1001 on 002/042
Jan 04 00:06:30 469.lan kernel: scsi 52:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Jan 04 00:06:30 469.lan kernel: scsi 53:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
Jan 04 00:06:30 469.lan kernel: sr 52:0:0:0: [sr1] scsi-1 drive
Jan 04 00:06:30 469.lan kernel: sr 52:0:0:0: Attached scsi CD-ROM sr1
Jan 04 00:06:30 469.lan kernel: sr 52:0:0:0: Attached scsi generic sg3 type 5
Jan 04 00:06:30 469.lan kernel: sd 53:0:0:0: Attached scsi generic sg4 type 0
Jan 04 00:06:30 469.lan kernel: sd 53:0:0:0: [sdc] Attached SCSI removable disk
Jan 04 00:06:32 469.lan mtp-probe[24127]: checking bus 2, device 42: "/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1"
Jan 04 00:06:32 469.lan mtp-probe[24127]: bus: 2, device: 42 was not an MTP device
Jan 04 00:06:32 469.lan ModemManager[1393]: <warn>  (ttyUSB1): port attributes not fully set
Jan 04 00:06:32 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:06:41 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:06:42 469.lan kernel: sd 53:0:0:0: [sdc] 3854336 512-byte logical blocks: (1.97 GB/1.83 GiB)
Jan 04 00:06:42 469.lan kernel: sd 53:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jan 04 00:06:42 469.lan kernel:  sdc: sdc1 sdc2
Jan 04 00:06:44 469.lan ModemManager[1393]: <info>  Creating modem with plugin 'Generic' and '3' ports
Jan 04 00:06:44 469.lan ModemManager[1393]: <warn>  Could not grab port (tty/ttyUSB0): 'Cannot add port 'tty/ttyUSB0', unhandled serial type'
Jan 04 00:06:44 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:06:44 469.lan ModemManager[1393]: <info>  Modem for device at '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1' successfully created
Jan 04 00:06:44 469.lan ModemManager[1393]: <info>  Modem: state changed (unknown -> disabled)
Jan 04 00:06:44 469.lan NetworkManager[1596]: <info>  (ttyUSB2): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Jan 04 00:06:44 469.lan NetworkManager[1596]: <info>  (ttyUSB2): new Broadband device (carrier: UNKNOWN, driver: 'option1', ifindex: 0)
Jan 04 00:06:44 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jan 04 00:06:44 469.lan NetworkManager[1596]: <info>  (ttyUSB2): modem state 'enabling'
Jan 04 00:06:44 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jan 04 00:06:44 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (disabled -> enabling)
Jan 04 00:06:44 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:06:45 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: 3GPP Registration state changed (unknown -> registering)
Jan 04 00:06:45 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: 3GPP Registration state changed (registering -> home)
Jan 04 00:06:45 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (enabling -> registered)
Jan 04 00:06:45 469.lan NetworkManager[1596]: <info>  (ttyUSB2): modem state changed, 'enabling' --> 'registered' (reason: user-requested)


Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): Activation: starting connection 'O2 Internet' (4fc980c2-41ca-409b-9e08-f294058d7e79)
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  NetworkManager state is now CONNECTING
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Simple connect started...
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Simple connect state (4/8): Wait to get fully enabled
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Simple connect state (5/8): Register
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Simple connect state (6/8): Bearer
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Simple connect state (7/8): Connect
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (registered -> connecting)
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connecting -> connected)
Jan 04 00:06:57 469.lan ModemManager[1393]: <info>  Simple connect state (8/8): All done
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Jan 04 00:06:57 469.lan NetworkManager[1596]: <warn>  (ttyUSB2): failed to look up interface index
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: prepare -> config (reason 'none') [40 50 0]
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=mangle family=2 entries=40
Jan 04 00:06:57 469.lan audit[24182]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=557d8b34d590 items=0 ppid=1396 pid=24182 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=mangle family=10 entries=40
Jan 04 00:06:57 469.lan audit[24183]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55cb1d9b11c0 items=0 ppid=1396 pid=24183 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=nat family=2 entries=52
Jan 04 00:06:57 469.lan audit[24184]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55e4747fc320 items=0 ppid=1396 pid=24184 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900504F5354524F5554494E475F5A4F4E45530031002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=nat family=10 entries=52
Jan 04 00:06:57 469.lan audit[24185]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55f20a584330 items=0 ppid=1396 pid=24185 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900504F5354524F5554494E475F5A4F4E45530031002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=nat family=2 entries=53
Jan 04 00:06:57 469.lan audit[24186]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5622f84bc4a0 items=0 ppid=1396 pid=24186 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=nat family=10 entries=53
Jan 04 00:06:57 469.lan audit[24187]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55b40787a520 items=0 ppid=1396 pid=24187 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900505245524F5554494E475F5A4F4E45530031002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=filter family=2 entries=85
Jan 04 00:06:57 469.lan audit[24188]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=556693232d90 items=0 ppid=1396 pid=24188 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900464F52574152445F494E5F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=filter family=10 entries=86
Jan 04 00:06:57 469.lan audit[24189]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55d7360f8da0 items=0 ppid=1396 pid=24189 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900464F52574152445F494E5F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=filter family=2 entries=86
Jan 04 00:06:57 469.lan audit[24190]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55d3b0357f10 items=0 ppid=1396 pid=24190 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900494E5055545F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=filter family=10 entries=87
Jan 04 00:06:57 469.lan audit[24191]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55ac88d0ef90 items=0 ppid=1396 pid=24191 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900494E5055545F5A4F4E45530031002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=filter family=2 entries=87
Jan 04 00:06:57 469.lan audit[24192]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=556d5d467080 items=0 ppid=1396 pid=24192 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4900464F52574152445F4F55545F5A4F4E45530031002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Jan 04 00:06:57 469.lan audit: NETFILTER_CFG table=filter family=10 entries=88
Jan 04 00:06:57 469.lan audit[24193]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=5640e620b180 items=0 ppid=1396 pid=24193 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:06:57 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4900464F52574152445F4F55545F5A4F4E45530031002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: config -> ip-config (reason 'none') [50 70 0]
Jan 04 00:06:57 469.lan NetworkManager[1596]: <warn>  (ttyUSB2): interface ttyUSB2 not up for IP configuration
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): using modem-specified IP timeout: 20 seconds
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  starting PPP connection
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  pppd started with pid 24194
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ttyUSB2): IPv6 configuration disabled
Jan 04 00:06:57 469.lan pppd[24194]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Jan 04 00:06:57 469.lan NetworkManager[1596]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Jan 04 00:06:57 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
Jan 04 00:06:57 469.lan pppd[24194]: pppd 2.4.7 started by root, uid 0
Jan 04 00:06:57 469.lan pppd[24194]: Removed stale lock on ttyUSB2 (pid 24021)
Jan 04 00:06:57 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Jan 04 00:06:57 469.lan NetworkManager[1596]: Removed stale lock on ttyUSB2 (pid 24021)
Jan 04 00:06:57 469.lan pppd[24194]: Using interface ppp0
Jan 04 00:06:57 469.lan pppd[24194]: Connect: ppp0 <--> /dev/ttyUSB2
Jan 04 00:06:57 469.lan NetworkManager[1596]: <info>  (ppp0): new Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 8)
Jan 04 00:06:57 469.lan NetworkManager[1596]: Using interface ppp0
Jan 04 00:06:57 469.lan NetworkManager[1596]: Connect: ppp0 <--> /dev/ttyUSB2
Jan 04 00:06:57 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Jan 04 00:07:18 469.lan NetworkManager[1596]: <warn>  pppd timed out or didn't initialize our dbus module
Jan 04 00:07:18 469.lan pppd[24194]: Terminating on signal 15
Jan 04 00:07:18 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Jan 04 00:07:18 469.lan NetworkManager[1596]: <info>  NetworkManager state is now DISCONNECTED
Jan 04 00:07:18 469.lan NetworkManager[1596]: Terminating on signal 15
Jan 04 00:07:18 469.lan NetworkManager[1596]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
Jan 04 00:07:18 469.lan NetworkManager[1596]: <warn>  (ttyUSB2): Activation: failed for connection 'O2 Internet'
Jan 04 00:07:18 469.lan NetworkManager[1596]: <info>  (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Jan 04 00:07:18 469.lan ModemManager[1393]: <info>  Modem /org/freedesktop/ModemManager1/Modem/2: state changed (connected -> disconnecting)
Jan 04 00:07:18 469.lan dbus[1402]: [system] Rejected send message, 9 matched rules; type="error", sender=":1.10" (uid=0 pid=1596 comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.160" (uid=0 pid=24194 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Jan 04 00:07:18 469.lan NetworkManager[1596]: <info>  (ttyUSB2): modem state changed, 'connected' --> 'disconnecting' (reason: user-requested)
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=mangle family=2 entries=41
Jan 04 00:07:18 469.lan audit[24203]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5615fdc4c560 items=0 ppid=1396 pid=24203 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=mangle family=10 entries=41
Jan 04 00:07:18 469.lan audit[24204]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=5642975b8180 items=0 ppid=1396 pid=24204 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006D616E676C65002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=nat family=2 entries=54
Jan 04 00:07:18 469.lan audit[24205]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55f414bca460 items=0 ppid=1396 pid=24205 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400504F5354524F5554494E475F5A4F4E4553002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=nat family=10 entries=54
Jan 04 00:07:18 469.lan audit[24206]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=55ff235854e0 items=0 ppid=1396 pid=24206 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400504F5354524F5554494E475F5A4F4E4553002D74006E6174002D6F0074747955534232002D6700504F53545F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=nat family=2 entries=53
Jan 04 00:07:18 469.lan audit[24207]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55d5bc19b2f0 items=0 ppid=1396 pid=24207 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=nat family=10 entries=53
Jan 04 00:07:18 469.lan audit[24208]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=556ab4dc72f0 items=0 ppid=1396 pid=24208 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400505245524F5554494E475F5A4F4E4553002D74006E6174002D690074747955534232002D67005052455F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=filter family=2 entries=88
Jan 04 00:07:18 469.lan audit[24209]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=555abfd4c050 items=0 ppid=1396 pid=24209 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400464F52574152445F494E5F5A4F4E4553002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=filter family=10 entries=89
Jan 04 00:07:18 469.lan audit[24210]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=5646f1177140 items=0 ppid=1396 pid=24210 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400464F52574152445F494E5F5A4F4E4553002D740066696C746572002D690074747955534232002D6700465744495F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=filter family=2 entries=87
Jan 04 00:07:18 469.lan audit[24211]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=5568b7486ed0 items=0 ppid=1396 pid=24211 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400494E5055545F5A4F4E4553002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=filter family=10 entries=88
Jan 04 00:07:18 469.lan audit[24212]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=559338642f50 items=0 ppid=1396 pid=24212 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400494E5055545F5A4F4E4553002D740066696C746572002D690074747955534232002D6700494E5F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=filter family=2 entries=86
Jan 04 00:07:18 469.lan audit[24213]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=0 a2=40 a3=55c344e20d60 items=0 ppid=1396 pid=24213 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F69707461626C6573002D77002D4400464F52574152445F4F55545F5A4F4E4553002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Jan 04 00:07:18 469.lan audit: NETFILTER_CFG table=filter family=10 entries=87
Jan 04 00:07:18 469.lan audit[24214]: SYSCALL arch=c000003e syscall=54 success=yes exit=0 a0=4 a1=29 a2=40 a3=56515ddead60 items=0 ppid=1396 pid=24214 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip6tables" exe="/usr/sbin/xtables-multi" key=(null)
Jan 04 00:07:18 469.lan audit: PROCTITLE proctitle=2F7362696E2F6970367461626C6573002D77002D4400464F52574152445F4F55545F5A4F4E4553002D740066696C746572002D6F0074747955534232002D67004657444F5F7075626C6963
Jan 04 00:07:19 469.lan ModemManager[1393]: <warn>  (ttyUSB2): port attributes not fully set
Jan 04 00:07:20 469.lan NetworkManager[1596]: <warn>  (ppp0): failed to disable userspace IPv6LL address handling


Does that make any sense?
Comment 11 Lubomir Rintel 2016-07-27 03:23:26 EDT
There different problems here.

The device is not connected to the network initially:

> Nov 12 14:43:52 469.lan NetworkManager[1410]: <warn>  (ttyUSB2): failed to connect modem: No cause information available
> Nov 12 14:43:52 469.lan NetworkManager[1410]: <info>  (ttyUSB2): device state change: prepare -> failed (reason 'modem-no-carrier') [40 120 25]

The second attempt looks alright, but times out waiting for the IP address via IPCP. Not sure why that happens:

> Nov 12 15:03:34 469.lan NetworkManager[13343]: <warn>  pppd timed out or didn't initialize our dbus module
> Nov 12 15:03:34 469.lan pppd[13472]: Terminating on signal 15

Not sure what went wrong here either...

> Nov 12 15:04:59 469.lan ModemManager[13268]: <warn>  Couldn't initialize PDP context with our APN: 'Sending command failed: 'Resource temporarily unavailable''
> Nov 12 15:04:59 469.lan ModemManager[13268]: <info>  Modem /org/freedesktop/ModemManager1/Modem/1: state changed (connecting -> registered)
> Nov 12 15:04:59 469.lan NetworkManager[13343]: <info>  (ttyUSB2): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
> Nov 12 15:04:59 469.lan NetworkManager[13343]: <warn>  (ttyUSB2): failed to connect modem: Sending command failed: 'Resource temporarily unavailable'

I'm wondering if you could retest with the updated packages from here:
https://bodhi.fedoraproject.org/updates/FEDORA-2016-494a721a73

Thank you,
Lubo
Comment 12 Sergey Bostandzhyan 2016-08-08 11:57:56 EDT
Hi Lubo,

I could check that in September, I am currently traveling and I do not have this modem with me. I eventually got frustrated with the breakage and bought a modem that does the mobile internet part itself and that presents itself as a WiFi gateway ;)

I'll get back to you mid-september, that's when I will have access to the modem from the bug report again.
Comment 13 Lubomir Rintel 2016-10-04 10:12:03 EDT
Any chance you could have a look?

The updated package made it to the updates repository since.
Comment 14 Sergey Bostandzhyan 2016-10-04 10:17:05 EDT
Sorry for not getting back to you earlier, I indeed returned recently and have the modem here. However, in the meantime I moved to Fedora 24, but I assume this is not a problem, I guess the updated package made it there as well?

I will test the modem tonight and let you know if it works now (just beware that it's not on Fedora 23 anymore...)
Comment 15 Sergey Bostandzhyan 2016-10-04 15:33 EDT
Created attachment 1207329 [details]
log output of journalctl -f while attempting to connect to the internet

So, here is the log.

I started ModemManager with DEBUG loglevel and saved the journalctl output.

What I did:

attached the modem
waited for it to show the available network
attempted to establish a connection (it failed)
attempted to establish a connection again (it failed)
removed the modem


The only thing removed from the log is the SMS readout/dump.

The above was done on Fedora 24, ModemManager-1.6.0-1.fc24.x86_64
Comment 16 Dan Williams 2016-10-04 16:57:40 EDT
Oct 04 21:18:03 469.lan pppd[21242]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Oct 04 21:18:03 469.lan NetworkManager[1648]: Plugin /usr/lib64/pppd/2.4.7/nm-pppd-plugin.so loaded.
Oct 04 21:18:03 469.lan NetworkManager[1648]: nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
Oct 04 21:18:03 469.lan pppd[21242]: pppd 2.4.7 started by root, uid 0
Oct 04 21:18:03 469.lan NetworkManager[1648]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Oct 04 21:18:03 469.lan pppd[21242]: Baud rate for /dev/ttyUSB0 is 0; need explicit baud rate
Oct 04 21:18:03 469.lan NetworkManager[1648]: Baud rate for /dev/ttyUSB0 is 0; need explicit baud rate
Oct 04 21:18:04 469.lan NetworkManager[1648]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_exit_notify): cleaning up

Looks like pppd complains because the port doesn't have a speed set.  Which is odd, since ModemManager defaults to 57600, and with USB the baud rate actually doesn't matter at all.

Could you report the output of "stty -F /dev/ttyUSB0":

1) before you try to connect
2) after the connect fails

Thanks!
Comment 17 Sergey Bostandzhyan 2016-10-05 03:04:19 EDT
Before:
$ stty -F /dev/ttyUSB0 
speed 0 baud; line = 0;
eof = ^A; min = 1; time = 0;
ignbrk -brkint -icrnl ixoff ixany -imaxbel
-opost -onlcr
-isig -icanon -iexten -echo -echoe

After:
$ stty -F /dev/ttyUSB0 
speed 0 baud; line = 0;
eof = ^A; min = 1; time = 0;
ignbrk -brkint -icrnl ixoff ixany -imaxbel
-opost -onlcr
-isig -icanon -iexten -echo -echoe

So actually same output before and after the failed connection.
Comment 18 Dan Williams 2016-10-05 08:33:04 EDT
Thanks; the serial port likely just doesn't care about baudrate, but pppd does.  What if you:

nmcli con mod HoT serial.baud 57600

and then retry the connection?  That may make pppd happy.
Comment 19 Sergey Bostandzhyan 2016-10-06 03:57:13 EDT
Tried it, indeed, this worked, after the above command I could initiate the connection without any problems.
Comment 20 Fedora End Of Life 2016-11-24 08:22:14 EST
This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '23'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 23 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.
Comment 21 Fedora End Of Life 2016-12-20 10:48:44 EST
Fedora 23 changed to end-of-life (EOL) status on 2016-12-20. Fedora 23 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Note You need to log in before you can comment on or make changes to this bug.