Re: ip-config -> failed for GlobeTrotter HSDPA Modem

[Dan Williams <dcbw redhat com>]

On Mon, 2011-09-05 at 11:48 +0200, richter ecos de wrote:
> Hi,
> 
> I am trying to get GlobeTrotter HSDPA Modem to run with network manager 0.9 and modem manager 0.5. Both are build from Gentoo ebuild system. Everything works fine until the ip configuration should happen, which fails.
> 
> Here is the debug output:
> 
> Sep  5 08:47:28 ThinClient modem-manager[2056]: <debug> [mm-generic-gsm.c:4988] simple_state_machine(): (ttyHS0): simple connect state 5
> Sep  5 08:47:28 ThinClient modem-manager[2056]: <info>  [mm-modem.c:742] mm_modem_set_state(): Modem /org/freedesktop/ModemManager/Modems/1: state changed (registered -> connecting)
> Sep  5 08:47:28 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): --> 'AT_OCTI?<CR>'
> Sep  5 08:47:28 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): <-- '<CR><LF>_OCTI: 1,3<CR><LF><CR><LF>OK<CR><LF>'
> Sep  5 08:47:28 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): --> 'AT$QCPDPP=1,1,"vodafone","vodafone"<CR>'
> Sep  5 08:47:29 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): <-- '<CR><LF>OK<CR><LF>'
> Sep  5 08:47:29 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): --> 'AT_OWANCALL=1,0,1<CR>'
> Sep  5 08:47:29 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): <-- '<CR><LF>OK<CR><LF>'
> Sep  5 08:47:29 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): --> 'AT_OWANCALL=1,1,1<CR>'
> Sep  5 08:47:29 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): <-- '<CR><LF>OK<CR><LF>'
> Sep  5 08:47:30 ThinClient modem-manager[2056]: <debug> [mm-at-serial-port.c:298] debug_log(): (ttyHS0): <-- '_OWANCALL: 1, 1<CR><LF>'
> Sep  5 08:47:30 ThinClient modem-manager[2056]: <debug> [mm-port.c:181] mm_port_set_connected(): (ttyHS0): port now connected
> Sep  5 08:47:30 ThinClient modem-manager[2056]: <info>  [mm-modem.c:742] mm_modem_set_state(): Modem /org/freedesktop/ModemManager/Modems/1: state changed (connecting -> connected)
> Sep  5 08:47:30 ThinClient modem-manager[2056]: <debug> [mm-generic-gsm.c:4988] simple_state_machine(): (ttyHS0): simple connect state 6
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 2 of 5 (Device Configure) scheduled...
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 2 of 5 (Device Configure) starting...
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> (ttyHS0): device state change: prepare -> config (reason 'none') [40 50 0]
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 2 of 5 (Device Configure) successful.
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 3 of 5 (IP Configure Start) scheduled.
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 2 of 5 (Device Configure) complete.
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 3 of 5 (IP Configure Start) started...
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> (ttyHS0): device state change: config -> ip-config (reason 'none') [50 70 0]
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <debug> [1315205250.785194] [NetworkManagerUtils.c:878] nm_utils_get_proc_sys_net_value(): (ttyHS0): error reading /proc/sys/net/ipv6/conf/ttyHS0/accept_ra: (4) Failed to open file '/proc/sys/net/ipv6/conf/ttyHS0/accept_ra': No such file or directory
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> Activation (ttyHS0) Stage 3 of 5 (IP Configure Start) complete.
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <warn> retrieving IP4 configuration failed: (32) Sending command failed: device is connected
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> (ttyHS0): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <warn> Activation (ttyHS0) failed.
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <debug> [1315205250.789933] [nm-device.c:3649] failed_to_disconnected(): (ttyHS0): running failed->disconnected transition
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> (ttyHS0): device state change: failed -> disconnected (reason 'none') [120 30 0]
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <info> (ttyHS0): deactivating device (reason: 0).
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <debug> [1315205250.790191] [nm-system.c:1349] flush_routes(): (ttyHS0) failed to lookup interface index
> Sep  5 08:47:30 ThinClient NetworkManager[2044]: <debug> [1315205250.790589] [nm-system.c:1349] flush_routes(): (ttyHS0) failed to lookup interface index

In ModemManager debug logs, we'd expect to see this sequence:

modem-manager[29908]: <debug> [1315348444.215419] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): --> 'AT$QCPDPP=1,0<CR>'
modem-manager[29908]: <debug> [1315348444.225854] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): <-- '<CR><LF>OK<CR><LF>'
modem-manager[29908]: <debug> [1315348444.226129] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): --> 'AT_OWANCALL=1,0,1<CR>'
modem-manager[29908]: <debug> [1315348444.227736] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): <-- '<CR><LF>OK<CR><LF>'
modem-manager[29908]: <debug> [1315348444.227964] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): --> 'AT_OWANCALL=1,1,1<CR>'
modem-manager[29908]: <debug> [1315348444.229092] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): <-- '<CR><LF>OK<CR><LF>'
modem-manager[29908]: <debug> [1315348448.063045] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): <-- '_OWANCALL: 1, 1<CR><LF>'
modem-manager[29908]: <debug> [1315348448.063262] [mm-port.c:181] mm_port_set_connected(): (hso0): port now connected
modem-manager[29908]: <info>  [1315348448.063535] [mm-modem.c:742] mm_modem_set_state(): Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
modem-manager[29908]: <debug> [1315348448.063695] [mm-generic-gsm.c:5025] simple_state_machine(): (hso0): simple connect state 6
modem-manager[29908]: <debug> [1315348448.068108] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): --> 'AT_OWANDATA=1<CR>'
modem-manager[29908]: <debug> [1315348448.073222] [mm-at-serial-port.c:298] debug_log(): (ttyHS4): <-- '<CR><LF>_OWANDATA: 1, 25.160.35.217, 0.0.0.0, 10.177.0.34, 10.168.189.116, 0.0.0.0, 0.0.0.0, 72000<CR><CR><LF><CR><LF><CR><LF>OK<CR><LF>'

For your device we're not seeing the OWANDATA call there.  That appears
to be because MM is not recognizing your modem's network device which
should be called 'hso0'.  Can you provide logs of starting up
ModemManager with the device plugged in so we can debug what's not
happening about the detection process?  Also, when you plug the modem
in, do you see 'hso0' (or hso1 or whatever) in the output of 'ifconfig
-a' ?

Dan