- some logging improvements and cosmetics

src/charon/encoding/message.c

@@ -559,8 +559,9 @@ static status_t generate(private_message_t *this, crypter_t *crypter, signer_t*
 	status_t status;
 	chunk_t packet_data;
 	
-	this->logger->log(this->logger, CONTROL, "Generating message of type %s, contains %d payloads",
+	this->logger->log(this->logger, CONTROL, "Generating %s %s, contains %d payloads",
 					  mapping_find(exchange_type_m,this->exchange_type),
+					  this->is_request ? "request" : "response",
 					  this->payloads->get_count(this->payloads));
 	
 	if (this->exchange_type == EXCHANGE_TYPE_UNDEFINED)
@@ -717,7 +718,7 @@ static status_t parse_header(private_message_t *this)
 	this->minor_version = ike_header->get_min_version(ike_header);
 	this->first_payload = ike_header->payload_interface.get_next_type(&(ike_header->payload_interface));
 	
-	this->logger->log(this->logger, CONTROL, "Parsed a %s %s", 
+	this->logger->log(this->logger, CONTROL|LEVEL1, "Parsed a %s %s", 
 						mapping_find(exchange_type_m, this->exchange_type),
 						this->is_request ? "request" : "response");
 	
@@ -810,7 +811,7 @@ static status_t parse_body(private_message_t *this, crypter_t *crypter, signer_t
 		this->logger->log(this->logger, ERROR, "Verification of message failed");
 	}
 	
-	this->logger->log(this->logger, CONTROL, "Message %s %s contains %d payloads", 
+	this->logger->log(this->logger, CONTROL, "Parsed %s %s, contains %d payloads", 
 					mapping_find(exchange_type_m, this->exchange_type),
 					this->is_request ? "request" : "response",
 					this->payloads->get_count(this->payloads));

src/charon/sa/ike_sa.c

@@ -974,6 +974,7 @@ static status_t delete_(private_ike_sa_t *this)
 	delete_payload_t *delete_payload;
 	u_int32_t timeout;
 	delete_half_open_ike_sa_job_t *job;
+	state_t *old_state;
 	
 	if (get_state(this) != IKE_SA_ESTABLISHED)
 	{
@@ -995,8 +996,9 @@ static status_t delete_(private_ike_sa_t *this)
 	}
 	
 	/* transit to state delete_requested */
-	this->current_state->destroy(this->current_state);
+	old_state = this->current_state;
 	set_new_state(this, (state_t*)delete_requested_create(this));
+	old_state->destroy(old_state);
 	
 	/* there is no guarantee that the other peer will acknowledge the delete,
 	 * so we have to set a timeout where we destroy the SA... This is done with

src/charon/sa/states/ike_auth_requested.c

@@ -184,6 +184,7 @@ static status_t process_message(private_ike_auth_requested_t *this, message_t *i
 	signer_t *signer = NULL;
 	status_t status;
 	host_t *my_host, *other_host;
+	identification_t *my_id, *other_id;
 	chunk_t seed;
 	prf_plus_t *prf_plus;
 	connection_t *connection;
@@ -361,8 +362,11 @@ static status_t process_message(private_ike_auth_requested_t *this, message_t *i
 	connection = this->ike_sa->get_connection(this->ike_sa);
 	my_host = connection->get_my_host(connection);
 	other_host = connection->get_other_host(connection);
-	this->logger->log(this->logger, AUDIT, "IKE_SA established between %s - %s", 
+	my_id = connection->get_my_id(connection);
-					  my_host->get_address(my_host), other_host->get_address(other_host));
+	other_id = connection->get_other_id(connection);
+	this->logger->log(this->logger, AUDIT, "IKE_SA established %s[%s]...%s[%s]", 
+					  my_host->get_address(my_host), my_id->get_string(my_id),
+					  other_host->get_address(other_host), other_id->get_string(other_id));
 	
 	return SUCCESS;
 }

src/charon/sa/states/ike_sa_init_responded.c

@@ -183,6 +183,7 @@ static status_t process_message(private_ike_sa_init_responded_t *this, message_t
 	signer_t *signer;
 	status_t status;
 	host_t *my_host, *other_host;
+	identification_t *my_id, *other_id;
 	connection_t *connection;
 	
 	if (request->get_exchange_type(request) != IKE_AUTH)
@@ -367,8 +368,11 @@ static status_t process_message(private_ike_sa_init_responded_t *this, message_t
 	connection = this->ike_sa->get_connection(this->ike_sa);
 	my_host = connection->get_my_host(connection);
 	other_host = connection->get_other_host(connection);
-	this->logger->log(this->logger, AUDIT, "IKE_SA established between %s - %s", 
+	my_id = connection->get_my_id(connection);
-					  my_host->get_address(my_host), other_host->get_address(other_host));
+	other_id = connection->get_other_id(connection);
+	this->logger->log(this->logger, AUDIT, "IKE_SA established %s[%s]...%s[%s]", 
+					  my_host->get_address(my_host), my_id->get_string(my_id),
+					  other_host->get_address(other_host), other_id->get_string(other_id));
 
 	return SUCCESS;
 }

src/libstrongswan/utils/logger.c

@@ -70,13 +70,46 @@ struct private_logger_t {
 	bool log_thread_id;
 };
 
+/**
+ * thread local storage for get_thread_number
+ */
+static pthread_key_t thread_ids;
+static void make_key(void)
+{
+	pthread_key_create(&thread_ids, NULL);
+}
+
+/**
+ * Get a unique thread number for a calling thread. Since
+ * pthread_self returns large and ugly numbers, use this function
+ * for logging; these numbers are incremental starting at 1
+ */
+static int get_thread_number(void)
+{
+	static int current_num = 0;
+	static pthread_once_t key_once = PTHREAD_ONCE_INIT;
+	int stored_num;
+	
+	pthread_once(&key_once, make_key);
+	stored_num = (int)pthread_getspecific(thread_ids);
+	if (stored_num == 0)
+	{
+		pthread_setspecific(thread_ids, (void*)++current_num);
+		return current_num;
+	}
+	else
+	{
+		return stored_num;
+	}
+}
+
 /**
  * prepend the logging prefix to string and store it in buffer
  */
 static void prepend_prefix(private_logger_t *this, log_level_t loglevel, const char *string, char *buffer)
 {
 	char log_type, log_details;
-	char thread_id[10] = "";
+	u_int8_t thread_id = 0;
 
 	if (loglevel & CONTROL)
 	{
@@ -122,9 +155,9 @@ static void prepend_prefix(private_logger_t *this, log_level_t loglevel, const c
 	
 	if (this->log_thread_id)
 	{
-		snprintf(thread_id, sizeof(thread_id), "%06d", (int)pthread_self());
+		thread_id = get_thread_number();
 	}
-	snprintf(buffer, MAX_LOG, "%s[%c%c:%s] %s", thread_id, log_type, log_details, this->name, string);
+	snprintf(buffer, MAX_LOG, "[%02d:%c%c:%s] %s", thread_id, log_type, log_details, this->name, string);
 }
 
 /**
@@ -186,7 +219,7 @@ static void log_bytes(private_logger_t *this, log_level_t loglevel, const char *
 
 	if ((this->level & loglevel) == loglevel)
 	{
-		char thread_id[10] = "";
+		u_int8_t thread_id = 0;
 		char buffer[MAX_LOG];
 		char ascii_buffer[MAX_BYTES+1];
 
@@ -198,11 +231,6 @@ static void log_bytes(private_logger_t *this, log_level_t loglevel, const char *
 		int line_start = 0;
 		int i = 0;
 
-		if (this->log_thread_id)
-		{
-			snprintf(thread_id, sizeof(thread_id), "%06d", (int)pthread_self());
-		}
-
 		/* since me can't do multi-line output to syslog, 
 		* we must do multiple syslogs. To avoid
 		* problems in output order, lock this by a mutex.
@@ -210,6 +238,11 @@ static void log_bytes(private_logger_t *this, log_level_t loglevel, const char *
 		pthread_mutex_lock(&mutex);
 
 		prepend_prefix(this, loglevel, format, buffer);
+		
+		if (this->log_thread_id)
+		{
+			thread_id = get_thread_number();
+		}
 
 		if (this->output == NULL)
 		{
@@ -244,11 +277,11 @@ static void log_bytes(private_logger_t *this, log_level_t loglevel, const char *
 
 				if (this->output == NULL)
 				{
-					syslog(get_priority(loglevel), "%s[  :%5d]   %s  %s", thread_id, line_start, buffer, ascii_buffer);	
+					syslog(get_priority(loglevel), "[%02d:  :%5d]  %s  %s", thread_id, line_start, buffer, ascii_buffer);	
 				}
 				else
 				{
-					fprintf(this->output, "%s[  :%5d]   %s  %s\n", thread_id, line_start, buffer, ascii_buffer);
+					fprintf(this->output, "[%02d:  :%5d]  %s  %s\n", thread_id, line_start, buffer, ascii_buffer);
 				}
 				buffer_pos = buffer;
 				line_start += MAX_BYTES;