GNOME.org
 

Re: NM 0.7.1 leaves open fd of /dev/tts/USB2 after disconnect

On Tue, 2009-06-30 at 17:51 -0400, Dan Williams wrote: 
> On Wed, 2009-06-24 at 22:26 +0300, Valmantas Palikša wrote:
> > Done some digging and found out that NM opens the device twice. This
> > very often leads to kernel panics here if the device connects multiple
> > times or is pluged/unpluged when the descriptor is left open. Probably
> > some bug in the kernel somewhere.. 
> 
> Yes, it is, and I think 2.6.31 should fix that, but I had thought that
> 2d93148ab6988cad872e65d694c95e8944e1b626 in 2.6.30 would have done so.
> 
> So you've got two issues here, the first is that NM is finding two
> ports, not one.  I'd expect NM 0.7.1 to do OK here, see my recent post
> on the ZTE thing a bit earlier today.  There may be a (already fixed)
> bug with HAL 'info.bus' handling that you can test by dropping that fdi
> file into the right place.
> 

NM applet shows 2 ports:

NetworkManager: <info>  (tts/USB2): found serial port (udev:GSM
hal:GSM)
NetworkManager: <info>  (tts/USB2): new Modem device (driver: 'option')
NetworkManager: <info>  (tts/USB2): exported
as /org/freedesktop/Hal/devices/usb_device_19d2_31_1234567890ABCDEF_if3_serial_usb_0
NetworkManager: <info>  (tts/USB0): ignoring due to lack of mobile
broadband capabilties
NetworkManager: <info>  (tts/USB2): device state change: 1 -> 2
NetworkManager: <info>  (tts/USB2): deactivating device (reason: 2).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion
`iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface:
assertion `iface_idx >= 0' failed
NetworkManager: <info>  (tts/USB2): device state change: 2 -> 3
NetworkManager: <info>  (tts/USB1): found serial port (udev:GSM  hal:)
NetworkManager: <info>  (tts/USB1): deferring until all ports found
NetworkManager: <info>  Re-checking deferred serial ports
NetworkManager: <info>  (tts/USB1): new Modem device (driver: 'option')
NetworkManager: <info>  (tts/USB1): exported
as /org/freedesktop/Hal/devices/usb_device_19d2_31_1234567890ABCDEF_if1_serial_usb_0
NetworkManager: <info>  (tts/USB1): device state change: 1 -> 2
NetworkManager: <info>  (tts/USB1): deactivating device (reason: 2).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion
`iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface:
assertion `iface_idx >= 0' failed
NetworkManager: <info>  (tts/USB1): device state change: 2 -> 3

Got it fixed by using this udev rule:
ACTION!="add|change", GOTO="nm_modem_probe_end"
SUBSYSTEM!="tty", GOTO="nm_modem_probe_end"

ENV{NM_MODEM_USB_INTERFACE_NUMBER}=="01", ENV{ID_VENDOR_ID}=="19d2",
ENV{ID_MODEL_ID}=="0031", ENV{ID_NM_MODEM_GSM}="0"

LABEL="nm_modem_probe_end"

EDIT:
dropped the deprecated keys fdi file and it seems it now detects 1 port
correctly.



> But yes, NM appears to re-open the port.  We should be closing it when
> requesting secrets since it may be a long time before secrets come back.
> Can you try they attached patch and let me know if it fixes the issue?
> 

Hmm, something's wrong with the patch, can't connect at all:

