GNOME.org
 

Re: SMS sending error with Telit module

On Wed, 2013-04-10 at 17:10 +0200, Enrico Murador - Research &
Development - CET wrote:

On 10/04/2013 14:11, Dan Williams wrote:

Hmm, try putting "noccp" into /etc/ppp/options, does that help with 
anything? It seems NM doesn't support changing that option (but does 
support flipping vjcomp, bsdcomp, etc) but I think putting it into 
/etc/ppp/options is a quick check. Dan 

Tried... the protocol reject lines disappeared, but the behavior remains 
the same. I've also tried to playing a bit with the settings in 
/etc/ppp/options, but nothing.
I don't understand why the module simply "hangs up", and why only the 
first time...

On Mon, 2013-04-08 at 10:39 +0200, Enrico Murador - Research &
Development - CET wrote:


I'm trying the packages I updated friday from PPA, but now I'm facing
another problem: after I start the gsm data connection, most of the time
connection drops automatically... sometimes immediately after
connection, sometimes after some seconds (and in the meantime, I see the
modem status icon on top right of the screen in "searching" state).
After the connection drops, the modem seems to become "unreachable" from
the manager. I can get it working by disconnect and reconnect the
module's USB cable, without powering it off.

I was finally able to make the module "hang", but I don't know how. 
After the issue happened, I tried to disconnect and reconnect the USB 
cable, but "hang" remained.
Finally, I cycled the power of the module, and then I was able to 
connect (apart from the first try...). Following is the log.

On this log the comm port used by the manager was USB4, and also after 
the failed attempts of disconnecting/reconnecting the cable, port was 
still USB4.
Only after I cycled the module power supply, used port was USB2, and 
connection worked again.
In the various logs I've done, I've found another connection attempt in 
which the comm port choosed was not USB2 (it was USB3), and I found the same


In the case where the module has multiple AT-capable ports, any of them
are available for PPP unless ModemManager is told otherwise.  Typically
MM does this either by asking the modem which ports it supports PPP on
(through proprietary AT commands), or by udev rules to "tag" the
specific USB interfaces as capable of PPP or not when we can't figure
this out automatically.

If you have Windows drivers for your modem, then the .INF files usually
tell us which ports are PPP capable and which are only used for status
and control.

Otherwise, if you determine that USB2 is the only one that reliably
supports the PPP connection, then we'll need to investigate whether this
is the same for all other devices with that vendor and product ID, or
whether there's an AT command we can run to ask the modem about this, or
whether we just need to tag the ports and hope for the best.

Also, can you grab 'lsusb -v -d <vid:pid>' output for your module?
Often the PPP-capable ports are the ones with an Interrupt endpoint,
while AT ports that don't support PPP do not have the interrupt
endpoint, only bulk in/bulk out ones.

Dan


"sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> 
<accomp>]" repeated attempts, until timeout happened.

I suppose that USB port assignments can vary from time to time... could 
it be that the manager chooses the wrong USB port to communicate?
If useful, I have the corresponding MM logs available.

Thank you very much

Here is the log:

