GNOME.org
 

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

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.

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?

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

diff --git a/src/nm-cdma-device.c b/src/nm-cdma-device.c
index 0de39a7..c2340bb 100644
--- a/src/nm-cdma-device.c
+++ b/src/nm-cdma-device.c
@@ -465,6 +465,7 @@ device_state_changed (NMDeviceInterface *device,
 	case NM_DEVICE_STATE_UNAVAILABLE:
 	case NM_DEVICE_STATE_FAILED:
 	case NM_DEVICE_STATE_DISCONNECTED:
+	case NM_DEVICE_STATE_NEED_AUTH:
 		nm_serial_device_close (NM_SERIAL_DEVICE (self));
 		break;
 	default:
diff --git a/src/nm-gsm-device.c b/src/nm-gsm-device.c
index cc83d1a..156902c 100644
--- a/src/nm-gsm-device.c
+++ b/src/nm-gsm-device.c
@@ -1076,6 +1076,7 @@ device_state_changed (NMDeviceInterface *device,
 	case NM_DEVICE_STATE_UNAVAILABLE:
 	case NM_DEVICE_STATE_FAILED:
 	case NM_DEVICE_STATE_DISCONNECTED:
+	case NM_DEVICE_STATE_NEED_AUTH:
 		nm_serial_device_close (NM_SERIAL_DEVICE (self));
 		break;
 	default:
diff --git a/src/nm-serial-device.c b/src/nm-serial-device.c
index ad481d3..98b08a4 100644
--- a/src/nm-serial-device.c
+++ b/src/nm-serial-device.c
@@ -391,6 +391,12 @@ nm_serial_device_open (NMSerialDevice *device,
 	priv = NM_SERIAL_DEVICE_GET_PRIVATE (device);
 	iface = nm_device_get_iface (NM_DEVICE (device));
 
+	if (priv->fd >= 0) {
+		nm_debug ("(%s) bug: device already open", iface);
+		nm_serial_device_close (device);
+		priv->fd = -1;
+	}
+
 	nm_debug ("(%s) opening device...", iface);
 
 	path = g_build_filename ("/dev", iface, NULL);
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]