Bug 568078

Summary:	Upgrading from ppp-2.4.4 to 2.4.5 broke Sprint EVDO USB modem - Novatel U727
Product:	[Fedora] Fedora	Reporter:	Ravi Srinivasan <ravishankar.srinivasan>
Component:	ppp	Assignee:	Jiri Skala <jskala>
Status:	CLOSED DUPLICATE	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	low
Version:	12	CC:	aglotov, jskala
Target Milestone:	---
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2010-02-25 07:43:33 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Ravi Srinivasan 2010-02-24 18:20:37 UTC

Description of problem:
Did a yum update on Feb 24 and saw that ppp has updates to 2.4.5.currently running F12 x86_64 with ppp-2.4.4.

Using a Sprint Novatel U727 USB EVDO modem with the usb_modeset approach to get the modem work out of the box with Network Manager. working flawlessly until the update. I can;t think of any other package in the list that can cause the modem to fail. here is what my yum update looks like

--> Running transaction check
---> Package cronie.x86_64 0:1.4.3-4.fc12 set to be updated
---> Package cronie-anacron.x86_64 0:1.4.3-4.fc12 set to be updated
---> Package ppp.x86_64 0:2.4.5-2.fc12 set to be updated
---> Package soprano.x86_64 0:2.4.0.1-1.fc12 set to be updated
--> Processing Dependency: virtuoso-opensource for package: soprano-2.4.0.1-1.fc12.x86_64
--> Processing Dependency: libiodbc.so.2()(64bit) for package: soprano-2.4.0.1-1.fc12.x86_64
--> Running transaction check
---> Package libiodbc.x86_64 0:3.52.7-1.fc12 set to be updated
---> Package virtuoso-opensource.x86_64 0:6.1.0-2.fc12 set to be updated
--> Finished Dependency Resolution

Dependencies Resolved

=================================================================================================================================================================================
 Package                                           Arch                                 Version                                      Repository                             Size
=================================================================================================================================================================================
Updating:
 cronie                                            x86_64                               1.4.3-4.fc12                                 updates                                68 k
 cronie-anacron                                    x86_64                               1.4.3-4.fc12                                 updates                                27 k
 ppp                                               x86_64                               2.4.5-2.fc12                                 updates                               323 k
 soprano                                           x86_64                               2.4.0.1-1.fc12                               updates                               625 k
Installing for dependencies:
 libiodbc                                          x86_64                               3.52.7-1.fc12                                fedora                                168 k
 virtuoso-opensource                               x86_64                               6.1.0-2.fc12                                 updates                               3.6 M

Transaction Summary
=================================================================================================================================================================================
Install       2 Package(s)
Upgrade       4 Package(s)



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

ppp-2.4.5 in F12 updates

How reproducible:
Apply the latest updates to F12. Novatel U727 unable to connect. roll back using yum history undo. modem able to connect

Steps to Reproduce:
1.
2.
3.
  
Actual results:
Not able to connect via the U727 modem. kernel msg:

Feb 24 09:57:22 localhost NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Sprint connection 1'
Feb 24 09:57:22 localhost NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
Feb 24 09:57:22 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Feb 24 09:57:22 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Feb 24 09:57:22 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Feb 24 09:57:22 localhost modem-manager: (ttyUSB0) opening serial device...
Feb 24 09:57:22 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabled -> enabling)
Feb 24 09:57:22 localhost modem-manager: Your CDMA modem does not support +CMEE command
Feb 24 09:57:22 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabling -> enabled)
Feb 24 09:57:22 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabled -> registered)
Feb 24 09:57:22 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
Feb 24 09:57:23 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Feb 24 09:57:23 localhost NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
Feb 24 09:57:23 localhost NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
Feb 24 09:57:23 localhost NetworkManager: <info>  Starting pppd connection
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
Feb 24 09:57:23 localhost pppd[3074]: Warning: can't open options file /root/.ppprc: Permission denied
Feb 24 09:57:23 localhost pppd[3074]: Plugin /usr/lib64/pppd/2.4.4/nm-pppd-plugin.so is for pppd version 2.4.4, this is 2.4.5
Feb 24 09:57:23 localhost NetworkManager: <WARN>  ppp_exit_code(): ppp pid 3074 exited with error: pppd options error
Feb 24 09:57:23 localhost NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 9 (reason 14)
Feb 24 09:57:23 localhost NetworkManager: <info>  Marking connection 'Sprint connection 1' invalid.
Feb 24 09:57:23 localhost NetworkManager: <info>  Activation (ttyUSB0) failed.
Feb 24 09:57:23 localhost NetworkManager: <info>  (ttyUSB0): device state change: 9 -> 3 (reason 0)
Feb 24 09:57:23 localhost NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 0).
Feb 24 09:57:23 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
Feb 24 09:57:23 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> disabling)
Feb 24 09:57:23 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabling -> disconnecting)
Feb 24 09:57:24 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> registered)
Feb 24 09:57:24 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> disabling)
Feb 24 09:57:24 localhost modem-manager: (ttyUSB0) closing serial device...
Feb 24 09:57:24 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabling -> disabled)


