Re: NM cell reconnect fails until PCMCIA eject/insert

[Dan Williams <dcbw redhat com>]

On Wed, 2010-06-30 at 06:15 -0700, David L wrote:
> I have a Verizon PCMCIA card I'm using with NM in Fedora 13.
> The same card seemed to work better in the location last
> summer with Fedora 11.  I'm getting disconnected more frequently
> now and after disconnects, I have often have to eject and reinsert
> the modem to re-establish the connection.  Below is an example
> output from /var/log/messages.
> 
> Any ideas why the cell is disconnecting or why it won't reconnect
> without ejecting the PCMCIA card?  Also, is there a way to get a
> history of cell signal strength so I can maybe find a better place
> to locate the laptop?

What specific card?  Can you grab 'lsusb' and 'lsusb -v' output for me
when the card is plugged in and (if needed) modeswitched into modem
mode?

Next, can you get some debug logging from ModemManager about why the
modem fails to reconnect successfully when you pick the connection again
from the menu?

1) service NetworkManager stop
2) killall -TERM modem-manager
3) modem-manager --debug
4) NM_PPP_DEBUG=1 NetworkManager --no-daemon

(1 - 3 in one root terminal, and #4 in a second root terminal)

then lets see what we get from both the modem-manager and NM debug
output.

Unfortunately it's not really possible to tell *why* the connection died
without getting information directly from the baseband inside the modem,
which probably means using the proprietary QCDM protocol to get that
status info, and we haven't reverse-engineered the event/logging system
there yet.  But hopefully we get to that point...  There could be any
number of reasons why the call disconnected, from hard handoff to
momentary signal strength dropoff to internal card errors.

Dan

> Thanks in advance.
> 
>               David
> 
> Jun 30 04:31:55 localhost pppd[9921]: LCP terminated by peer
> Jun 30 04:31:55 localhost pppd[9921]: Connect time 20.6 minutes.
> Jun 30 04:31:55 localhost pppd[9921]: Sent 273109 bytes, received 1669735 bytes.
> Jun 30 04:31:55 localhost pppd[9921]: Modem hangup
> Jun 30 04:31:55 localhost pppd[9921]: Connection terminated.
> Jun 30 04:31:55 localhost NetworkManager[1089]: <info> (ttyUSB0):
> device state change: 8 -> 9 (reason 13)
> Jun 30 04:31:55 localhost modem-manager: (ttyUSB0) closing serial device...
> Jun 30 04:31:55 localhost modem-manager: Modem
> /org/freedesktop/ModemManager/Modems/6: state changed (connected ->
> disconnecting)
> Jun 30 04:31:55 localhost pppd[10030]: Terminating on signal 15
> Jun 30 04:31:55 localhost pppd[10030]: Connect time 17.3 minutes.
> Jun 30 04:31:55 localhost pppd[10030]: Sent 68631 bytes, received 1029149 bytes.
> Jun 30 04:31:55 localhost pptp[10038]: nm-pptp-service-10028
> log[callmgr_main:pptp_callmgr.c:234]: Closing connection (unhandled)
> Jun 30 04:31:55 localhost pptp[10038]: nm-pptp-service-10028
> log[ctrlp_rep:pptp_ctrl.c:251]: Sent control packet type is 12
> 'Call-Clear-Request'
> Jun 30 04:31:55 localhost pptp[10038]: nm-pptp-service-10028
> log[call_callback:pptp_callmgr.c:79]: Closing connection (call state)
> Jun 30 04:31:55 localhost pppd[10030]: MPPE disabled
> Jun 30 04:31:55 localhost pppd[10030]: Modem hangup
> Jun 30 04:31:55 localhost pppd[10030]: Connection terminated.
> Jun 30 04:31:55 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:55 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:55 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:55 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:55 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:55 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:55 localhost NetworkManager[1089]: <error>
> [1277897515.763317] [nm-system.c:319] sync_addresses(): (ppp0): error
> -19 returned from rtnl_addr_add():#012Sucess#012
> Jun 30 04:31:56 localhost pppd[10030]: Exit.
> Jun 30 04:31:56 localhost dbus: [system] Rejected send message, 1
> matched rules; type="error", sender=":1.273" (uid=0 pid=10028
> comm="/usr/libexec/nm-pptp-service) interface="(unset)"
> member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod"
> requested_reply=0 destination=":1.274" (uid=0 pid=10030
> comm="/usr/sbin/pppd))
> Jun 30 04:31:56 localhost modem-manager: Modem
> /org/freedesktop/ModemManager/Modems/6: state changed (disconnecting
> -> connected)
> Jun 30 04:31:56 localhost NetworkManager[1089]:
> nm_system_device_set_priority: assertion `info.iface >= 0' failed
> Jun 30 04:31:56 localhost NetworkManager[1089]: <warn> Activation
> (ttyUSB0) failed.
> Jun 30 04:31:56 localhost NetworkManager[1089]: <info> disconnect
> failed: (32) Failed to retrieve current speed
> Jun 30 04:31:56 localhost NetworkManager[1089]: <info> (ttyUSB0):
> device state change: 9 -> 3 (reason 0)
> Jun 30 04:31:56 localhost NetworkManager[1089]: <info> (ttyUSB0):
> deactivating device (reason: 0).
> Jun 30 04:31:56 localhost NetworkManager[1089]: <warn> could not read
> ppp stats: No such device
> Jun 30 04:31:56 localhost pppd[9921]: Exit.
> _______________________________________________
> networkmanager-list mailing list
> networkmanager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list