security-and-privacy/uts-server
security-and-privacy/uts-server
1
0
Fork 0
mirror of https://github.com/kakwa/uts-server synced 2025-01-10 05:34:29 +01:00
Code Issues Releases Wiki Activity

implement better query and response logging

Browse Source 
* recover the serial
* add the serial in many logs
* add response log
* add timer
This commit is contained in:
kakwa 2016-09-02 00:36:25 +02:00
parent d36c2b4286
commit 16a34d9c7d
5 changed files with 111 additions and 28 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
inc/rfc3161.h
View File

@ -31,7 +31,7 @@ static int reply_command(CONF *conf, char *section, char *engine, char *query,
static TS_RESP *read_PKCS7(BIO *in_bio); static TS_RESP *read_PKCS7(BIO *in_bio);
int create_response(rfc3161_context *ct, char *query, int query_len, int create_response(rfc3161_context *ct, char *query, int query_len,
TS_RESP_CTX *resp_ctx, size_t *resp_size, 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 *serial_cb(TS_RESP_CTX *ctx, void *data);
static ASN1_INTEGER *next_serial(const char *serialfile); static ASN1_INTEGER *next_serial(const char *serialfile);
static int save_ts_serial(const char *serialfile, ASN1_INTEGER *serial); static int save_ts_serial(const char *serialfile, ASN1_INTEGER *serial);

1
inc/utils.h
View File

@ -7,5 +7,6 @@ void uts_logger(rfc3161_context *ct, int priority, char *fmt, ...);
void log_hex(rfc3161_context *ct, int priority, char *id, void log_hex(rfc3161_context *ct, int priority, char *id,
unsigned char *content, int content_length); unsigned char *content, int content_length);
int set_params(rfc3161_context *ct, char *conf_file, char *conf_wd); 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_up;
int g_uts_sig; int g_uts_sig;

83
src/lib/http.c
View File

@ -13,32 +13,46 @@
#include <stdbool.h> #include <stdbool.h>
#include <sys/syslog.h> #include <sys/syslog.h>
#include <unistd.h> #include <unistd.h>
#include <time.h>
#include "http.h" #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, 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++) { 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_id, request_info->http_headers[i].name,
request_info->http_headers[i].value); 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); 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); 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); 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); 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); 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); 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); 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); 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); request_info->remote_port);
// uts_logger(context, LOG_DEBUG, "Request[%d], user_data: %s", // uts_logger(context, LOG_DEBUG, "Request[%d], user_data: %s",
// request_id, // request_id,
@ -48,6 +62,28 @@ void log_request_debug(const struct mg_request_info *request_info,
// request_info->conn_data); // 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. // This function will be called by civetweb on every new request.
static int begin_request_handler(struct mg_connection *conn) { static int begin_request_handler(struct mg_connection *conn) {
const struct mg_request_info *request_info = mg_get_request_info(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) { 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 */ /* Handler may access the request info using mg_get_request_info */
const struct mg_request_info *request_info = mg_get_request_info(conn); const struct mg_request_info *request_info = mg_get_request_info(conn);
rfc3161_context *ct = (rfc3161_context *)context; rfc3161_context *ct = (rfc3161_context *)context;
int ret; int ret;
int resp_code;
ct->query_counter++; ct->query_counter++;
uint64_t query_id = ct->query_counter; uint64_t query_id = ct->query_counter;
log_request_debug(request_info, query_id, ct);
bool is_tsq = 0; bool is_tsq = 0;
@ -86,6 +124,8 @@ int rfc3161_handler(struct mg_connection *conn, void *context) {
unsigned char *content = NULL; unsigned char *content = NULL;
size_t content_length = 0; size_t content_length = 0;
char *serial_id = NULL;
// Send HTTP reply to the client // Send HTTP reply to the client
if (is_tsq) { if (is_tsq) {
char *query = calloc(request_info->content_length, sizeof(char)); 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); request_info->content_length);
int ts_resp = create_response(ct, query, query_len, ct->ts_ctx, int ts_resp = create_response(ct, query, query_len, ct->ts_ctx,
&content_length, &content); &content_length, &content, &serial_id);
if (ts_resp) { if (ts_resp) {
resp_code = 200;
mg_printf(conn, mg_printf(conn,
"HTTP/1.1 200 OK\r\n" "HTTP/1.1 200 OK\r\n"
"Content-Type: application/timestamp-reply\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); mg_write(conn, content, content_length);
log_hex(ct, LOG_DEBUG, "response hexdump content", content, log_hex(ct, LOG_DEBUG, "response hexdump content", content,
content_length); content_length);
free(content);
} else { } else {
resp_code = 500;
mg_printf(conn, 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-Type: text/plain\r\n"
"Content-Length: 17\r\n" // Always set Content-Length "Content-Length: 17\r\n" // Always set Content-Length
"\r\n" "\r\n"
"uts-server error"); "uts-server error");
} }
free(content);
} else { } else {
resp_code = 200;
mg_printf(conn, mg_printf(conn,
"HTTP/1.1 200 OK\r\n" "HTTP/1.1 200 OK\r\n"
"Content-Type: text/plain\r\n" "Content-Type: text/plain\r\n"
@ -124,7 +166,16 @@ int rfc3161_handler(struct mg_connection *conn, void *context) {
"\r\n" "\r\n"
"uts-server, a simple RFC 3161 timestamp server"); "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; return 1;
} }

51
src/lib/rfc3161.c
View File

@ -25,6 +25,9 @@
#define OID_SECTION "oids" #define OID_SECTION "oids"
// number of char we get to log for the serial
#define SERIAL_ID_SIZE 8
/* Reply related functions. */ /* Reply related functions. */
static int reply_command(CONF *conf, char *section, char *engine, char *query, static int reply_command(CONF *conf, char *section, char *engine, char *query,
char *passin, char *inkey, const EVP_MD *md, char *passin, char *inkey, const EVP_MD *md,
@ -173,11 +176,12 @@ end:
int create_response(rfc3161_context *ct, char *query, int query_len, int create_response(rfc3161_context *ct, char *query, int query_len,
TS_RESP_CTX *resp_ctx, size_t *resp_size, TS_RESP_CTX *resp_ctx, size_t *resp_size,
unsigned char **resp) { unsigned char **resp, char **serial_id) {
int ret = 0; int ret = 0;
TS_RESP *ts_response = NULL; TS_RESP *ts_response = NULL;
BIO *query_bio = NULL; BIO *query_bio = NULL;
BIO *out_bio = NULL; BIO *out_bio = NULL;
BIO *text_bio = BIO_new(BIO_s_mem());
BIO *status_bio = BIO_new(BIO_s_mem()); BIO *status_bio = BIO_new(BIO_s_mem());
; ;
unsigned long err_code; unsigned long err_code;
@ -206,43 +210,69 @@ end:
TS_STATUS_INFO_print_bio(status_bio, ts_response->status_info); TS_STATUS_INFO_print_bio(status_bio, ts_response->status_info);
BIO_get_mem_ptr(status_bio, &bptr); 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 // replacing '\n' by '|' to log on one line only
char *temp = strstr(bptr->data, "\n"); char *temp = strstr(bptr->data, "\n");
while ((temp = strstr(bptr->data, "\n")) != NULL) { while ((temp = strstr(bptr->data, "\n")) != NULL) {
temp[0] = '|'; 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); BUF_MEM_free(bptr);
long status = ASN1_INTEGER_get(ts_response->status_info->status); long status = ASN1_INTEGER_get(ts_response->status_info->status);
switch (status) { switch (status) {
case TS_STATUS_GRANTED: 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; ret = 1;
break; break;
case TS_STATUS_GRANTED_WITH_MODS: case TS_STATUS_GRANTED_WITH_MODS:
uts_logger(ct, LOG_NOTICE, uts_logger(ct, LOG_NOTICE, "timestamp request granted with "
"timestamp request granted with modification"); "modification (response serial '%s...')",
*serial_id);
ret = 1; ret = 1;
break; break;
case TS_STATUS_REJECTION: 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; ret = 0;
break; break;
case TS_STATUS_WAITING: 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; ret = 0;
break; break;
case TS_STATUS_REVOCATION_WARNING: 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; ret = 0;
break; break;
case TS_STATUS_REVOCATION_NOTIFICATION: 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; ret = 0;
break; break;
default: 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; ret = 0;
} }
@ -259,6 +289,7 @@ end:
} }
// BIO_free_all(status_bio); // BIO_free_all(status_bio);
TS_RESP_free(ts_response); TS_RESP_free(ts_response);
free(serial_hex);
return ret; return ret;
} }