NetworkManager: <info>  (tts/USB2): found serial port (udev:GSM
hal:GSM)
NetworkManager: <info>  (tts/USB2): new Modem device (driver: 'option')
NetworkManager: <info>  (tts/USB2): exported
as /org/freedesktop/Hal/devices/usb_device_19d2_31_1234567890ABCDEF_if3_serial_usb_0
NetworkManager: <info>  (tts/USB0): ignoring due to lack of mobile
broadband capabilties
NetworkManager: <info>  (tts/USB2): device state change: 1 -> 2
NetworkManager: <info>  (tts/USB2): deactivating device (reason: 2).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion
`iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface:
assertion `iface_idx >= 0' failed
NetworkManager: <info>  (tts/USB2): device state change: 2 -> 3
NetworkManager: <info>  Activation (tts/USB2) starting connection 'Omni
Connect'
NetworkManager: <info>  (tts/USB2): device state change: 3 -> 4
NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
Prepare) scheduled...
NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
Prepare) started...
NetworkManager: <debug> [1246435879.217633] nm_serial_device_open():
(tts/USB2) bug: device already open
NetworkManager: <debug> [1246435879.217670] nm_serial_device_open():
(tts/USB2) opening device...
NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
Prepare) complete.
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (1)
NetworkManager: <info>  (tts/USB1): ignoring due to lack of mobile
broadband capabilties
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (2)
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (3)
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (4)
NetworkManager: <info>  (tts/USB2): GSM pin secret required
NetworkManager: <info>  (tts/USB2): device state change: 4 -> 6
NetworkManager: <debug> [1246435887.061857] nm_serial_device_close():
Closing device 'tts/USB2'
NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
Prepare) scheduled...
NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
Prepare) started...
NetworkManager: <info>  (tts/USB2): device state change: 6 -> 4
NetworkManager: <debug> [1246435887.066475] nm_serial_device_open():
(tts/USB2) bug: device already open
NetworkManager: <debug> [1246435887.066503] nm_serial_device_open():
(tts/USB2) opening device...
NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
Prepare) complete.
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (1)
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (2)
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (3)
NetworkManager: <WARN>  init_done(): Trying alternate modem
initialization (4)
NetworkManager: <info>  (tts/USB2): powering up...
NetworkManager: <info>  Searching for a network...
NetworkManager: <info>  Searching for a network...
NetworkManager: <info>  Registered on Home network
NetworkManager: <info>  Associated with network: +COPS: 0,1,"OMT",2
NetworkManager: <info>  Connected, Woo!
NetworkManager: <info>  Activation (tts/USB2) Stage 2 of 5 (Device
Configure) scheduled...
NetworkManager: <info>  Activation (tts/USB2) Stage 2 of 5 (Device
Configure) starting...
NetworkManager: <info>  (tts/USB2): device state change: 4 -> 5
NetworkManager: <info>  Starting pppd connection
NetworkManager: <debug> [1246435894.109089] nm_ppp_manager_start():
Command line: /usr/sbin/pppd nodetach lock nodefaultroute tts/USB2
noipdefault noauth refuse-eap refuse-pap refuse-chap refuse-mschap
refuse-mschap-v2 usepeerdns lcp-echo-failure 0 lcp-echo-interval 0
ipparam /org/freedesktop/NetworkManager/PPP/0
plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
NetworkManager: <debug> [1246435894.125042] nm_ppp_manager_start(): ppp
started with pid 2143
Using interface ppp0
Connect: ppp0 <--> /dev/tts/USB2
NetworkManager: <info>  Activation (tts/USB2) Stage 2 of 5 (Device
Configure) complete.
NetworkManager: <info>  (tts/USB2): device state change: 5 -> 6
Terminating on signal 15
NetworkManager: <debug> [1246435894.159214] nm_serial_device_close():
Closing device 'tts/USB2'
Connection terminated.
NetworkManager: <debug> [1246435896.000993] ensure_killed(): waiting for
ppp pid 2143 to exit
NetworkManager: <debug> [1246435896.001139] ensure_killed(): ppp pid
2143 cleaned up