Expected results:

Connection to internet via U727 modem

Additional info:

A valid connection sequence results in the following messages in the kernel log

Feb 24 10:06:29 localhost kernel: usb 5-1: new full speed USB device using uhci_hcd and address 4
Feb 24 10:06:29 localhost kernel: usb 5-1: New USB device found, idVendor=1410, idProduct=5010
Feb 24 10:06:29 localhost kernel: usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=4
Feb 24 10:06:29 localhost kernel: usb 5-1: Product: Novatel Wireless CDMA
Feb 24 10:06:29 localhost kernel: usb 5-1: Manufacturer: Novatel Wireless Inc.
Feb 24 10:06:29 localhost kernel: usb 5-1: SerialNumber: 091050709430000
Feb 24 10:06:29 localhost kernel: usb 5-1: configuration #1 chosen from 1 choice
Feb 24 10:06:29 localhost kernel: scsi7 : SCSI emulation for USB Mass Storage devices
Feb 24 10:06:29 localhost usb-modeswitch: switching 1410:5010 (Novatel Wireless Inc.: Novatel Wireless CDMA)
Feb 24 10:06:30 localhost kernel: usb 5-1: USB disconnect, address 4
Feb 24 10:06:32 localhost kernel: usb 5-1: new full speed USB device using uhci_hcd and address 5
Feb 24 10:06:32 localhost kernel: usb 5-1: New USB device found, idVendor=1410, idProduct=4100
Feb 24 10:06:32 localhost kernel: usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=4
Feb 24 10:06:32 localhost kernel: usb 5-1: Product: Novatel Wireless CDMA
Feb 24 10:06:32 localhost kernel: usb 5-1: Manufacturer: Novatel Wireless Inc.
Feb 24 10:06:32 localhost kernel: usb 5-1: SerialNumber: 091050709431000
Feb 24 10:06:32 localhost kernel: usb 5-1: configuration #1 chosen from 1 choice
Feb 24 10:06:32 localhost kernel: option 5-1:1.0: GSM modem (1-port) converter detected
Feb 24 10:06:32 localhost kernel: usb 5-1: GSM modem (1-port) converter now attached to ttyUSB0
Feb 24 10:06:32 localhost kernel: option 5-1:1.1: GSM modem (1-port) converter detected
Feb 24 10:06:32 localhost kernel: usb 5-1: GSM modem (1-port) converter now attached to ttyUSB1
Feb 24 10:06:32 localhost kernel: option 5-1:1.2: GSM modem (1-port) converter detected
Feb 24 10:06:32 localhost kernel: usb 5-1: GSM modem (1-port) converter now attached to ttyUSB2
Feb 24 10:06:32 localhost kernel: option 5-1:1.3: GSM modem (1-port) converter detected
Feb 24 10:06:32 localhost kernel: usb 5-1: GSM modem (1-port) converter now attached to ttyUSB3
Feb 24 10:06:32 localhost kernel: scsi8 : SCSI emulation for USB Mass Storage devices
Feb 24 10:06:32 localhost modem-manager: (ttyUSB0) opening serial device...
Feb 24 10:06:32 localhost modem-manager: (ttyUSB3) opening serial device...
Feb 24 10:06:32 localhost modem-manager: (ttyUSB1) opening serial device...
Feb 24 10:06:32 localhost modem-manager: (ttyUSB2) opening serial device...
Feb 24 10:06:32 localhost usb-modeswitch: switched to 1410:4100 (Novatel Wireless Inc.: Novatel Wireless CDMA)
Feb 24 10:06:35 localhost modem-manager: (ttyUSB0) closing serial device...
Feb 24 10:06:35 localhost modem-manager: (Novatel): CDMA modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-1 claimed port ttyUSB0
Feb 24 10:06:35 localhost NetworkManager: <info>  (ttyUSB0): new CDMA device (driver: 'option1')
Feb 24 10:06:35 localhost NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/3
Feb 24 10:06:35 localhost NetworkManager: <info>  (ttyUSB0): now managed
Feb 24 10:06:35 localhost NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2 (reason 2)
Feb 24 10:06:35 localhost NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2).
Feb 24 10:06:35 localhost NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3 (reason 0)
Feb 24 10:06:37 localhost kernel: scsi 8:0:0:0: Direct-Access     Novatel  MMC Storage      2.31 PQ: 0 ANSI: 2
Feb 24 10:06:37 localhost kernel: sd 8:0:0:0: Attached scsi generic sg2 type 0
Feb 24 10:06:37 localhost kernel: sd 8:0:0:0: [sdb] Attached SCSI removable disk
Feb 24 10:06:41 localhost NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Sprint connection 1'
Feb 24 10:06:41 localhost NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
Feb 24 10:06:41 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Feb 24 10:06:41 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Feb 24 10:06:41 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Feb 24 10:06:41 localhost modem-manager: (ttyUSB0) opening serial device...
Feb 24 10:06:41 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (disabled -> enabling)
Feb 24 10:06:41 localhost modem-manager: Your CDMA modem does not support +CMEE command
Feb 24 10:06:41 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabling -> enabled)
Feb 24 10:06:41 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabled -> registered)
Feb 24 10:06:41 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (registered -> connecting)
Feb 24 10:06:43 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (connecting -> connected)
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Feb 24 10:06:43 localhost NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
Feb 24 10:06:43 localhost NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
Feb 24 10:06:43 localhost NetworkManager: <info>  Starting pppd connection
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
Feb 24 10:06:43 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
Feb 24 10:06:43 localhost pppd[3682]: Warning: can't open options file /root/.ppprc: Permission denied
Feb 24 10:06:43 localhost pppd[3682]: Plugin /usr/lib64/pppd/2.4.4/nm-pppd-plugin.so loaded.
Feb 24 10:06:43 localhost kernel: PPP generic driver version 2.4.2
Feb 24 10:06:43 localhost pppd[3682]: pppd 2.4.4 started by root, uid 0
Feb 24 10:06:43 localhost pppd[3682]: Using interface ppp0
Feb 24 10:06:43 localhost pppd[3682]: Connect: ppp0 <--> /dev/ttyUSB0
Feb 24 10:06:44 localhost kernel: PPP Deflate Compression module registered
Feb 24 10:06:44 localhost dnsmasq[1696]: no servers found in /etc/resolv.conf, will retry
Feb 24 10:06:44 localhost pppd[3682]: local  IP address 70.6.24.23
Feb 24 10:06:44 localhost pppd[3682]: remote IP address 68.28.49.85
Feb 24 10:06:44 localhost pppd[3682]: primary   DNS address 68.28.50.91
Feb 24 10:06:44 localhost pppd[3682]: secondary DNS address 68.28.58.92
Feb 24 10:06:44 localhost NetworkManager: <info>  PPP manager(IP Config Get) reply received.
Feb 24 10:06:44 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Feb 24 10:06:44 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) started...
Feb 24 10:06:44 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
Feb 24 10:06:44 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) complete.
Feb 24 10:06:44 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
Feb 24 10:06:45 localhost modem-manager: (ttyUSB3) closing serial device...
Feb 24 10:06:45 localhost NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8 (reason 0)
Feb 24 10:06:45 localhost dnsmasq[1696]: reading /etc/resolv.conf
Feb 24 10:06:45 localhost dnsmasq[1696]: using nameserver 68.28.58.92#53
Feb 24 10:06:45 localhost dnsmasq[1696]: using nameserver 68.28.50.91#53
Feb 24 10:06:45 localhost NetworkManager: <info>  Policy set 'Sprint connection 1' (ppp0) as default for routing and DNS.
Feb 24 10:06:45 localhost NetworkManager: <info>  Activation (ttyUSB0) successful, device activated.
Feb 24 10:06:45 localhost NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete.
Feb 24 10:06:45 localhost ntpd[1543]: Listening on interface #10 ppp0, 70.6.24.23#123 Enabled
Feb 24 10:06:46 localhost modem-manager: (ttyUSB1) closing serial device...
Feb 24 10:06:47 localhost modem-manager: (ttyUSB2) closing serial device...

