- fixed bad bugs in kernel interface

- added some logging info
- works now much more stable

Source/charon/threads/kernel_interface.c

@@ -123,7 +123,11 @@ struct private_kernel_interface_t {
 	 */
 	int socket;
 	
+	/**
+	 * Process id of kernel thread
+	 */
 	pid_t pid;
+	
 	/**
 	 * Sequence number for messages.
 	 */
@@ -149,6 +153,11 @@ struct private_kernel_interface_t {
 	 */
 	pthread_cond_t condvar;
 	
+	/**
+	 * Logger for XFRM stuff
+	 */
+	logger_t *logger;
+	
 	/**
 	 * Function for the thread, receives messages.
 	 */
@@ -196,6 +205,7 @@ mapping_t kernel_integrity_algs_m[] = {
 	{MAPPING_END, NULL}
 };
 
+
 /**
  * Implementation of kernel_interface_t.get_spi.
  */
@@ -207,6 +217,9 @@ static status_t get_spi(private_kernel_interface_t *this,
 	netlink_message_t request, *response;
 	status_t status = SUCCESS;
 	
+	
+	this->logger->log(this->logger, CONTROL|LEVEL2, "getting spi");
+	
 	memset(&request, 0, sizeof(request));
 	request.hdr.nlmsg_len = NLMSG_ALIGN(NLMSG_LENGTH(sizeof(request.spi)));
 	request.hdr.nlmsg_flags = NLM_F_REQUEST;
@@ -222,22 +235,29 @@ static status_t get_spi(private_kernel_interface_t *this,
 	
 	if (this->send_message(this, &request, &response) != SUCCESS)
 	{
-		status = FAILED;
+		this->logger->log(this->logger, ERROR, "netlink communication failed");
+		return FAILED;
 	}
 	else if (response->hdr.nlmsg_type == NLMSG_ERROR)
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_ALLOCSPI got an error: %s",
+						  strerror(-response->e.error));
 		status = FAILED;
 	}
 	else if (response->hdr.nlmsg_type != XFRM_MSG_NEWSA)
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_ALLOCSPI got a unknown reply");
 		status = FAILED;
 	}
 	else if (response->hdr.nlmsg_len < NLMSG_LENGTH(sizeof(response->sa)))
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_ALLOCSPI got an invalid reply");
 		status = FAILED;
 	}
-	
+	else
-	*spi = response->sa.id.spi;
+	{
+		*spi = response->sa.id.spi;
+	}
 	free(response);
 	
 	return status;
@@ -260,7 +280,9 @@ static status_t add_sa(	private_kernel_interface_t *this,
 {
 	netlink_message_t request, *response;
 	memset(&request, 0, sizeof(request));
-	status_t status;
+	status_t status = SUCCESS;
+	
+	this->logger->log(this->logger, CONTROL|LEVEL2, "adding SA");
 	
 	request.hdr.nlmsg_flags = NLM_F_REQUEST | NLM_F_ACK;
 	request.hdr.nlmsg_type = replace ? XFRM_MSG_UPDSA : XFRM_MSG_NEWSA;
@@ -317,19 +339,23 @@ static status_t add_sa(	private_kernel_interface_t *this,
 	
 	if (this->send_message(this, &request, &response) != SUCCESS)
 	{
-		status = FAILED;
+		this->logger->log(this->logger, ERROR, "netlink communication failed");
+		return FAILED;
 	}
 	else if (response->hdr.nlmsg_type != NLMSG_ERROR)
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_NEWSA not acknowledged");
 		status = FAILED;
 	}
 	else if (response->e.error)
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_NEWSA got error %s",
+						  strerror(-response->e.error));
 		status = FAILED;
 	}
 	
 	free(response);
