[strongSwan-dev] [PATCH 1/5] Add extra information in debug output for IKE_SA check{out, in}

[Thomas Egerer]

This output helps tracing checkout and checkin of IKE_SAs when there is
more than one IKE_SAs with the same name. I also added the type of
in-air-exchange to the debug output issued by the task_manager in case
a task initiation is delayed, came in handy for me.
---
 src/libcharon/sa/ike_sa_manager.c |   34 +++++++++++++++++++++++++---------
 src/libcharon/sa/task_manager.c   |    3 ++-
 2 files changed, 27 insertions(+), 10 deletions(-)

diff --git a/src/libcharon/sa/ike_sa_manager.c b/src/libcharon/sa/ike_sa_manager.c
index 3ef0f3b..c71c3b2 100644
--- a/src/libcharon/sa/ike_sa_manager.c
+++ b/src/libcharon/sa/ike_sa_manager.c
@@ -886,9 +886,10 @@ static ike_sa_t* checkout(private_ike_sa_manager_t *this, ike_sa_id_t *ike_sa_id
 	{
 		if (wait_for_entry(this, entry, segment))
 		{
-			DBG2(DBG_MGR, "IKE_SA successfully checked out");
 			entry->checked_out = TRUE;
 			ike_sa = entry->ike_sa;
+			DBG2(DBG_MGR, "IKE_SA %s[%u] successfully checked out",
+					ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 		}
 		unlock_single_segment(this, segment);
 	}
@@ -916,7 +917,8 @@ static ike_sa_t *checkout_new(private_ike_sa_manager_t* this, bool initiator)
 	}
 	ike_sa = ike_sa_create(ike_sa_id);

-	DBG2(DBG_MGR, "created IKE_SA");
+	DBG2(DBG_MGR, "created IKE_SA %s[%u]", ike_sa->get_name(ike_sa),
+			ike_sa->get_unique_id(ike_sa));

 	if (!initiator)
 	{
@@ -971,10 +973,11 @@ static ike_sa_t* checkout_by_message(private_ike_sa_manager_t* this,
 			}
 			else if (wait_for_entry(this, entry, segment))
 			{
-				DBG2(DBG_MGR, "IKE_SA checked out by hash");
 				entry->checked_out = TRUE;
 				entry->message_id = message->get_message_id(message);
 				ike_sa = entry->ike_sa;
+				DBG2(DBG_MGR, "IKE_SA %s[%u] checked out by hash",
+						ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 			}
 			unlock_single_segment(this, segment);
 		}
@@ -998,7 +1001,8 @@ static ike_sa_t* checkout_by_message(private_ike_sa_manager_t* this,
 				entry->init_hash = hash;
 				ike_sa = entry->ike_sa;

-				DBG2(DBG_MGR, "created IKE_SA");
+				DBG2(DBG_MGR, "created IKE_SA %s[%u]",
+						ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 			}
 			else
 			{
@@ -1027,7 +1031,6 @@ static ike_sa_t* checkout_by_message(private_ike_sa_manager_t* this,
 		else if (wait_for_entry(this, entry, segment))
 		{
 			ike_sa_id_t *ike_id = entry->ike_sa->get_id(entry->ike_sa);
-			DBG2(DBG_MGR, "IKE_SA successfully checked out");
 			entry->checked_out = TRUE;
 			entry->message_id = message->get_message_id(message);
 			if (ike_id->get_responder_spi(ike_id) == 0)
@@ -1035,6 +1038,8 @@ static ike_sa_t* checkout_by_message(private_ike_sa_manager_t* this,
 				ike_id->set_responder_spi(ike_id, id->get_responder_spi(id));
 			}
 			ike_sa = entry->ike_sa;
+			DBG2(DBG_MGR, "IKE_SA %s[%u] successfully checked out",
+					ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 		}
 		unlock_single_segment(this, segment);
 	}
@@ -1056,6 +1061,8 @@ static ike_sa_t* checkout_by_config(private_ike_sa_manager_t *this,
 	ike_cfg_t *current_ike;
 	u_int segment;

+	DBG2(DBG_MGR, "checkout IKE_SA by config");
+
 	if (!this->reuse_ikesa)
 	{	/* IKE_SA reuse disable by config */
 		ike_sa = checkout_new(this, TRUE);
@@ -1081,10 +1088,11 @@ static ike_sa_t* checkout_by_config(private_ike_sa_manager_t *this,
 			current_ike = current_peer->get_ike_cfg(current_peer);
 			if (current_ike->equals(current_ike, peer_cfg->get_ike_cfg(peer_cfg)))
 			{
-				DBG2(DBG_MGR, "found an existing IKE_SA with a '%s' config",
-					 current_peer->get_name(current_peer));
 				entry->checked_out = TRUE;
 				ike_sa = entry->ike_sa;
+				DBG2(DBG_MGR, "found existing IKE_SA %u with a '%s' config",
+						ike_sa->get_unique_id(ike_sa),
+						current_peer->get_name(current_peer));
 				break;
 			}
 		}
@@ -1112,6 +1120,8 @@ static ike_sa_t* checkout_by_id(private_ike_sa_manager_t *this, u_int32_t id,
 	child_sa_t *child_sa;
 	u_int segment;

+	DBG2(DBG_MGR, "checkout IKE_SA by ID");
+
 	enumerator = create_table_enumerator(this);
 	while (enumerator->enumerate(enumerator, &entry, &segment))
 	{
@@ -1142,6 +1152,8 @@ static ike_sa_t* checkout_by_id(private_ike_sa_manager_t *this, u_int32_t id,
 			if (ike_sa)
 			{
 				entry->checked_out = TRUE;
+				DBG2(DBG_MGR, "IKE_SA %s[%u] successfully checked out",
+						ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 				break;
 			}
 		}
@@ -1195,6 +1207,8 @@ static ike_sa_t* checkout_by_name(private_ike_sa_manager_t *this, char *name,
 			if (ike_sa)
 			{
 				entry->checked_out = TRUE;
+				DBG2(DBG_MGR, "IKE_SA %s[%u] successfully checked out",
+						ike_sa->get_name(ike_sa), ike_sa->get_unique_id(ike_sa));
 				break;
 			}
 		}
@@ -1251,7 +1265,8 @@ static void checkin(private_ike_sa_manager_t *this, ike_sa_t *ike_sa)
 	other_id = ike_sa->get_other_id(ike_sa);
 	other = ike_sa->get_other_host(ike_sa);

-	DBG2(DBG_MGR, "checkin IKE_SA");
+	DBG2(DBG_MGR, "checkin IKE_SA %s[%u]", ike_sa->get_name(ike_sa),
+			ike_sa->get_unique_id(ike_sa));

 	/* look for the entry */
 	if (get_entry_by_sa(this, ike_sa_id, ike_sa, &entry, &segment) == SUCCESS)
@@ -1327,7 +1342,8 @@ static void checkin_and_destroy(private_ike_sa_manager_t *this, ike_sa_t *ike_sa

 	ike_sa_id = ike_sa->get_id(ike_sa);

-	DBG2(DBG_MGR, "checkin and destroy IKE_SA");
+	DBG2(DBG_MGR, "checkin and destroy IKE_SA %s[%u]", ike_sa->get_name(ike_sa),
+			ike_sa->get_unique_id(ike_sa));

 	if (get_entry_by_sa(this, ike_sa_id, ike_sa, &entry, &segment) == SUCCESS)
 	{
diff --git a/src/libcharon/sa/task_manager.c b/src/libcharon/sa/task_manager.c
index eeda6c8..4c8f3be 100644
--- a/src/libcharon/sa/task_manager.c
+++ b/src/libcharon/sa/task_manager.c
@@ -296,7 +296,8 @@ static status_t build_request(private_task_manager_t *this)

 	if (this->initiating.type != EXCHANGE_TYPE_UNDEFINED)
 	{
-		DBG2(DBG_IKE, "delaying task initiation, exchange in progress");
+		DBG2(DBG_IKE, "delaying task initiation, %N exchange in progress",
+				exchange_type_names, this->initiating.type);
 		/* do not initiate if we already have a message in the air */
 		return SUCCESS;
 	}
-- 1.5.6.5