diff --git a/ChangeLog b/ChangeLog index 8fa2377fc2..b21c5220a1 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,19 @@ +2006-02-28 Dan Williams + + * src/vpn-manager/nm-vpn-service.c + - (nm_vpn_service_start_connection): if the vpn service daemon is + already running, don't blindly ask it to connect, but wait until + it's in the STOPPED state first. Fixes an assertion when user + starts a second vpn connection without stopping the first. + - (nm_vpn_service_stage2_daemon_wait): ensure the vpn service's + dbus service exists before continuing with the connection + process, and reduce latency while waiting for it to become + available + - (nm_vpn_service_schedule_stage2_daemon_wait): reduce latency + waiting for the vpn service daemon to become available + - General log message cleanups; show progress via "Stage x of 4" + rather than not telling anyone how many stages there are + 2006-02-28 Robert Love * src/NetworkManagerSystem.h: Add nm_system_should_modify_resolv_conf. diff --git a/src/vpn-manager/nm-vpn-service.c b/src/vpn-manager/nm-vpn-service.c index a696d1b51c..73bf13e72e 100644 --- a/src/vpn-manager/nm-vpn-service.c +++ b/src/vpn-manager/nm-vpn-service.c @@ -292,7 +292,7 @@ void nm_vpn_service_start_connection (NMVPNService *service, NMVPNActRequest *re if (!dbus_bus_name_has_owner (service->app_data->dbus_connection, service->service, NULL)) nm_vpn_service_schedule_stage1_daemon_exec (service, req); else - nm_vpn_service_schedule_stage3_connect (service, req); + nm_vpn_service_schedule_stage2_daemon_wait (service, req); } @@ -306,6 +306,7 @@ static gboolean nm_vpn_service_stage1_daemon_exec (gpointer user_data) { NMVPNActRequest * req = (NMVPNActRequest *) user_data; NMVPNService * service; + NMVPNConnection * vpn = NULL; GPtrArray * vpn_argv; GError * error = NULL; GPid pid; @@ -316,6 +317,9 @@ static gboolean nm_vpn_service_stage1_daemon_exec (gpointer user_data) g_assert (service != NULL); g_assert (service->program != NULL); + vpn = nm_vpn_act_request_get_connection (req); + g_assert (vpn); + nm_vpn_act_request_set_callback_id (req, 0); vpn_argv = g_ptr_array_new (); @@ -325,13 +329,16 @@ static gboolean nm_vpn_service_stage1_daemon_exec (gpointer user_data) if (!g_spawn_async (NULL, (char **) vpn_argv->pdata, NULL, 0, NULL, NULL, &pid, &error)) { g_ptr_array_free (vpn_argv, TRUE); - nm_warning ("nm_vpn_service_stage1_daemon_exec(%s): could not launch the VPN service. error: '%s'.", service->service, error->message); + nm_warning ("(VPN Service %s): could not launch the VPN service. error: '%s'.", service->service, error->message); g_error_free (error); nm_vpn_service_act_request_failed (service, req); goto out; } g_ptr_array_free (vpn_argv, TRUE); - nm_info ("nm_vpn_service_stage1_daemon_exec(%s): execed the VPN service, PID is %d.", service->service, pid); + nm_info ("VPN Activation (%s) Stage 1 of 4 (Connection Prepare) ran VPN service daemon %s (PID %d)", + nm_vpn_connection_get_name (vpn), service->service, pid); + nm_info ("VPN Activation (%s) Stage 1 of 4 (Connection Prepare) complete.", + nm_vpn_connection_get_name (vpn)); nm_vpn_service_schedule_stage2_daemon_wait (service, req); @@ -360,7 +367,7 @@ static void nm_vpn_service_schedule_stage1_daemon_exec (NMVPNService *service, N id = g_source_attach (source, service->app_data->main_context); nm_vpn_act_request_set_callback_id (req, id); g_source_unref (source); - nm_info ("VPN Activation (%s) Stage 1 (Connection Prepare) scheduled...", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 1 of 4 (Connection Prepare) scheduled...", nm_vpn_connection_get_name (vpn)); } @@ -374,19 +381,35 @@ static gboolean nm_vpn_service_stage2_daemon_wait (gpointer user_data) { NMVPNActRequest * req = (NMVPNActRequest *) user_data; NMVPNService * service; + NMVPNConnection * vpn = NULL; + gboolean service_exists = FALSE; g_assert (req != NULL); service = nm_vpn_act_request_get_service (req); g_assert (service != NULL); + vpn = nm_vpn_act_request_get_connection (req); + g_assert (vpn); + nm_vpn_act_request_set_callback_id (req, 0); - if (service->state == NM_VPN_STATE_STOPPED) - nm_vpn_service_schedule_stage3_connect (service, req); - else if (nm_vpn_act_request_get_daemon_wait_count (req) >= 4) + nm_info ("VPN Activation (%s) Stage 2 of 4 (Connection Prepare Wait) " + "waiting...", nm_vpn_connection_get_name (vpn)); + + service_exists = dbus_bus_name_has_owner (service->app_data->dbus_connection, + service->service, NULL); + if (service_exists && (service->state == NM_VPN_STATE_STOPPED)) { - /* We only wait 2s (4 * 500 milliseconds) for the service to start up */ + nm_info ("VPN Activation (%s) Stage 2 of 4 (Connection Prepare Wait) " + "complete.", nm_vpn_connection_get_name (vpn)); + nm_vpn_service_schedule_stage3_connect (service, req); + } + else if (nm_vpn_act_request_get_daemon_wait_count (req) > 10) + { + /* We only wait 2s (10 * 200 milliseconds) for the service to + * become available. + */ nm_vpn_service_act_request_failed (service, req); } else @@ -412,12 +435,12 @@ static void nm_vpn_service_schedule_stage2_daemon_wait (NMVPNService *service, N nm_vpn_act_request_set_daemon_wait_count (req, nm_vpn_act_request_get_daemon_wait_count (req) + 1); - source = g_timeout_source_new (500); + source = g_timeout_source_new (200); g_source_set_callback (source, (GSourceFunc) nm_vpn_service_stage2_daemon_wait, req, NULL); id = g_source_attach (source, service->app_data->main_context); nm_vpn_act_request_set_callback_id (req, id); g_source_unref (source); - nm_info ("VPN Activation (%s) Stage 2 (Connection Prepare Wait) scheduled...", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 2 of 4 (Connection Prepare Wait) scheduled...", nm_vpn_connection_get_name (vpn)); } @@ -437,11 +460,13 @@ static void nm_vpn_service_stage3_connect_cb (DBusPendingCall *pcall, void *user vpn = nm_vpn_act_request_get_connection (req); g_assert (vpn); - nm_info ("VPN Activation (%s) Stage 3 (Connect) reply received.", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 3 of 4 (Connect) reply received.", + nm_vpn_connection_get_name (vpn)); if (!(reply = dbus_pending_call_steal_reply (pcall))) { - nm_warning ("nm_vpn_service_stage3_connect_cb(%s): could not obtain VPN service's reply.", service->service); + nm_warning ("(VPN Service %s): could not obtain VPN service's reply.", + service->service); nm_vpn_service_act_request_failed (service, req); goto out; } @@ -454,7 +479,7 @@ static void nm_vpn_service_stage3_connect_cb (DBusPendingCall *pcall, void *user if (!dbus_message_get_args (reply, NULL, DBUS_TYPE_STRING, &message, NULL)) message = (char *) ""; - nm_warning ("nm_vpn_service_stage3_connect_cb(%s): could not start the VPN '%s'. dbus says: '%s' '%s'.", + nm_warning ("(VPN Service %s): could not start the VPN '%s'. dbus says: '%s' '%s'.", service->service, nm_vpn_connection_get_name (vpn), member, message); nm_vpn_service_act_request_failed (service, req); } @@ -462,7 +487,8 @@ static void nm_vpn_service_stage3_connect_cb (DBusPendingCall *pcall, void *user { nm_vpn_act_request_set_stage (req, NM_VPN_ACT_STAGE_IP_CONFIG_GET); nm_vpn_service_schedule_stage4_ip_config_get_timeout (service, req); - nm_info ("VPN Activation (%s) Stage 4 (IP Config Get) reply expected soon...", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 3 of 4 (Connect) complete, " + "waiting for IP configuration...", nm_vpn_connection_get_name (vpn)); } dbus_message_unref (reply); @@ -522,7 +548,7 @@ static gboolean nm_vpn_service_stage3_connect (gpointer user_data) g_free (op); if (!message) { - nm_warning ("nm_vpn_service_stage3_connect(%s): couldn't allocate dbus message.", service->service); + nm_warning ("(VPN Service %s): couldn't allocate dbus message.", service->service); nm_vpn_service_act_request_failed (service, req); return FALSE; } @@ -537,6 +563,8 @@ static gboolean nm_vpn_service_stage3_connect (gpointer user_data) data_items = sanitize_dbus_string_array (data_items, &data_count); user_routes = sanitize_dbus_string_array (user_routes, &user_routes_count); + nm_info ("VPN Activation (%s) Stage 3 of 4 (Connect) sending connect request.", + nm_vpn_connection_get_name (vpn)); dbus_message_append_args (message, DBUS_TYPE_STRING, &name, DBUS_TYPE_STRING, &user_name, DBUS_TYPE_ARRAY, DBUS_TYPE_STRING, &password_items, password_count, @@ -548,7 +576,8 @@ static gboolean nm_vpn_service_stage3_connect (gpointer user_data) if (pcall) { dbus_pending_call_set_notify (pcall, nm_vpn_service_stage3_connect_cb, req, NULL); - nm_info ("VPN Activation (%s) Stage 3 (Connect) reply expected soon...", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 3 of 4 (Connect) request sent," + " waiting for reply...", nm_vpn_connection_get_name (vpn)); } else nm_vpn_service_act_request_failed (service, req); @@ -577,7 +606,7 @@ static void nm_vpn_service_schedule_stage3_connect (NMVPNService *service, NMVPN id = g_source_attach (source, service->app_data->main_context); nm_vpn_act_request_set_callback_id (req, id); g_source_unref (source); - nm_info ("VPN Activation (%s) Stage 3 (Connect) scheduled...", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 3 of 4 (Connect) scheduled...", nm_vpn_connection_get_name (vpn)); } @@ -602,7 +631,7 @@ static gboolean nm_vpn_service_stage4_ip_config_get_timeout (gpointer *user_data */ if (nm_vpn_act_request_get_stage (req) == NM_VPN_ACT_STAGE_IP_CONFIG_GET) { - nm_info ("VPN Activation (%s) Stage 4 (IP Config Get) timeout exceeded.", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 4 of 4 (IP Config Get) timeout exceeded.", nm_vpn_connection_get_name (vpn)); nm_vpn_service_act_request_failed (service, req); } @@ -630,7 +659,7 @@ static void nm_vpn_service_schedule_stage4_ip_config_get_timeout (NMVPNService * id = g_source_attach (source, service->app_data->main_context); nm_vpn_act_request_set_callback_id (req, id); g_source_unref (source); - nm_info ("VPN Activation (%s) Stage 4 (IP Config Get) timeout scheduled...", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 4 of 4 (IP Config Get) timeout scheduled...", nm_vpn_connection_get_name (vpn)); } @@ -709,7 +738,8 @@ nm_vpn_service_stage4_ip_config_get (NMVPNService *service, vpn = nm_vpn_act_request_get_connection (req); g_assert (vpn); - nm_info ("VPN Activation (%s) Stage 4 (IP Config Get) reply received.", nm_vpn_connection_get_name (vpn)); + nm_info ("VPN Activation (%s) Stage 4 of 4 (IP Config Get) reply received.", + nm_vpn_connection_get_name (vpn)); config = nm_ip4_config_new (); nm_ip4_config_set_secondary (config, TRUE); @@ -808,6 +838,8 @@ nm_vpn_service_stage4_ip_config_get (NMVPNService *service, if (nm_vpn_connection_set_config (vpn, tundev, parent_dev, config)) { + nm_info ("VPN Activation (%s) Stage 4 of 4 (IP Config Get) complete.", + nm_vpn_connection_get_name (vpn)); if (login_banner && strlen (login_banner)) nm_dbus_vpn_signal_vpn_login_banner (service->app_data->dbus_connection, vpn, login_banner); success = TRUE; @@ -818,7 +850,7 @@ out: if (!success) { nm_ip4_config_unref (config); - nm_warning ("nm_vpn_service_stage4_ip_config_get(%s): did not receive valid IP config information.", service->service); + nm_warning ("(VPN Service %s): did not receive valid IP config information.", service->service); nm_vpn_service_act_request_failed (service, req); } } @@ -839,7 +871,7 @@ static void nm_vpn_service_stop_connection_internal (NMVPNService *service) dbus_message_unref (message); } else - nm_warning ("nm_vpn_service_stop_connection_internal(): error, couldn't allocate dbus message."); + nm_warning ("(VPN Service %s): couldn't allocate dbus message.", service->service); g_free (op); } @@ -861,7 +893,7 @@ void nm_vpn_service_stop_connection (NMVPNService *service, NMVPNActRequest *req /* Ensure we can stop the connection in this state */ if ((service->state != NM_VPN_STATE_STARTED) && (service->state != NM_VPN_STATE_STARTING)) { - nm_info ("nm_vpn_service_stop_connection(%s): could not stop connection '%s' because service was %d.", + nm_warning ("(VPN Service %s): could not stop connection '%s' because service was %d.", service->service, nm_vpn_connection_get_name (vpn), service->state); return; } @@ -993,7 +1025,7 @@ gboolean nm_vpn_service_process_signal (NMVPNService *service, NMVPNActRequest * NMVPNState old_state = (NMVPNState) old_state_int; NMVPNState new_state = (NMVPNState) new_state_int; - nm_info ("VPN service '%s' signaled new state %d, old state %d.", service->service, new_state, old_state); + nm_info ("VPN service '%s' signaled state change %d -> %d.", service->service, old_state, new_state); nm_vpn_service_set_state (service, new_state); /* If the VPN daemon state is now stopped and it was starting, clear the active connection */