-	return SUCCESS;
+	return status;
 }
 
 static status_t del_sa(	private_kernel_interface_t *this,
@@ -339,7 +365,9 @@ static status_t del_sa(	private_kernel_interface_t *this,
 {
 	netlink_message_t request, *response;
 	memset(&request, 0, sizeof(request));
-	status_t status;
+	status_t status = SUCCESS;
+	
+	this->logger->log(this->logger, CONTROL|LEVEL2, "deleting SA");
 	
 	request.hdr.nlmsg_flags = NLM_F_REQUEST | NLM_F_ACK;
 	request.hdr.nlmsg_type = XFRM_MSG_DELSA;
@@ -354,7 +382,7 @@ static status_t del_sa(	private_kernel_interface_t *this,
 	
 	if (this->send_message(this, &request, &response) != SUCCESS)
 	{
-		status = FAILED;
+		return FAILED;
 	}
 	else if (response->hdr.nlmsg_type != NLMSG_ERROR)
 	{
@@ -366,7 +394,7 @@ static status_t del_sa(	private_kernel_interface_t *this,
 	}
 	
 	free(response);
-	return SUCCESS;
+	return status;
 }
 
 /**
@@ -383,6 +411,8 @@ static status_t add_policy(private_kernel_interface_t *this,
 	netlink_message_t request, *response;
 	status_t status = SUCCESS;
 	
+	this->logger->log(this->logger, CONTROL|LEVEL2, "adding policy");
+	
 	memset(&request, 0, sizeof(request));
 	request.hdr.nlmsg_flags = NLM_F_REQUEST | NLM_F_ACK;
 
@@ -446,14 +476,18 @@ static status_t add_policy(private_kernel_interface_t *this,
 	
 	if (this->send_message(this, &request, &response) != SUCCESS)
 	{
-		status = FAILED;
+		this->logger->log(this->logger, ERROR, "netlink communication failed");
+		return FAILED;
 	}
 	else if (response->hdr.nlmsg_type != NLMSG_ERROR)
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_NEWPOLICY not acknowledged");
 		status = FAILED;
 	}
 	else if (response->e.error)
 	{
+		this->logger->log(this->logger, ERROR, "netlink request XFRM_MSG_NEWPOLICY got error %s",
+						  strerror(-response->e.error));
 		status = FAILED;
 	}
 	
@@ -473,6 +507,9 @@ static status_t del_policy(private_kernel_interface_t *this,
 	netlink_message_t request, *response;
 	status_t status = SUCCESS;
 	
+	
+	this->logger->log(this->logger, CONTROL|LEVEL2, "deleting policy");
+	
 	memset(&request, 0, sizeof(request));
 	request.hdr.nlmsg_flags = NLM_F_REQUEST | NLM_F_ACK;
 
@@ -494,7 +531,7 @@ static status_t del_policy(private_kernel_interface_t *this,
 	
 	if (this->send_message(this, &request, &response) != SUCCESS)
 	{
-		status = FAILED;
+		return FAILED;
 	}
 	else if (response->hdr.nlmsg_type != NLMSG_ERROR)
 	{
@@ -668,23 +705,25 @@ kernel_interface_t *kernel_interface_create()
 	this->send_message = send_message;
 	this->pid = getpid();
 	this->responses = linked_list_create();
+	this->logger = logger_manager->get_logger(logger_manager, XFRM);
 	pthread_mutex_init(&(this->mutex),NULL);
 	pthread_cond_init(&(this->condvar),NULL);
 	this->seq = 0;
 	this->socket = socket(PF_NETLINK, SOCK_RAW, NETLINK_XFRM);
 	if (this->socket <= 0)
 	{
+		this->responses->destroy(this->responses);
 		free(this);
 		charon->kill(charon, "Unable to create netlink socket");	
 	}
 	
 	if (pthread_create(&(this->thread), NULL, (void*(*)(void*))this->receive_messages, this) != 0)
 	{
+		this->responses->destroy(this->responses);
 		close(this->socket);
 		free(this);
 		charon->kill(charon, "Unable to create netlink thread");
 	}
 	
-	logger_manager->enable_log_level(logger_manager, TESTER, FULL);
 	return (&this->public);
 }

Source/charon/threads/stroke_interface.c

@@ -210,14 +210,18 @@ static rsa_private_key_t *find_private_key(private_stroke_t *this, rsa_public_ke
 	rsa_private_key_t *private_key = NULL;
 	iterator_t *iterator;
 	
+	this->logger->log(this->logger, CONTROL|LEVEL2, "Looking up private key by public key...");
+	
 	iterator = this->private_keys->create_iterator(this->private_keys, TRUE);
 	while (iterator->has_next(iterator))
 	{
 		iterator->current(iterator, (void**)&private_key);
 		if (private_key->belongs_to(private_key, public_key))
 		{
+			this->logger->log(this->logger, CONTROL|LEVEL2, "found a match");
 			break;
 		}
+		this->logger->log(this->logger, CONTROL|LEVEL2, "this one did not match");
 	}
 	iterator->destroy(iterator);
 	return private_key;
@@ -257,7 +261,7 @@ static void load_private_keys(private_stroke_t *this)
 			}
 			else
 			{
-				this->logger->log(this->logger, CONTROL|LEVEL1, "private key \"%s%s\" invalid, skipped", 
+				this->logger->log(this->logger, ERROR, "private key \"%s%s\" invalid, skipped", 
 								  PRIVATE_KEY_DIR, entry->d_name);
 			}
 		}
@@ -641,7 +645,7 @@ static void stroke_loglevel(private_stroke_t *this, stroke_msg_t *msg)
 {
 	pop_string(msg, &(msg->loglevel.context));
 	
-	this->logger->log(this->logger, CONTROL, "received stroke: log_level for %s", msg->loglevel.context);
+	this->logger->log(this->logger, CONTROL, "received stroke: loglevel for %s", msg->loglevel.context);
 	
 	log_level_t level;
 	logger_context_t context = get_context(msg->loglevel.context);

Source/lib/utils/logger.c

@@ -124,11 +124,11 @@ static void prepend_prefix(private_logger_t *this, log_level_t loglevel, char *s
 	
 	if (this->log_thread_id)
 	{
-		snprintf(buffer, MAX_LOG, "[%c%c] [%s] @%u %s", log_type, log_details, this->name, (int)pthread_self(), string);
+		snprintf(buffer, MAX_LOG, "[%c%c:%s] @%u %s", log_type, log_details, this->name, (int)pthread_self(), string);
 	}
 	else
 	{
-		snprintf(buffer, MAX_LOG, "[%c%c] [%s] %s", log_type, log_details, this->name, string);
+		snprintf(buffer, MAX_LOG, "[%c%c:%s] %s", log_type, log_details, this->name, string);
 	}
 }
 
@@ -220,11 +220,11 @@ static void log_bytes(private_logger_t *this, log_level_t loglevel, char *label,
 				buffer_pos = buffer;
 				if (this->output == NULL)
 				{
-					syslog(LOG_INFO, "[=>] [%5d] %s %s", line_start, buffer, ascii_buffer);	
+					syslog(LOG_INFO, "[  :%5d] %s %s", line_start, buffer, ascii_buffer);	
 				}
 				else
 				{
-					fprintf(this->output, "[=>] [%5d] %s %s\n", line_start, buffer, ascii_buffer);
+					fprintf(this->output, "[  :%5d] %s %s\n", line_start, buffer, ascii_buffer);
 				}
 				memset(ascii_buffer, 0, 16);
 				line_start += 16;
@@ -257,11 +257,11 @@ static void log_bytes(private_logger_t *this, log_level_t loglevel, char *label,
 			buffer_pos = buffer;
 			if (this->output == NULL)
 			{		
-				syslog(LOG_INFO, "[=>] [%5d] %s %16s", line_start, buffer, ascii_buffer);
+				syslog(LOG_INFO, "[  :%5d] %s %16s", line_start, buffer, ascii_buffer);
 			}
 			else
 			{
-				fprintf(this->output, "[=>] [%5d] %s %16s\n", line_start, buffer, ascii_buffer);
+				fprintf(this->output, "[  :%5d] %s %16s\n", line_start, buffer, ascii_buffer);
 			}
 		}
 		pthread_mutex_unlock(&mutex);

Source/lib/utils/logger_manager.c

@@ -78,7 +78,8 @@ struct {
 	{ "PAYLD", ERROR|CONTROL|AUDIT|LEVEL0,	TRUE }, /* PAYLOAD */
 	{ "DERDC", ERROR|CONTROL|AUDIT|LEVEL0,	TRUE }, /* DER_DECODER */
 	{ "DEREC", ERROR|CONTROL|AUDIT|LEVEL0,	TRUE }, /* DER_ENCODER */
-	{ "ASN_1", ERROR|CONTROL|AUDIT|RAW|LEVEL3,	TRUE }, /* ASN1 */
+	{ "ASN_1", ERROR|CONTROL|AUDIT|LEVEL0,	TRUE }, /* ASN1 */
+	{ "XFRM ", ERROR|CONTROL|AUDIT|LEVEL0,	TRUE }, /* XFRM */
 };
 
 
@@ -198,7 +199,7 @@ void __attribute__ ((constructor)) logger_manager_create()
 		private_logger_manager.loggers[i] = logger_create(logger_defaults[i].name,
 														  logger_defaults[i].level, 
 														  logger_defaults[i].log_thread_ids, 
-														  stdout);
+														  INITIAL_LOG_OUTPUT);
 	}
 	
 }

Source/lib/utils/logger_manager.h

@@ -27,6 +27,7 @@
 
 #include <utils/logger.h>
 
+#define INITIAL_LOG_OUTPUT stderr
 
 typedef enum logger_context_t logger_context_t;
 
@@ -57,6 +58,7 @@ enum logger_context_t {
 	DER_DECODER,
 	DER_ENCODER,
 	ASN1,
+	XFRM,
 	LOGGER_CONTEXT_ROOF,
 };