> Dan
> 
> > Kernel: 2.6.30
> > NM: 0.7.1
> > Modem: ZTE MF633 (0x19d2 0x0031)
> > 
> > My temporary patch:
> > 
> > --- nm-gsm-device.old.c	2009-04-13 01:29:59.000000000 +0300
> > +++ nm-gsm-device.c	2009-06-24 22:17:58.039782740 +0300
> > @@ -823,6 +823,11 @@
> >  
> >  	setting = NM_SETTING_SERIAL (gsm_device_get_setting (NM_GSM_DEVICE
> > (device), NM_TYPE_SETTING_SERIAL));
> >  
> > + 	if(NM_GSM_DEVICE_GET_PRIVATE (device)->init_ok) {
> > + 		nm_warning("BUG: Closing previous connection");
> > + 		nm_serial_device_close (serial_device);
> > + 	}
> > +
> >  	if (!nm_serial_device_open (serial_device, setting)) {
> >  		*reason = NM_DEVICE_STATE_REASON_CONFIG_FAILED;
> >  		return NM_ACT_STAGE_RETURN_FAILURE;
> > 
> > Also the log:
> > 
> > NetworkManager: <info>  (tts/USB2): device state change: 2 -> 3
> > NetworkManager: <info>  (tts/USB1): found serial port (udev:GSM  hal:)
> > NetworkManager: <info>  (tts/USB1): deferring until all ports found
> > NetworkManager: <info>  Activation (tts/USB2) starting connection 'Omni
> > Connect'
> > NetworkManager: <info>  (tts/USB2): device state change: 3 -> 4
> > NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
> > Prepare) scheduled...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
> > Prepare) started...
> > NetworkManager: <WARN>  real_act_stage1_prepare(): Stage1 0xf64010 0
> > NetworkManager: <debug> [1245870737.912363] nm_serial_device_open():
> > (tts/USB2) opening device...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
> > Prepare) complete.
> > NetworkManager: <info>  Re-checking deferred serial ports
> > NetworkManager: <info>  (tts/USB1): new Modem device (driver: 'option')
> > NetworkManager: <info>  (tts/USB1): exported
> > as /org/freedesktop/Hal/devices/usb_device_19d2_31_1234567890ABCDEF_if1_serial_usb_0
> > NetworkManager: <debug> [1245870738.017629] nm_serial_debug(): Sending:
> > 'ATZ E0 V1 X4 &C1 +FCLASS=0
> > '
> > NetworkManager: <debug> [1245870738.075007] nm_serial_debug(): Got: 'ATZ
> > E0 V1 X4 &C1 +FCLASS=0'
> > NetworkManager: <debug> [1245870738.086523] nm_serial_debug(): Got: 'ATZ
> > E0 V1 X4 &C1 +FCLASS=0
> > 
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (1)
> > NetworkManager: <debug> [1245870739.001616] nm_serial_debug(): Sending:
> > 'ATZ E0 V1 &C1
> > '
> > NetworkManager: <debug> [1245870739.046540] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (2)
> > NetworkManager: <debug> [1245870740.001537] nm_serial_debug(): Sending:
> > 'AT&F E0 V1 X4 &C1 +FCLASS=0
> > '
> > NetworkManager: <debug> [1245870740.073194] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (3)
> > NetworkManager: <debug> [1245870741.001280] nm_serial_debug(): Sending:
> > 'AT&F E0 V1 &C1
> > '
> > NetworkManager: <debug> [1245870741.043247] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (4)
> > NetworkManager: <info>  (tts/USB1): device state change: 1 -> 2
> > NetworkManager: <info>  (tts/USB1): deactivating device (reason: 2).
> > NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion
> > `iface_idx >= 0' failed
> > NetworkManager: nm_system_device_flush_ip4_addresses_with_iface:
> > assertion `iface_idx >= 0' failed
> > NetworkManager: <debug> [1245870742.008830] nm_serial_debug(): Sending:
> > 'AT&F E0 V1
> > '
> > NetworkManager: <info>  (tts/USB1): device state change: 2 -> 3
> > NetworkManager: <debug> [1245870742.043197] nm_serial_debug(): Got: '
> > 
> > OK
> > 
> > '
> > NetworkManager: <debug> [1245870742.043300] nm_serial_debug(): Sending:
> > 'AT+CPIN?
> > '
> > NetworkManager: <debug> [1245870742.073198] nm_serial_debug(): Got: '
> > 
> > +CPIN: SIM PIN
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <info>  (tts/USB2): GSM pin secret required
> > NetworkManager: <info>  (tts/USB2): device state change: 4 -> 6
> > NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
> > Prepare) scheduled...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
> > Prepare) started...
> > NetworkManager: <info>  (tts/USB2): device state change: 6 -> 4
> > NetworkManager: <WARN>  real_act_stage1_prepare(): Stage1 0xf64010 1
> > NetworkManager: <WARN>  real_act_stage1_prepare(): BUG: Closing previous
> > connection
> > NetworkManager: <debug> [1245870742.083547] nm_serial_device_close():
> > Closing device 'tts/USB2'
> > NetworkManager: <debug> [1245870742.085062] nm_serial_device_open():
> > (tts/USB2) opening device...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 1 of 5 (Device
> > Prepare) complete.
> > NetworkManager: <debug> [1245870742.189500] nm_serial_debug(): Sending:
> > 'ATZ E0 V1 X4 &C1 +FCLASS=0
> > '
> > NetworkManager: <debug> [1245870742.263205] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (1)
> > NetworkManager: <debug> [1245870744.000128] nm_serial_debug(): Sending:
> > 'ATZ E0 V1 &C1
> > '
> > NetworkManager: <debug> [1245870744.043202] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (2)
> > NetworkManager: <debug> [1245870745.001327] nm_serial_debug(): Sending:
> > 'AT&F E0 V1 X4 &C1 +FCLASS=0
> > '
> > NetworkManager: <debug> [1245870745.073348] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (3)
> > NetworkManager: <debug> [1245870746.001424] nm_serial_debug(): Sending:
> > 'AT&F E0 V1 &C1
> > '
> > NetworkManager: <debug> [1245870746.046530] nm_serial_debug(): Got: '
> > 
> > ERROR
> > 
> > '
> > NetworkManager: <WARN>  init_done(): Trying alternate modem
> > initialization (4)
> > NetworkManager: <debug> [1245870747.001170] nm_serial_debug(): Sending:
> > 'AT&F E0 V1
> > '
> > NetworkManager: <debug> [1245870747.036539] nm_serial_debug(): Got: '
> > 
> > OK
> > 
> > '
> > NetworkManager: <debug> [1245870747.036647] nm_serial_debug(): Sending:
> > 'AT+CPIN?
> > '
> > NetworkManager: <debug> [1245870747.066536] nm_serial_debug(): Got: '
> > 
> > +CPIN: SIM PIN
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <debug> [1245870747.066661] nm_serial_debug(): Sending:
> > 'AT+CPIN="6486"
> > '
> > NetworkManager: <debug> [1245870747.206678] nm_serial_debug(): Got: '
> > 
> > OK
> > 
> > '
> > NetworkManager: <debug> [1245870747.206787] nm_serial_debug(): Sending:
> > 'AT&F E0 V1
> > '
> > NetworkManager: <debug> [1245870747.239868] nm_serial_debug(): Got: '
> > 
> > OK
> > 
> > '
> > NetworkManager: <info>  (tts/USB2): powering up...
> > NetworkManager: <debug> [1245870747.239981] nm_serial_debug(): Sending:
> > 'AT+CFUN=1
> > '
> > NetworkManager: <debug> [1245870747.273203] nm_serial_debug(): Got: '
> > 
> > OK
> > 
> > '
> > NetworkManager: <debug> [1245870747.273295] nm_serial_debug(): Sending:
> > 'AT+CGMM
> > '
> > NetworkManager: <debug> [1245870747.303212] nm_serial_debug(): Got: '
> > 
> > MF633
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <debug> [1245870747.303328] nm_serial_debug(): Sending:
> > 'AT+CREG?
> > '
> > NetworkManager: <debug> [1245870747.333206] nm_serial_debug(): Got: '
> > 
> > +CREG: 0,2
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <info>  Searching for a network...
> > NetworkManager: <debug> [1245870749.000070] nm_serial_debug(): Sending:
> > 'AT+CREG?
> > '
> > NetworkManager: <debug> [1245870749.083204] nm_serial_debug(): Got: '
> > 
> > +CREG: 0,2
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <info>  Searching for a network...
> > NetworkManager: <debug> [1245870750.001634] nm_serial_debug(): Sending:
> > 'AT+CREG?
> > '
> > NetworkManager: <debug> [1245870750.023357] nm_serial_debug(): Got: '
> > 
> > +ZDONR: "OMT",246,1,"CS_ONLY","ROAM_OFF"
> > 
> > 
> > 
> > +ZPASR: "UMTS"
> > 
> > '
> > NetworkManager: <debug> [1245870750.036873] nm_serial_debug(): Got: '
> > 
> > +ZDONR: "OMT",246,1,"CS_ONLY","ROAM_OFF"
> > 
> > 
> > 
> > +ZPASR: "UMTS"
> > 
> > 
> > 
> > +CREG: 0,1
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <info>  Registered on Home network
> > NetworkManager: <debug> [1245870750.037021] nm_serial_debug(): Sending:
> > 'AT+COPS?
> > '
> > NetworkManager: <debug> [1245870750.066538] nm_serial_debug(): Got: '
> > 
> > +COPS: 0,1,"OMT",2
> > 
> > 
> > 
> > OK
> > 
> > '
> > NetworkManager: <info>  Associated with network: +COPS: 0,1,"OMT",2
> > NetworkManager: <debug> [1245870750.066685] nm_serial_debug(): Sending:
> > 'ATDT*99#
> > '
> > NetworkManager: <debug> [1245870750.096538] nm_serial_debug(): Got: '
> > 
> > CONNECT
> > 
> > '
> > NetworkManager: <info>  Connected, Woo!
> > NetworkManager: <info>  Activation (tts/USB2) Stage 2 of 5 (Device
> > Configure) scheduled...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 2 of 5 (Device
> > Configure) starting...
> > NetworkManager: <info>  (tts/USB2): device state change: 4 -> 5
> > NetworkManager: <info>  Starting pppd connection
> > NetworkManager: <debug> [1245870750.106860] nm_ppp_manager_start():
> > Command line: /usr/sbin/pppd nodetach lock nodefaultroute tts/USB2
> > noipdefault noauth refuse-eap refuse-pap refuse-chap refuse-mschap
> > refuse-mschap-v2 usepeerdns lcp-echo-failure 0 lcp-echo-interval 0
> > ipparam /org/freedesktop/NetworkManager/PPP/0
> > plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
> > Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
> > NetworkManager: <debug> [1245870750.121755] nm_ppp_manager_start(): ppp
> > started with pid 27105
> > Using interface ppp0
> > Connect: ppp0 <--> /dev/tts/USB2
> > NetworkManager: <info>  Activation (tts/USB2) Stage 2 of 5 (Device
> > Configure) complete.
> > NetworkManager: <info>  (tts/USB2): device state change: 5 -> 6
> > NetworkManager: <info>  (tts/USB2): device state change: 6 -> 7
> > Could not determine remote IP address: defaulting to 10.64.64.64
> > Cannot determine ethernet address for proxy ARP
> > local  IP address 10.123.21.99
> > remote IP address 10.64.64.64
> > primary   DNS address 10.11.12.13
> > secondary DNS address 10.11.12.14
> > NetworkManager: <info>  PPP manager(IP Config Get) reply received.
> > NetworkManager: <info>  Activation (tts/USB2) Stage 4 of 5 (IP Configure
> > Get) scheduled...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 4 of 5 (IP Configure
> > Get) started...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 5 of 5 (IP Configure
> > Commit) scheduled...
> > NetworkManager: <info>  Activation (tts/USB2) Stage 4 of 5 (IP Configure
> > Get) complete.
> > NetworkManager: <info>  Activation (tts/USB2) Stage 5 of 5 (IP Configure
> > Commit) started...
> > NetworkManager: <info>  (tts/USB2): device state change: 7 -> 8
> > NetworkManager: <info>  Policy set 'Omni Connect' (ppp0) as default for
> > routing and DNS.
> > NetworkManager: <info>  Activation (tts/USB2) successful, device
> > activated.
> > NetworkManager: <info>  Activation (tts/USB2) Stage 5 of 5 (IP Configure
> > Commit) complete.
> > 
> > 
> > 
> > 
> > _______________________________________________
> > NetworkManager-list mailing list
> > NetworkManager-list gnome org
> > http://mail.gnome.org/mailman/listinfo/networkmanager-list
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]