First (failed) connection attempt:
NetworkManager[10648]: <info> Activation (ttyUSB4) starting connection 
'gsm1'
NetworkManager[10648]: <info> (ttyUSB4): device state change: 
disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) scheduled...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) started...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) complete.
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'disabled' --> 
'enabling' (reason: user-requested)
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'enabling' --> 
'registered' (reason: user-requested)
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'registered' --> 
'connecting' (reason: user-requested)
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'connecting' --> 
'connected' (reason: user-requested)
NetworkManager[10648]: <warn> (ttyUSB4): failed to look up interface index
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device 
Configure) scheduled...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device 
Configure) starting...
NetworkManager[10648]: <info> (ttyUSB4): device state change: prepare -> 
config (reason 'none') [40 50 0]
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device 
Configure) successful.
NetworkManager[10648]: <debug> [1365603731.639957] [nm-device.c:3085] 
nm_device_activate_schedule_stage3_ip_config_start(): Activation 
(ttyUSB4) setting firewall zone 'default'
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 3 of 5 (IP 
Configure Start) scheduled.
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device 
Configure) complete.
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 3 of 5 (IP 
Configure Start) started...
NetworkManager[10648]: <info> (ttyUSB4): device state change: config -> 
ip-config (reason 'none') [50 70 0]
NetworkManager[10648]: <info> using modem-specified IP timeout: 20 seconds
NetworkManager[10648]: <info> starting PPP connection
NetworkManager[10648]: <debug> [1365603731.641587] 
[nm-ppp-manager.c:1067] nm_ppp_manager_start(): command line: 
/usr/sbin/pppd nodetach lock nodefaultroute ipv6 , debug ttyUSB4 
noipdefault noauth usepeerdns lcp-echo-failure 5 lcp-echo-interval 30 
ipparam /org/freedesktop/NetworkManager/PPP/17 plugin 
/usr/lib/i386-linux-gnu/pppd/2.4.5/nm-pppd-plugin.so
NetworkManager[10648]: <info> pppd started with pid 12276
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv6 
Configure Timeout) scheduled...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 3 of 5 (IP 
Configure Start) complete.
Plugin /usr/lib/i386-linux-gnu/pppd/2.4.5/nm-pppd-plugin.so loaded.
** Message: nm-ppp-plugin: (plugin_init): initializing
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial 
connection'
Removed stale lock on ttyUSB4 (pid 12181)
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv6 
Configure Timeout) started...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv6 
Configure Timeout) complete.
using channel 57
NetworkManager[10648]: <debug> [1365603731.651022] 
[nm-ip6-manager.c:1340] netlink_notification(): netlink event type 16
NetworkManager[10648]: <debug> [1365603731.652138] 
[nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: 
iface idx 48 flags 0x1090
NetworkManager[10648]:    SCPlugin-Ifupdown: devices added (path: 
/sys/devices/virtual/net/ppp0, iface: ppp0)
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB4NetworkManager[10648]: SCPlugin-Ifupdown: 
device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no 
ifupdown configuration found.
NetworkManager[10648]: <debug> [1365603731.652400] 
[nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'add' subsys 
'net' device 'ppp0'

** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> 
<accomp>]NetworkManager[10648]: <warn> /sys/devices/virtual/net/ppp0: 
couldn't determine device driver; ignoring...

sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]
NetworkManager[10648]: <warn> pppd timed out or didn't initialize our 
dbus module
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv4 
Configure Timeout) scheduled...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv4 
Configure Timeout) started...
NetworkManager[10648]: <info> (ttyUSB4): device state change: ip-config 
-> failed (reason 'ip-config-unavailable') [70 120 5]
Terminating on signal 15
** Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
sent [LCP TermReq id=0x2 "User request"]
NetworkManager[10648]: <warn> Activation (ttyUSB4) failed for connection 
'gsm1'
NetworkManager[10648]: <debug> [1365603751.808564] [nm-device.c:5256] 
nm_device_queue_state(): (ttyUSB4): queued state change to disconnected 
(id 2917)
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv4 
Configure Timeout) complete.
NetworkManager[10648]: <debug> [1365603751.808893] [nm-device.c:5214] 
queued_set_state(): (ttyUSB4): running queued state change to 
disconnected (id 2917)
NetworkManager[10648]: <info> (ttyUSB4): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
NetworkManager[10648]: <info> (ttyUSB4): deactivating device (reason 
'none') [0]
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'connected' --> 
'disconnecting' (reason: user-requested)
NetworkManager[10648]: <debug> [1365603753.789508] 
[nm-ppp-manager.c:1103] ensure_killed(): waiting for pppd pid 12276 to exit
NetworkManager[10648]: <debug> [1365603753.794918] 
[nm-ppp-manager.c:1105] ensure_killed(): pppd pid 12276 cleaned up
NetworkManager[10648]: <debug> [1365603753.795013] 
[nm-ip6-manager.c:1340] netlink_notification(): netlink event type 17
NetworkManager[10648]: <debug> [1365603753.795055] 
[nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: 
iface idx 48 flags 0x1090
NetworkManager[10648]:    SCPlugin-Ifupdown: devices removed (path: 
/sys/devices/virtual/net/ppp0, iface: ppp0)
NetworkManager[10648]: <debug> [1365603753.795234] 
[nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'remove' 
subsys 'net' device 'ppp0'

Second (failed) attempt:
NetworkManager[10648]: <info> Activation (ttyUSB4) starting connection 
'gsm1'
NetworkManager[10648]: <info> (ttyUSB4): device state change: 
disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) scheduled...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) started...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) complete.
NetworkManager[10648]: <warn> (ttyUSB4) failed to connect modem: Bearer 
currently being disconnected
NetworkManager[10648]: <debug> [1365603765.579840] 
[nm-modem-broadband.c:102] translate_mm_error(): unmapped error 
detected: 'Bearer currently being disconnected'
NetworkManager[10648]: <info> (ttyUSB4): device state change: prepare -> 
failed (reason 'unknown') [40 120 1]
NetworkManager[10648]: <warn> Activation (ttyUSB4) failed for connection 
'gsm1'
NetworkManager[10648]: <debug> [1365603765.580106] [nm-device.c:5256] 
nm_device_queue_state(): (ttyUSB4): queued state change to disconnected 
(id 2952)
NetworkManager[10648]: <debug> [1365603765.583728] [nm-device.c:5214] 
queued_set_state(): (ttyUSB4): running queued state change to 
disconnected (id 2952)
NetworkManager[10648]: <info> (ttyUSB4): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
NetworkManager[10648]: <info> (ttyUSB4): deactivating device (reason 
'none') [0]
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'disconnecting' 
--> 'registered' (reason: user-requested)
NetworkManager[10648]: <info> Activation (ttyUSB4) starting connection 
'gsm1'
NetworkManager[10648]: <info> (ttyUSB4): device state change: 
disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) scheduled...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) started...
NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device 
Prepare) complete.
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'registered' --> 
'connecting' (reason: user-requested)
NetworkManager[10648]: <info> (ttyUSB4) state changed, 'connecting' --> 
'registered' (reason: user-requested)
NetworkManager[10648]: <warn> (ttyUSB4) failed to connect modem: Sending 
command failed: 'Resource temporarily unavailable'
NetworkManager[10648]: <debug> [1365603791.534050] 
[nm-modem-broadband.c:102] translate_mm_error(): unmapped error 
detected: 'Sending command failed: 'Resource temporarily unavailable''
NetworkManager[10648]: <info> (ttyUSB4): device state change: prepare -> 
failed (reason 'unknown') [40 120 1]
NetworkManager[10648]: <warn> Activation (ttyUSB4) failed for connection 
'gsm1'
NetworkManager[10648]: <debug> [1365603791.534589] [nm-device.c:5256] 
nm_device_queue_state(): (ttyUSB4): queued state change to disconnected 
(id 3003)
NetworkManager[10648]: <debug> [1365603791.534852] [nm-device.c:5214] 
queued_set_state(): (ttyUSB4): running queued state change to 
disconnected (id 3003)
NetworkManager[10648]: <info> (ttyUSB4): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
NetworkManager[10648]: <info> (ttyUSB4): deactivating device (reason 
'none') [0]


_______________________________________________
networkmanager-list mailing list
networkmanager-list gnome org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]