diff options
author | Toni Uhlig <matzeton@googlemail.com> | 2020-10-24 18:26:40 +0200 |
---|---|---|
committer | Toni Uhlig <matzeton@googlemail.com> | 2020-10-24 18:26:40 +0200 |
commit | 4ba484be6ef6e1f759fdb6dbde056592143cbd14 (patch) | |
tree | 0dc9ec3162d6278fe28a726495d1986742c5a795 | |
parent | 749a4b2eda0b3b2d7a796530bb64fdfb4b5f3df4 (diff) |
time/timestamp refactoring
Signed-off-by: Toni Uhlig <matzeton@googlemail.com>
-rw-r--r-- | Makefile | 3 | ||||
-rw-r--r-- | client.c | 33 | ||||
-rw-r--r-- | common-event2.c | 35 | ||||
-rw-r--r-- | protocol.c | 91 | ||||
-rw-r--r-- | protocol.h | 40 | ||||
-rw-r--r-- | server.c | 32 | ||||
-rw-r--r-- | utils.c | 24 | ||||
-rw-r--r-- | utils.h | 4 |
8 files changed, 146 insertions, 116 deletions
@@ -19,7 +19,7 @@ DEBUG_CFLAGS = EXTRA_CFLAGS = -Werror -Os endif -CFLAGS += -Wall -Wextra -Wstrict-prototypes -std=gnu11 $(EXTRA_CFLAGS) -D_GNU_SOURCE $(DEBUG_CFLAGS) $(SANITIZER_CFLAGS) -fstrict-aliasing \ +CFLAGS += -Wall -Wextra -Wsign-conversion -Wstrict-prototypes -std=gnu11 $(EXTRA_CFLAGS) -D_GNU_SOURCE $(DEBUG_CFLAGS) $(SANITIZER_CFLAGS) -fstrict-aliasing \ $(shell $(PKG_CONFIG_BIN) --cflags libsodium) \ $(shell $(PKG_CONFIG_BIN) --cflags libevent) @@ -81,7 +81,6 @@ help: @echo "\tENABLE_DEBUG=$(ENABLE_DEBUG) \\" @echo "\tENABLE_STATIC=$(ENABLE_STATIC) \\" @echo "\tENABLE_SANITIZER=$(ENABLE_SANITIZER) \\" - @echo "\tBUILD_STATIC=$(BUILD_STATIC) \\" @echo "\tBUILD_SHARED=$(BUILD_SHARED) \\" @echo "\tDESTDIR=$(DESTDIR) \\" @echo "\tPREFIX=$(PREFIX)" @@ -103,15 +103,15 @@ enum recv_return protocol_request_ping(struct connection * const state, size_t * const processed) { struct protocol_ping const * const ping_pkt = (struct protocol_ping *)buffer; + char ts_str[TIMESTAMP_STRLEN]; + double ts = to_timestamp(be64toh(ping_pkt->timestamp.sec), ntohl(ping_pkt->timestamp.nsec)); (void)processed; - LOG(NOTICE, - "Received PING with timestamp: %.*s / %lluus", - sizeof(ping_pkt->timestamp), - ping_pkt->timestamp, - state->last_ping_recv_usec); - if (state->latency_usec > 0.0) { - LOG(NOTICE, "PING-PONG latency: %.02lfms", state->latency_usec / 1000.0); + strftime_local(ts, ts_str, sizeof(ts_str)); + LOG(NOTICE, "Received PING with timestamp %.09lfs: %s / %lluns", + ts, ts_str, extract_nsecs(ts)); + if (state->latency > 0.0f) { + LOG(NOTICE, "PING-PONG latency: %.09lfs", state->latency); } if (ev_protocol_pong(state) != 0) { @@ -126,13 +126,18 @@ enum recv_return protocol_request_pong(struct connection * const state, size_t * const processed) { struct protocol_pong const * const pong_pkt = (struct protocol_pong *)buffer; + char ts_str[TIMESTAMP_STRLEN]; + double ts = to_timestamp(be64toh(pong_pkt->timestamp.sec), ntohl(pong_pkt->timestamp.nsec)); + (void)processed; - LOG(NOTICE, - "Received PONG with timestamp: %.*s / %lluus / %zu outstanding PONG's", - sizeof(pong_pkt->timestamp), - pong_pkt->timestamp, - state->last_pong_recv_usec, - state->awaiting_pong); + strftime_local(ts, ts_str, sizeof(ts_str)); + LOG(NOTICE, "Received PONG with timestamp %.09lfs: %s / %lluns / %zu outstanding PONG's", + ts, ts_str, extract_nsecs(ts), state->awaiting_pong); + + if (state->awaiting_pong > 3) { + LOG(ERROR, "Waiting for more than 3 PONG's, disconnecting.."); + return RECV_FATAL_CALLBACK_ERROR; + } return RECV_SUCCESS; } @@ -351,7 +356,7 @@ int main(int argc, char ** argv) } LOG(NOTICE, "Connecting to %s:%s", ip_str, opts.port); - if (bufferevent_socket_connect(bev, ai->ai_addr, ai->ai_addrlen) == 0) { + if (bufferevent_socket_connect(bev, ai->ai_addr, (int)ai->ai_addrlen) == 0) { bev_connected = 1; break; } diff --git a/common-event2.c b/common-event2.c index 7f60ba9..9c5ac93 100644 --- a/common-event2.c +++ b/common-event2.c @@ -7,6 +7,7 @@ #include "common-event2.h" #include "logging.h" #include "protocol.h" +#include "utils.h" int ev_auth_timeout(struct ev_user_data * const user_data) { @@ -19,6 +20,7 @@ int ev_add_timer(struct ev_user_data * const user_data, time_t trigger_after) { struct timeval tv; + LOG(LP_DEBUG, "Added timer event, next trigger in %llus", (unsigned long long int)trigger_after); tv.tv_sec = trigger_after; tv.tv_usec = 0; return event_add(user_data->generic_timer, &tv); @@ -29,12 +31,9 @@ int ev_del_timer(struct ev_user_data * const user_data) return event_del(user_data->generic_timer); } -static double time_passed(struct tm * const tm) +static double time_passed(double last_time) { - time_t cur = time(NULL); - time_t chk = timegm(tm); - - return difftime(cur, chk); + return create_timestamp() - last_time; } int ev_default_timeout(struct ev_user_data * const user_data) @@ -44,16 +43,15 @@ int ev_default_timeout(struct ev_user_data * const user_data) ev_disconnect(user_data->state); return 0; } - - if (time_passed(&user_data->state->last_ping_recv) > PING_INTERVAL || - time_passed(&user_data->state->last_ping_send) > PING_INTERVAL) { + if (time_passed(user_data->state->last_ping_recv) > PING_INTERVAL || + time_passed(user_data->state->last_ping_send) > PING_INTERVAL) { LOG(NOTICE, "Sending PING"); if (ev_protocol_ping(user_data->state) != RECV_SUCCESS) { LOG(WARNING, "Could not send PING"); return 1; } } - if (ev_add_timer(user_data, random() % PING_INTERVAL) != 0) { + if (ev_add_timer(user_data, PING_INTERVAL + (random() % PING_INTERVAL)) != 0) { return 1; } return 0; @@ -208,13 +206,14 @@ int ev_protocol_ping(struct connection * const state) { int result; unsigned char ping_pkt_crypted[CRYPT_PACKET_SIZE_PING]; - char timestamp[PROTOCOL_TIME_STRLEN]; + char timestamp[TIMESTAMP_STRLEN]; struct ev_user_data * user_data = (struct ev_user_data *)state->user_data; protocol_response_ping(ping_pkt_crypted, state); - if (strftime(timestamp, PROTOCOL_TIME_STRLEN, "%a, %d %b %Y %T %z", &state->last_ping_send) > 0) { - LOG(LP_DEBUG, "Sending PING with ts %s / %lluus", timestamp, state->last_ping_send_usec); - } + + strftime_local(state->last_ping_send, timestamp, sizeof(timestamp)); + LOG(LP_DEBUG, "Sending PING with ts %.09lf: %s / %lluns", + state->last_ping_send, timestamp, extract_nsecs(state->last_ping_send)); result = evbuffer_add(bufferevent_get_output(user_data->bev), ping_pkt_crypted, sizeof(ping_pkt_crypted)); return result; } @@ -223,13 +222,13 @@ int ev_protocol_pong(struct connection * const state) { int result; unsigned char pong_pkt_crypted[CRYPT_PACKET_SIZE_PONG]; - char timestamp[PROTOCOL_TIME_STRLEN]; + char timestamp[TIMESTAMP_STRLEN]; struct ev_user_data * user_data = (struct ev_user_data *)state->user_data; protocol_response_pong(pong_pkt_crypted, state); - if (strftime(timestamp, PROTOCOL_TIME_STRLEN, "%a, %d %b %Y %T %z", &state->last_pong_send) > 0) { - LOG(LP_DEBUG, "Sending PONG with ts %s / %lluus", timestamp, state->last_pong_send_usec); - } + strftime_local(state->last_pong_send, timestamp, sizeof(timestamp)); + LOG(LP_DEBUG, "Sending PONG with ts %.09lf: %s / %lluns", + state->last_pong_send, timestamp, extract_nsecs(state->last_pong_send)); result = evbuffer_add(bufferevent_get_output(user_data->bev), pong_pkt_crypted, sizeof(pong_pkt_crypted)); return result; } @@ -326,7 +325,7 @@ static void event_to_string(char ** buffer, size_t * const buffer_size, const ch int written = snprintf(*buffer, *buffer_size, "%s, ", str); if (written > 0) { *buffer += written; - *buffer_size -= written; + *buffer_size -= (size_t)written; } } @@ -67,14 +67,32 @@ static size_t calculate_min_recv_size(enum header_types type, size_t size) return 0; } -static enum recv_return parse_protocol_timestamp(char const protocol_timestamp[PROTOCOL_TIME_STRLEN], - struct tm * const dest) +double create_timestamp(void) { - char timestamp_sz[PROTOCOL_TIME_STRLEN + 1]; - strncpy(timestamp_sz, protocol_timestamp, sizeof(timestamp_sz) - 1); - timestamp_sz[PROTOCOL_TIME_STRLEN] = '\0'; - strptime(timestamp_sz, "%a, %d %b %Y %T %z", dest); - return RECV_SUCCESS; + struct timespec ts; + int err = clock_gettime(CLOCK_REALTIME, &ts); + double decimal_places; + + if (err != 0) { + return 0.0f; + } + + decimal_places = (double)ts.tv_nsec * 1e-9; + return (double)ts.tv_sec + decimal_places; +} + +double to_timestamp(uint64_t time_in_secs, uint32_t nano_secs) +{ + double r = (double)time_in_secs; + + return r + ((double)nano_secs * 1e-9); +} + +suseconds_t extract_nsecs(double time_in_secs) +{ + double s = (double)((time_t)time_in_secs); + + return (suseconds_t)((time_in_secs - s) / 1e-9); } static enum recv_return process_body(struct connection * const state, @@ -83,7 +101,6 @@ static enum recv_return process_body(struct connection * const state, size_t * const processed) { struct protocol_header const * const hdr = (struct protocol_header *)decrypted->pointer; - enum recv_return retval; (void)encrypted; switch (hdr->pdu_type) { @@ -118,27 +135,19 @@ static enum recv_return process_body(struct connection * const state, case TYPE_PING: { struct protocol_ping const * const ping_pkt = (struct protocol_ping *)hdr; - retval = parse_protocol_timestamp(ping_pkt->timestamp, &state->last_ping_recv); - if (retval != RECV_SUCCESS) { - return retval; - } - state->last_ping_recv_usec = be64toh(ping_pkt->timestamp_usec); + state->last_ping_recv = to_timestamp(be64toh(ping_pkt->timestamp.sec), ntohl(ping_pkt->timestamp.nsec)); *processed += CRYPT_PACKET_SIZE_PING; break; } case TYPE_PONG: { struct protocol_pong const * const pong_pkt = (struct protocol_pong *)hdr; - retval = parse_protocol_timestamp(pong_pkt->timestamp, &state->last_pong_recv); - if (retval != RECV_SUCCESS) { - return retval; - } + state->last_pong_recv = to_timestamp(be64toh(pong_pkt->timestamp.sec), ntohl(pong_pkt->timestamp.nsec)); if (state->awaiting_pong == 0) { return RECV_FATAL; } state->awaiting_pong--; - state->last_pong_recv_usec = be64toh(pong_pkt->timestamp_usec); - state->latency_usec = state->last_pong_recv_usec - state->last_ping_send_usec; + state->latency = state->last_pong_recv - state->last_ping_send; *processed += CRYPT_PACKET_SIZE_PONG; break; } @@ -157,7 +166,7 @@ static enum recv_return run_protocol_callback(struct connection * const state, size_t * const processed) { struct protocol_header const * const hdr = (struct protocol_header *)decrypted->pointer; - enum header_types type = (enum header_types)hdr->pdu_type; + enum header_types type = hdr->pdu_type; size_t min_size = 0; uint32_t size = hdr->body_size; @@ -198,13 +207,13 @@ static enum recv_return run_protocol_callback(struct connection * const state, static void header_ntoh(struct protocol_header * const hdr) { hdr->magic = ntohl(hdr->magic); - hdr->pdu_type = ntohs(hdr->pdu_type); + hdr->pdu_type = ntohl(hdr->pdu_type); hdr->body_size = ntohl(hdr->body_size); } static enum recv_return validate_header(struct protocol_header const * const hdr, size_t buffer_size) { - enum header_types type = (enum header_types)hdr->pdu_type; + enum header_types type = hdr->pdu_type; uint32_t size; if (hdr->magic != PROTOCOL_MAGIC) { @@ -418,7 +427,7 @@ static void protocol_response(struct connection * const state, struct protocol_header * const header = (struct protocol_header *)buffer; header->magic = htonl(PROTOCOL_MAGIC); - header->pdu_type = htons((uint16_t)type); + header->pdu_type = htonl(type); header->body_size = htonl(body_and_payload_size - sizeof(*header)); state->total_bytes_sent += (sizeof(*header) + body_and_payload_size); @@ -492,32 +501,15 @@ void protocol_response_data(uint8_t * out, &state->crypto_tx_state, CRYPT_PACKET_POINTER_AFTER_HEADER(out), NULL, payload, payload_size, NULL, 0, 0); } -static int create_timestamp(struct tm * const timestamp, - char timestamp_str[PROTOCOL_TIME_STRLEN], - suseconds_t * const usec) -{ - time_t ts; - struct timeval ts_val; - - gettimeofday(&ts_val, NULL); - *usec = ts_val.tv_usec; - ts = time(NULL); - gmtime_r(&ts, timestamp); - - if (timestamp_str) { - return strftime(timestamp_str, PROTOCOL_TIME_STRLEN, "%a, %d %b %Y %T %z", timestamp); - } - return 0; -} - void protocol_response_ping(unsigned char out[CRYPT_PACKET_SIZE_PING], struct connection * const state) { struct protocol_ping ping_pkt; state->awaiting_pong++; protocol_response(state, &ping_pkt, sizeof(ping_pkt), TYPE_PING); - create_timestamp(&state->last_ping_send, ping_pkt.timestamp, &state->last_ping_send_usec); - ping_pkt.timestamp_usec = htobe64(state->last_ping_send_usec); + state->last_ping_send = create_timestamp(); + ping_pkt.timestamp.sec = htobe64(state->last_ping_send); + ping_pkt.timestamp.nsec = htonl(extract_nsecs(state->last_ping_send)); crypto_secretstream_xchacha20poly1305_push( &state->crypto_tx_state, &out[0], NULL, (uint8_t *)&ping_pkt.header, sizeof(ping_pkt.header), NULL, 0, 0); @@ -536,8 +528,9 @@ void protocol_response_pong(unsigned char out[CRYPT_PACKET_SIZE_PONG], struct co struct protocol_pong pong_pkt; protocol_response(state, &pong_pkt, sizeof(pong_pkt), TYPE_PONG); - create_timestamp(&state->last_pong_send, pong_pkt.timestamp, &state->last_pong_send_usec); - pong_pkt.timestamp_usec = htobe64(state->last_pong_send_usec); + state->last_pong_send = create_timestamp(); + pong_pkt.timestamp.sec = htobe64(state->last_pong_send); + pong_pkt.timestamp.nsec = htonl(extract_nsecs(state->last_pong_send)); crypto_secretstream_xchacha20poly1305_push( &state->crypto_tx_state, &out[0], NULL, (uint8_t *)&pong_pkt.header, sizeof(pong_pkt.header), NULL, 0, 0); @@ -567,11 +560,9 @@ static struct connection * new_connection(struct longterm_keypair const * const c->session_keys = NULL; c->my_keypair = my_keypair; c->user_data = NULL; - create_timestamp(&c->last_ping_recv, NULL, &c->last_ping_recv_usec); - create_timestamp(&c->last_ping_send, NULL, &c->last_ping_send_usec); - create_timestamp(&c->last_pong_recv, NULL, &c->last_pong_recv_usec); - create_timestamp(&c->last_pong_send, NULL, &c->last_pong_send_usec); - c->latency_usec = 0.0; + + c->last_ping_recv = c->last_ping_send = c->last_pong_recv = c->last_pong_send = create_timestamp(); + c->latency = 0.0; c->total_bytes_recv = 0; c->total_bytes_sent = 0; sodium_mlock(c, sizeof(*c)); @@ -10,7 +10,6 @@ #define PROTOCOL_ATTRIBUTES __attribute__((packed)) #define PROTOCOL_MAGIC 0xBAADC0DE #define PROTOCOL_VERSION 0xDEADCAFE -#define PROTOCOL_TIME_STRLEN 32 #define WINDOW_SIZE (65535 * 2) #if WINDOW_SIZE > (UINT_MAX) #error "Window size is limited by sizeof(header.body_size)" @@ -90,14 +89,18 @@ struct protocol_data { struct protocol_ping { struct protocol_header header; - char timestamp[PROTOCOL_TIME_STRLEN]; - uint64_t timestamp_usec; + struct { + uint64_t sec; + uint32_t nsec; + } timestamp; } PROTOCOL_ATTRIBUTES; struct protocol_pong { struct protocol_header header; - char timestamp[PROTOCOL_TIME_STRLEN]; - uint64_t timestamp_usec; + struct { + uint64_t sec; + uint32_t nsec; + } timestamp; } PROTOCOL_ATTRIBUTES; enum state { CONNECTION_INVALID = 0, CONNECTION_NEW, CONNECTION_AUTH_SUCCESS }; @@ -130,17 +133,11 @@ struct connection { /* nonce must be incremented before sending or comparing a remote received one */ uint8_t last_nonce[crypto_box_NONCEBYTES]; - struct tm last_ping_recv; - struct tm last_ping_send; - struct tm last_pong_recv; - struct tm last_pong_send; - - suseconds_t last_ping_recv_usec; - suseconds_t last_ping_send_usec; - suseconds_t last_pong_recv_usec; - suseconds_t last_pong_send_usec; - - double latency_usec; + double last_ping_recv; + double last_ping_send; + double last_pong_recv; + double last_pong_send; + double latency; uint64_t total_bytes_recv; uint64_t total_bytes_sent; @@ -194,9 +191,9 @@ extern enum recv_return protocol_request_pong(struct connection * const state, struct protocol_header const * const buffer, size_t * const processed); -/******************************* +/************************** * PDU send functionality * - *******************************/ + **************************/ void protocol_response_client_auth(unsigned char out[CRYPT_PACKET_SIZE_CLIENT_AUTH], struct connection * const state, @@ -220,4 +217,11 @@ void protocol_response_pong(unsigned char out[CRYPT_PACKET_SIZE_PONG], struct co struct connection * new_connection_from_client(struct longterm_keypair const * const my_keypair); struct connection * new_connection_to_server(struct longterm_keypair const * const my_keypair); +/*********************** + * timestamp functions * + ***********************/ +double create_timestamp(void); +double to_timestamp(uint64_t time_in_secs, uint32_t nano_secs); +suseconds_t extract_nsecs(double time_in_secs); + #endif @@ -121,15 +121,15 @@ enum recv_return protocol_request_ping(struct connection * const state, size_t * const processed) { struct protocol_ping const * const ping_pkt = (struct protocol_ping *)buffer; + char ts_str[TIMESTAMP_STRLEN]; + double ts = to_timestamp(be64toh(ping_pkt->timestamp.sec), ntohl(ping_pkt->timestamp.nsec)); (void)processed; - LOG(NOTICE, - "Received PING with timestamp: %.*s / %lluus", - sizeof(ping_pkt->timestamp), - ping_pkt->timestamp, - state->last_ping_recv_usec); - if (state->latency_usec > 0.0) { - LOG(NOTICE, "PING-PONG latency: %.02lfms", state->latency_usec / 1000.0); + strftime_local(ts, ts_str, sizeof(ts_str)); + LOG(NOTICE, "Received PING with timestamp %.09lfs: %s / %lluns", + ts, ts_str, extract_nsecs(ts)); + if (state->latency > 0.0f) { + LOG(NOTICE, "PING-PONG latency: %.09lfs", state->latency); } if (ev_protocol_pong(state) != 0) { @@ -144,14 +144,18 @@ enum recv_return protocol_request_pong(struct connection * const state, size_t * const processed) { struct protocol_pong const * const pong_pkt = (struct protocol_pong *)buffer; + char ts_str[TIMESTAMP_STRLEN]; + double ts = to_timestamp(be64toh(pong_pkt->timestamp.sec), ntohl(pong_pkt->timestamp.nsec)); (void)processed; - LOG(NOTICE, - "Received PONG with timestamp: %.*s / %lluus / %zu outstanding PONG's", - sizeof(pong_pkt->timestamp), - pong_pkt->timestamp, - state->last_pong_recv_usec, - state->awaiting_pong); + strftime_local(ts, ts_str, sizeof(ts_str)); + LOG(NOTICE, "Received PONG with timestamp %.09lfs: %s / %lluns / %zu outstanding PONG's", + ts, ts_str, extract_nsecs(ts), state->awaiting_pong); + + if (state->awaiting_pong > 3) { + LOG(ERROR, "Waiting for more than 3 PONG's, disconnecting.."); + return RECV_FATAL_CALLBACK_ERROR; + } return RECV_SUCCESS; } @@ -386,7 +390,7 @@ int main(int argc, char ** argv) LEV_OPT_CLOSE_ON_FREE | LEV_OPT_REUSEABLE, -1, ai->ai_addr, - ai->ai_addrlen); + (int)ai->ai_addrlen); if (ev_listener != NULL) { break; } @@ -3,6 +3,7 @@ #include <string.h> #include <sys/types.h> #include <sys/socket.h> +#include <time.h> #include <unistd.h> #include "utils.h" @@ -82,3 +83,26 @@ int hostname_to_address(char const * const host, char const * const port, struct return 0; } + +void strftime_local(double time_in_secs, char * const out, size_t out_size) +{ + time_t t = (time_t)time_in_secs; + struct tm r; + + if (localtime_r(&t, &r) == NULL) + { + out[0] = '\0'; + return; + } + + if (out_size > TIMESTAMP_STRLEN) + { + out_size = TIMESTAMP_STRLEN; + } + + if (strftime(out, out_size, "%a, %d %b %Y %T %z", &r) <= 0) + { + out[0] = '\0'; + return; + } +} @@ -3,6 +3,8 @@ #include <stdlib.h> +#define TIMESTAMP_STRLEN 32 + struct cmd_options { /* server: private key * client: server public key @@ -31,4 +33,6 @@ char * prettify_bytes_with_units(char * const out, size_t out_size, unsigned lon int hostname_to_address(char const * const host, char const * const port, struct addrinfo ** const result); +void strftime_local(double time_in_secs, char * const out, size_t out_size); + #endif |