Problem connecting with a 3G ZTE USB Modem

[paquete]

Hello.

I'm currently using Fedora 17 and trying to connect to a 3G network using a ZTE USB Modem.
The modem worked very well in a previous Fedora 16 installation and still does on Windows. Modem configuration seems fine and it even recognizes the carrier's network and signal strength.

But when I try to connect, it fails without a cause.
Reviewing /var/log/messages I came across the log lines attached at the bottom of this message. Authentication succeeds and then:

NetworkManager[642]: PAP authentication succeeded
pppd[1741]: Modem hangup
pppd[1741]: Connection terminated.

If useful, I also have the log when the modem is plugged, unblocked and enabled.
Any help would be deeply appreciated.

Thanks.

Jun 27 15:22:47 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) starting connection 'Ancel ADSL Móvil'
Jun 27 15:22:47 paquete-laptop NetworkManager[642]: <info> (ttyUSB3): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jun 27 15:22:47 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 1 of 5 (Device Prepare) scheduled...
Jun 27 15:22:47 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 1 of 5 (Device Prepare) started...
Jun 27 15:22:47 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 1 of 5 (Device Prepare) complete.
Jun 27 15:22:47 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> searching)
Jun 27 15:22:47 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> searching)
Jun 27 15:22:47 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (searching -> registered)
Jun 27 15:22:47 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (searching -> registered)
Jun 27 15:22:47 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> searching)
Jun 27 15:22:47 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> searching)
Jun 27 15:22:47 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (searching -> registered)
Jun 27 15:22:47 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (searching -> registered)
Jun 27 15:22:48 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
Jun 27 15:22:48 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
Jun 27 15:22:48 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
Jun 27 15:22:48 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 2 of 5 (Device Configure) scheduled...
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 2 of 5 (Device Configure) starting...
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> (ttyUSB3): device state change: prepare -> config (reason 'none') [40 50 0]
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 2 of 5 (Device Configure) successful.
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 3 of 5 (IP Configure Start) scheduled.
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 2 of 5 (Device Configure) complete.
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 3 of 5 (IP Configure Start) started...
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> (ttyUSB3): device state change: config -> ip-config (reason 'none') [50 70 0]
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> starting PPP connection
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> pppd started with pid 1741
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 3 of 5 (IP Configure Start) complete.
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 4 of 5 (IPv6 Configure Timeout) started...
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Jun 27 15:22:48 paquete-laptop pppd[1741]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Jun 27 15:22:48 paquete-laptop kernel: [  269.562450] PPP generic driver version 2.4.2
Jun 27 15:22:48 paquete-laptop pppd[1741]: pppd 2.4.5 started by root, uid 0
Jun 27 15:22:48 paquete-laptop pppd[1741]: Using interface ppp0
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: Using interface ppp0
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: Connect: ppp0 <--> /dev/ttyUSB3
Jun 27 15:22:48 paquete-laptop pppd[1741]: Connect: ppp0 <--> /dev/ttyUSB3
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
Jun 27 15:22:48 paquete-laptop pppd[1741]: PAP authentication succeeded
Jun 27 15:22:48 paquete-laptop NetworkManager[642]: PAP authentication succeeded
Jun 27 15:22:54 paquete-laptop pppd[1741]: Modem hangup
Jun 27 15:22:54 paquete-laptop pppd[1741]: Connection terminated.
Jun 27 15:22:54 paquete-laptop avahi-daemon[659]: Withdrawing workstation service for ppp0.
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 4 of 5 (IPv4 Configure Timeout) started...
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> (ttyUSB3): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <warn> Activation (ttyUSB3) failed.
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> Activation (ttyUSB3) Stage 4 of 5 (IPv4 Configure Timeout) complete.
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> (ttyUSB3): device state change: failed -> disconnected (reason 'none') [120 30 0]
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> (ttyUSB3): deactivating device (reason 'none') [0]
Jun 27 15:22:54 paquete-laptop modem-manager[762]: <info>  (ttyUSB3) closing serial port...
Jun 27 15:22:54 paquete-laptop modem-manager[762]: <info>  (ttyUSB3) serial port closed
Jun 27 15:22:54 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
Jun 27 15:22:54 paquete-laptop modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> Policy set 'System em1' (em1) as default for IPv4 routing and DNS.
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> Policy set 'System em1' (em1) as default for IPv4 routing and DNS.
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: <info> disconnect failed: (32) The serial port is not open.
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: Modem hangup
Jun 27 15:22:54 paquete-laptop NetworkManager[642]: Connection terminated.
Jun 27 15:22:54 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  (ttyUSB3) closing serial port...
Jun 27 15:22:54 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  (ttyUSB3) serial port closed
Jun 27 15:22:54 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
Jun 27 15:22:54 paquete-laptop dbus-daemon[712]: modem-manager[762]: <info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
Jun 27 15:22:55 paquete-laptop pppd[1741]: Exit.
Jun 27 15:22:55 paquete-laptop dbus-daemon[712]: dbus[712]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=642 comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.77" (uid=0 pid=1741 comm="/usr/sbin/pppd nodetach lock nodefaultroute user i")
Jun 27 15:22:55 paquete-laptop dbus[712]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=642 comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.77" (uid=0 pid=1741 comm="/usr/sbin/pppd nodetach lock nodefaultroute user i")

[claudio4j]

