From 65996a534da2438300a7311ddf72f35bccb600f6 Mon Sep 17 00:00:00 2001 From: Martin Willi Date: Wed, 24 May 2006 11:59:58 +0000 Subject: [PATCH] - some logging improvements and cosmetics --- src/charon/encoding/message.c | 7 +-- src/charon/sa/ike_sa.c | 4 +- src/charon/sa/states/ike_auth_requested.c | 8 ++- src/charon/sa/states/ike_sa_init_responded.c | 8 ++- src/libstrongswan/utils/logger.c | 55 ++++++++++++++++---- 5 files changed, 63 insertions(+), 19 deletions(-) diff --git a/src/charon/encoding/message.c b/src/charon/encoding/message.c index 9875a3df9..24b4d8e69 100644 --- a/src/charon/encoding/message.c +++ b/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)); diff --git a/src/charon/sa/ike_sa.c b/src/charon/sa/ike_sa.c index 8bc03d141..91f839a5b 100644 --- a/src/charon/sa/ike_sa.c +++ b/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 diff --git a/src/charon/sa/states/ike_auth_requested.c b/src/charon/sa/states/ike_auth_requested.c index 45e40bed4..47cc16f81 100644 --- a/src/charon/sa/states/ike_auth_requested.c +++ b/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_host->get_address(my_host), other_host->get_address(other_host)); + my_id = connection->get_my_id(connection); + 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; } diff --git a/src/charon/sa/states/ike_sa_init_responded.c b/src/charon/sa/states/ike_sa_init_responded.c index 249f05823..17d9e9db0 100644 --- a/src/charon/sa/states/ike_sa_init_responded.c +++ b/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_host->get_address(my_host), other_host->get_address(other_host)); + my_id = connection->get_my_id(connection); + 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; } diff --git a/src/libstrongswan/utils/logger.c b/src/libstrongswan/utils/logger.c index 728892b17..e99d1b07c 100644 --- a/src/libstrongswan/utils/logger.c +++ b/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;