From 21e2a4de851133d1446c21a3bbca60042d76d8b4 Mon Sep 17 00:00:00 2001 From: kakwa Date: Fri, 2 Sep 2016 00:36:25 +0200 Subject: [PATCH] implement better query and response logging * recover the serial * add the serial in many logs * add response log * add timer --- inc/rfc3161.h | 2 +- inc/utils.h | 1 + src/lib/http.c | 83 ++++++++++++++++++++++++++++++++++++++--------- src/lib/rfc3161.c | 51 +++++++++++++++++++++++------ src/lib/utils.c | 2 +- 5 files changed, 111 insertions(+), 28 deletions(-) diff --git a/inc/rfc3161.h b/inc/rfc3161.h index 04a79b9..6a09efc 100644 --- a/inc/rfc3161.h +++ b/inc/rfc3161.h @@ -31,7 +31,7 @@ static int reply_command(CONF *conf, char *section, char *engine, char *query, static TS_RESP *read_PKCS7(BIO *in_bio); int create_response(rfc3161_context *ct, char *query, int query_len, TS_RESP_CTX *resp_ctx, size_t *resp_size, - unsigned char **resp); + unsigned char **resp, char **serial_id); static ASN1_INTEGER *serial_cb(TS_RESP_CTX *ctx, void *data); static ASN1_INTEGER *next_serial(const char *serialfile); static int save_ts_serial(const char *serialfile, ASN1_INTEGER *serial); diff --git a/inc/utils.h b/inc/utils.h index 461819a..e225f38 100644 --- a/inc/utils.h +++ b/inc/utils.h @@ -7,5 +7,6 @@ void uts_logger(rfc3161_context *ct, int priority, char *fmt, ...); void log_hex(rfc3161_context *ct, int priority, char *id, unsigned char *content, int content_length); int set_params(rfc3161_context *ct, char *conf_file, char *conf_wd); +static char *rand_string(char *str, size_t size); int g_uts_sig_up; int g_uts_sig; diff --git a/src/lib/http.c b/src/lib/http.c index 8f90be2..1329cf0 100644 --- a/src/lib/http.c +++ b/src/lib/http.c @@ -13,32 +13,46 @@ #include #include #include +#include #include "http.h" +static char *rand_string(char *str, size_t size) { + const char charset[] = "1234567890ABCDEF"; + if (size) { + --size; + for (size_t n = 0; n < size; n++) { + int key = rand() % (int)(sizeof charset - 1); + str[n] = charset[key]; + } + str[size] = '\0'; + } + return str; +} + void log_request_debug(const struct mg_request_info *request_info, - int request_id, void *context) { + char *request_id, void *context) { for (int i = 0; i < request_info->num_headers; i++) { - uts_logger(context, LOG_DEBUG, "Request[%d], Header[%s]: %s", + uts_logger(context, LOG_DEBUG, "Request[%s], Header[%s]: %s", request_id, request_info->http_headers[i].name, request_info->http_headers[i].value); } - uts_logger(context, LOG_DEBUG, "Request[%d], request_method: %s", + uts_logger(context, LOG_DEBUG, "Request[%s], request_method: %s", request_id, request_info->request_method); - uts_logger(context, LOG_DEBUG, "Request[%d], request_uri: %s", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], request_uri: %s", request_id, request_info->request_uri); - uts_logger(context, LOG_DEBUG, "Request[%d], local_uri: %s", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], local_uri: %s", request_id, request_info->local_uri); - uts_logger(context, LOG_DEBUG, "Request[%d], http_version: %s", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], http_version: %s", request_id, request_info->http_version); - uts_logger(context, LOG_DEBUG, "Request[%d], query_string: %s", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], query_string: %s", request_id, request_info->query_string); - uts_logger(context, LOG_DEBUG, "Request[%d], remote_addr: %s", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], remote_addr: %s", request_id, request_info->remote_addr); - uts_logger(context, LOG_DEBUG, "Request[%d], is_ssl: %d", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], is_ssl: %d", request_id, request_info->is_ssl); - uts_logger(context, LOG_DEBUG, "Request[%d], content_length: %d", + uts_logger(context, LOG_DEBUG, "Request[%s], content_length: %d", request_id, request_info->content_length); - uts_logger(context, LOG_DEBUG, "Request[%d], remote_port: %d", request_id, + uts_logger(context, LOG_DEBUG, "Request[%s], remote_port: %d", request_id, request_info->remote_port); // uts_logger(context, LOG_DEBUG, "Request[%d], user_data: %s", // request_id, @@ -48,6 +62,28 @@ void log_request_debug(const struct mg_request_info *request_info, // request_info->conn_data); } +void log_request(const struct mg_request_info *request_info, char *request_id, + void *context, int response_code, int timer) { + const char *user_agent = NULL; + const char *content_type = NULL; + + for (int i = 0; i < request_info->num_headers; i++) { + if (strcmp(request_info->http_headers[i].name, "User-Agent") == 0) { + user_agent = request_info->http_headers[i].value; + } + if (strcmp(request_info->http_headers[i].name, "Content-Type") == 0) { + content_type = request_info->http_headers[i].value; + } + } + + uts_logger(context, LOG_INFO, "Request[%s], remote_addr[%s] ssl[%d] " + "uri[%s] http_resp_code[%d] duration[%d us] " + "user-agent[%s] content-type[%s]", + request_id, request_info->remote_addr, request_info->is_ssl, + request_info->local_uri, response_code, timer, user_agent, + content_type); +} + // This function will be called by civetweb on every new request. static int begin_request_handler(struct mg_connection *conn) { const struct mg_request_info *request_info = mg_get_request_info(conn); @@ -65,13 +101,15 @@ static int begin_request_handler(struct mg_connection *conn) { } int rfc3161_handler(struct mg_connection *conn, void *context) { + // some timer stuff + clock_t start = clock(), diff; /* Handler may access the request info using mg_get_request_info */ const struct mg_request_info *request_info = mg_get_request_info(conn); rfc3161_context *ct = (rfc3161_context *)context; int ret; + int resp_code; ct->query_counter++; uint64_t query_id = ct->query_counter; - log_request_debug(request_info, query_id, ct); bool is_tsq = 0; @@ -86,6 +124,8 @@ int rfc3161_handler(struct mg_connection *conn, void *context) { unsigned char *content = NULL; size_t content_length = 0; + char *serial_id = NULL; + // Send HTTP reply to the client if (is_tsq) { char *query = calloc(request_info->content_length, sizeof(char)); @@ -95,8 +135,9 @@ int rfc3161_handler(struct mg_connection *conn, void *context) { request_info->content_length); int ts_resp = create_response(ct, query, query_len, ct->ts_ctx, - &content_length, &content); + &content_length, &content, &serial_id); if (ts_resp) { + resp_code = 200; mg_printf(conn, "HTTP/1.1 200 OK\r\n" "Content-Type: application/timestamp-reply\r\n" @@ -106,17 +147,18 @@ int rfc3161_handler(struct mg_connection *conn, void *context) { mg_write(conn, content, content_length); log_hex(ct, LOG_DEBUG, "response hexdump content", content, content_length); - - free(content); } else { + resp_code = 500; mg_printf(conn, - "HTTP/1.1 500 OK\r\n" + "HTTP/1.1 500 Internal Server Error\r\n" "Content-Type: text/plain\r\n" "Content-Length: 17\r\n" // Always set Content-Length "\r\n" "uts-server error"); } + free(content); } else { + resp_code = 200; mg_printf(conn, "HTTP/1.1 200 OK\r\n" "Content-Type: text/plain\r\n" @@ -124,7 +166,16 @@ int rfc3161_handler(struct mg_connection *conn, void *context) { "\r\n" "uts-server, a simple RFC 3161 timestamp server"); } + if (serial_id == NULL) { + serial_id = calloc(8, sizeof(char)); + serial_id = rand_string(serial_id, 8); + } + log_request_debug(request_info, serial_id, ct); + diff = clock() - start; + log_request(request_info, serial_id, ct, resp_code, + (diff * 1000000 / CLOCKS_PER_SEC)); + free(serial_id); return 1; } diff --git a/src/lib/rfc3161.c b/src/lib/rfc3161.c index f23d368..afd951f 100644 --- a/src/lib/rfc3161.c +++ b/src/lib/rfc3161.c @@ -25,6 +25,9 @@ #define OID_SECTION "oids" +// number of char we get to log for the serial +#define SERIAL_ID_SIZE 8 + /* Reply related functions. */ static int reply_command(CONF *conf, char *section, char *engine, char *query, char *passin, char *inkey, const EVP_MD *md, @@ -173,11 +176,12 @@ end: int create_response(rfc3161_context *ct, char *query, int query_len, TS_RESP_CTX *resp_ctx, size_t *resp_size, - unsigned char **resp) { + unsigned char **resp, char **serial_id) { int ret = 0; TS_RESP *ts_response = NULL; BIO *query_bio = NULL; BIO *out_bio = NULL; + BIO *text_bio = BIO_new(BIO_s_mem()); BIO *status_bio = BIO_new(BIO_s_mem()); ; unsigned long err_code; @@ -206,43 +210,69 @@ end: TS_STATUS_INFO_print_bio(status_bio, ts_response->status_info); BIO_get_mem_ptr(status_bio, &bptr); + ASN1_INTEGER *serial = ts_response->tst_info->serial; + BIGNUM *serial_bn = ASN1_INTEGER_to_BN(serial, NULL); + char *serial_hex = BN_bn2hex(serial_bn); + BN_free(serial_bn); + *serial_id = calloc(SERIAL_ID_SIZE, sizeof(char)); + strncpy(*serial_id, serial_hex, SERIAL_ID_SIZE); + // replacing '\n' by '|' to log on one line only char *temp = strstr(bptr->data, "\n"); while ((temp = strstr(bptr->data, "\n")) != NULL) { temp[0] = '|'; } - uts_logger(ct, LOG_DEBUG, "TimeStamp OpenSSL status: |%s", bptr->data); + uts_logger(ct, LOG_DEBUG, + "timestamp full serial: %s (response serial '%s...')", + serial_hex, *serial_id); + uts_logger(ct, LOG_DEBUG, + "TimeStamp OpenSSL status: |%s (response serial '%s...')", + bptr->data, *serial_id); BUF_MEM_free(bptr); long status = ASN1_INTEGER_get(ts_response->status_info->status); switch (status) { case TS_STATUS_GRANTED: - uts_logger(ct, LOG_INFO, "timestamp request granted"); + uts_logger(ct, LOG_INFO, + "timestamp request granted (response serial '%s...')", + *serial_id); ret = 1; break; case TS_STATUS_GRANTED_WITH_MODS: - uts_logger(ct, LOG_NOTICE, - "timestamp request granted with modification"); + uts_logger(ct, LOG_NOTICE, "timestamp request granted with " + "modification (response serial '%s...')", + *serial_id); ret = 1; break; case TS_STATUS_REJECTION: - uts_logger(ct, LOG_WARNING, "timestamp request rejected"); + uts_logger(ct, LOG_WARNING, + "timestamp request rejected (response serial '%s...')", + *serial_id); ret = 0; break; case TS_STATUS_WAITING: - uts_logger(ct, LOG_NOTICE, "timestamp request waiting"); + uts_logger(ct, LOG_NOTICE, + "timestamp request waiting (response serial '%s...')", + *serial_id); ret = 0; break; case TS_STATUS_REVOCATION_WARNING: - uts_logger(ct, LOG_WARNING, "timestamp request revocation warning"); + uts_logger( + ct, LOG_WARNING, + "timestamp request revocation warning (response serial '%s...')", + *serial_id); ret = 0; break; case TS_STATUS_REVOCATION_NOTIFICATION: - uts_logger(ct, LOG_NOTICE, "timestamp request revovation notification"); + uts_logger(ct, LOG_NOTICE, "timestamp request revovation notification " + "(response serial '%s...')", + *serial_id); ret = 0; break; default: - uts_logger(ct, LOG_ERR, "unknown error code '%d'", status); + uts_logger(ct, LOG_ERR, + "unknown error code '%d' (response serial '%s...')", status, + *serial_id); ret = 0; } @@ -259,6 +289,7 @@ end: } // BIO_free_all(status_bio); TS_RESP_free(ts_response); + free(serial_hex); return ret; } diff --git a/src/lib/utils.c b/src/lib/utils.c index ec5514a..6f3fbf3 100644 --- a/src/lib/utils.c +++ b/src/lib/utils.c @@ -146,7 +146,7 @@ void log_hex(rfc3161_context *ct, int priority, char *id, stream = open_memstream(&out, &len); for (int i = 0; i < content_length; i++) { - fprintf(stream, "%02x ", content[i]); + fprintf(stream, "%02x", content[i]); } fflush(stream); fclose(stream);