The issue for me is the very similar. However the /var/log/message is a bit different. Did you manage to solve it ?

paquete, can you upload the output of "rpm -qa|sort " ? I want to see if there is some missing packages.

pppd connects, but it could not determine the device driver. See below

See full log for details.

Jul 30 15:46:14 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) starting connection 'Vivo 3G'
Jul 30 15:46:14 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jul 30 15:46:14 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled...
Jul 30 15:46:14 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started...
Jul 30 15:46:14 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: prepare -> need-auth (reason 'none') [40 60 0]
Jul 30 15:46:14 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete.
Jul 30 15:46:18 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled...
Jul 30 15:46:18 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started...
Jul 30 15:46:18 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Jul 30 15:46:18 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete.
Jul 30 15:46:18 zhukov modem-manager[667]: <info>  (ttyUSB2) opening serial port...
Jul 30 15:46:18 zhukov dbus-daemon[631]: modem-manager[667]: <info>  (ttyUSB2) opening serial port...
Jul 30 15:46:18 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Jul 30 15:46:18 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Jul 30 15:46:18 zhukov dbus-daemon[631]: modem-manager[667]: <info>  (ttyUSB1) opening serial port...
Jul 30 15:46:18 zhukov modem-manager[667]: <info>  (ttyUSB1) opening serial port...
Jul 30 15:46:19 zhukov dbus-daemon[631]: modem-manager[667]: <info>  (ttyUSB2): using text mode for SMS
Jul 30 15:46:19 zhukov modem-manager[667]: <info>  (ttyUSB2): using text mode for SMS
Jul 30 15:46:19 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> enabled)
Jul 30 15:46:19 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> enabled)
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> WWAN now enabled by management service
Jul 30 15:46:19 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabled -> registered)
Jul 30 15:46:19 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabled -> registered)
Jul 30 15:46:19 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (registered -> connecting)
Jul 30 15:46:19 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (registered -> connecting)
Jul 30 15:46:19 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (connecting -> connected)
Jul 30 15:46:19 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (connecting -> connected)
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) scheduled...
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) starting...
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: prepare -> config (reason 'none') [40 50 0]
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) successful.
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) scheduled.
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) complete.
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) started...
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: config -> ip-config (reason 'none') [50 70 0]
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> starting PPP connection
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> pppd started with pid 14699
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) complete.
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) started...
Jul 30 15:46:19 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Jul 30 15:46:19 zhukov pppd[14699]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Jul 30 15:46:19 zhukov NetworkManager[602]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Jul 30 15:46:19 zhukov pppd[14699]: pppd 2.4.5 started by root, uid 0
Jul 30 15:46:19 zhukov pppd[14699]: Removed stale lock on ttyUSB2 (pid 14577)
Jul 30 15:46:19 zhukov NetworkManager[602]: Removed stale lock on ttyUSB2 (pid 14577)
Jul 30 15:46:19 zhukov pppd[14699]: Using interface ppp0
Jul 30 15:46:19 zhukov pppd[14699]: Connect: ppp0 <--> /dev/ttyUSB2
Jul 30 15:46:19 zhukov NetworkManager[602]: Using interface ppp0
Jul 30 15:46:19 zhukov NetworkManager[602]: Connect: ppp0 <--> /dev/ttyUSB2
Jul 30 15:46:19 zhukov NetworkManager[602]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
Jul 30 15:46:39 zhukov NetworkManager[602]: <warn> pppd timed out or didn't initialize our dbus module
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv4 Configure Timeout) started...
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Jul 30 15:46:39 zhukov NetworkManager[602]: <warn> Activation (ttyUSB2) failed.
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv4 Configure Timeout) complete.
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0]
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> (ttyUSB2): deactivating device (reason 'none') [0]
Jul 30 15:46:39 zhukov modem-manager[667]: <info>  (ttyUSB2) closing serial port...
Jul 30 15:46:39 zhukov modem-manager[667]: <info>  (ttyUSB2) serial port closed
Jul 30 15:46:39 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (connected -> disconnecting)
Jul 30 15:46:39 zhukov modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (disconnecting -> connected)
Jul 30 15:46:39 zhukov dbus[631]: [system] Rejected send message, 11 matched rules; type="error", sender=":1.16" (uid=1000 pid=1091 comm="kded4 ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=602 comm="/usr/sbin/NetworkManager --no-daemon ")
Jul 30 15:46:39 zhukov NetworkManager[602]: <info> disconnect failed: (32) The serial port is not open.
Jul 30 15:46:39 zhukov dbus-daemon[631]: modem-manager[667]: <info>  (ttyUSB2) closing serial port...
Jul 30 15:46:39 zhukov dbus-daemon[631]: modem-manager[667]: <info>  (ttyUSB2) serial port closed
Jul 30 15:46:39 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (connected -> disconnecting)
Jul 30 15:46:39 zhukov dbus-daemon[631]: modem-manager[667]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (disconnecting -> connected)
Jul 30 15:46:39 zhukov dbus-daemon[631]: dbus[631]: [system] Rejected send message, 11 matched rules; type="error", sender=":1.16" (uid=1000 pid=1091 comm="kded4 ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=602 comm="/usr/sbin/NetworkManager --no-daemon ")

[claudio4j]

I managed to solve my issue.

The connection was marked as "system connection" in connection management (NetworkManager), then I disabled it. It works.

Looks like the message "/sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring" is no harm.