Comment 1 Ravi Srinivasan 2010-02-24 19:50:48 UTC

confirmed issue is in ppp. I selectively updated all the other packages and my yum update now looks like this:

[ravis@cosminexus ~]$ sudo yum update
Loaded plugins: fastestmirror, presto, refresh-packagekit
Loading mirror speeds from cached hostfile
 * fedora: mirror.web-ster.com
 * livna: rpm.livna.org
 * rpmfusion-free: mirror.web-ster.com
 * rpmfusion-free-updates: mirror.web-ster.com
 * rpmfusion-nonfree: mirror.web-ster.com
 * rpmfusion-nonfree-updates: mirror.web-ster.com
 * updates: mirror.web-ster.com
Setting up Update Process
Resolving Dependencies
--> Running transaction check
---> Package ppp.x86_64 0:2.4.5-2.fc12 set to be updated
--> Finished Dependency Resolution

Dependencies Resolved

=================================================================================================================================================================================
 Package                               Arch                                     Version                                          Repository                                 Size
=================================================================================================================================================================================
Updating:
 ppp                                   x86_64                                   2.4.5-2.fc12                                     updates                                   323 k

Transaction Summary
=================================================================================================================================================================================
Install       0 Package(s)
Upgrade       1 Package(s)

Total download size: 323 k
Is this ok [y/N]:

Comment 2 Jiri Skala 2010-02-25 07:43:33 UTC


*** This bug has been marked as a duplicate of bug 568177 ***