From 6c84e680af75d338121e4b4d1964d5788eab7692 Mon Sep 17 00:00:00 2001 From: evgeny Date: Wed, 21 Oct 2026 20:18:17 +0200 Subject: [PATCH] Improve NTP failure diagnostics and source transition coverage --- src/ntp_time.c | 55 +++++++++++++++++++++++------------- tests/test_ntp_regressions.c | 19 ++++++++++++- 2 files changed, 53 insertions(+), 21 deletions(-) diff --git a/src/ntp_time.c b/src/ntp_time.c index a181034e..d360a18e 100644 --- a/src/ntp_time.c +++ b/src/ntp_time.c @@ -94,16 +94,29 @@ static void ntp_build_request(uint8_t* req, uint64_t* t1_ntp_out) { /* возвращает 0 если ответ валиден; иначе -1 (пакет игнорируется, ждём timeout) */ static int ntp_parse_reply(const uint8_t* buf, size_t len, uint64_t t1_ntp, int64_t* offset_us_out, int64_t* rtt_us_out, int* stratum_out) { - if (len < sizeof(struct ntp_packet)) return -1; + if (len < sizeof(struct ntp_packet)) { + DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: short reply: bytes=%zu required=%zu", len, sizeof(struct ntp_packet)); + return -1; + } const struct ntp_packet* reply = (const struct ntp_packet*)buf; uint8_t mode = reply->li_vn_mode & 0x07; - if (mode != 4) return -1; + if (mode != 4) { + DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: invalid reply mode=%u", (unsigned)mode); + return -1; + } int stratum = reply->stratum; - if (stratum == 0) return -1; + if (stratum == 0) { + DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: server returned stratum=0 (no time sample)"); + return -1; + } - if (be64toh(reply->orig_ts) != t1_ntp) return -1; + if (be64toh(reply->orig_ts) != t1_ntp) { + DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: stale/unmatched reply: originate=%llu expected=%llu", + (unsigned long long)be64toh(reply->orig_ts), (unsigned long long)t1_ntp); + return -1; + } struct timeval t4_tv; #ifdef _WIN32 @@ -214,15 +227,16 @@ static int ntp_start_query(struct ntp_sync* ctx, const struct sockaddr_in* addr) static int ntp_send_request(struct ntp_sync* ctx) { struct UTUN_INSTANCE* inst = ctx->inst; + const char* name = ctx->query_idx >= 0 ? inst->ntp.servers[ctx->query_idx] : "test-server"; if (ctx->sock == SOCKET_INVALID) { ctx->sock = socket_create_udp(AF_INET); if (ctx->sock == SOCKET_INVALID) { - DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: socket() failed: %s", socket_strerror(socket_get_error())); + DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: socket() failed for %s: %s", name, socket_strerror(socket_get_error())); return -1; } if (socket_set_nonblocking(ctx->sock) != 0) { - DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: nonblocking mode failed: %s", socket_strerror(socket_get_error())); + DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: nonblocking mode failed for %s: %s", name, socket_strerror(socket_get_error())); return -1; } } @@ -233,26 +247,26 @@ static int ntp_send_request(struct ntp_sync* ctx) { ssize_t sent = socket_sendto(ctx->sock, ctx->req, sizeof(ctx->req), (const struct sockaddr*)&ctx->qaddr, sizeof(ctx->qaddr)); if (sent != (ssize_t)sizeof(ctx->req)) { - DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: sendto failed/short: sent=%lld error=%s", - (long long)sent, sent < 0 ? socket_strerror(socket_get_error()) : "short datagram"); + DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: sendto failed/short for %s: sent=%lld error=%s", + name, (long long)sent, sent < 0 ? socket_strerror(socket_get_error()) : "short datagram"); return -1; } if (!ctx->socket_id) { ctx->socket_id = uasync_add_socket_t(inst->ua, ctx->sock, ntp_query_read_cb, NULL, NULL, "ntp_query", ctx); if (!ctx->socket_id) { - DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: uasync_add_socket_t failed"); + DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: uasync_add_socket_t failed for %s", name); return -1; } } ctx->timer = uasync_set_timeout(inst->ua, NTP_TIMEOUT_SEC * 10000, ctx, ntp_query_timeout_cb, "ntp_q"); if (!ctx->timer) { - DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: uasync_set_timeout failed"); + DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "NTP: request timer failed for %s", name); return -1; } - DEBUG_DEBUG(DEBUG_CATEGORY_GENERAL, "NTP: sent request server=%d attempt=%d/%d timestamp=%llu", - ctx->query_idx, ctx->tries, NTP_MAX_TRIES, (unsigned long long)ctx->t1_ntp); + DEBUG_DEBUG(DEBUG_CATEGORY_GENERAL, "NTP: sent request server=%s attempt=%d/%d timestamp=%llu", + name, ctx->tries, NTP_MAX_TRIES, (unsigned long long)ctx->t1_ntp); return 0; } @@ -263,15 +277,16 @@ static void ntp_query_read_cb(socket_t sock, void* arg) { struct sockaddr_in from; socklen_t from_len = sizeof(from); ssize_t n = socket_recvfrom(ctx->sock, (void*)&reply, sizeof(reply), (struct sockaddr*)&from, &from_len); - if (n < 0) return; /* EAGAIN / ICMP (WSAECONNRESET) — ждём timeout */ + if (n < 0) { + int error = socket_get_error(); + if (error != ERR_AGAIN && error != ERR_WOULDBLOCK) + DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: recvfrom failed server=%d: %s", ctx->query_idx, socket_strerror(error)); + return; + } int64_t offset_us, rtt_us; int stratum; - if (ntp_parse_reply((const uint8_t*)&reply, (size_t)n, ctx->t1_ntp, &offset_us, &rtt_us, &stratum) != 0) { - DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: ignoring invalid/stale reply: bytes=%lld server=%d", - (long long)n, ctx->query_idx); - return; - } + if (ntp_parse_reply((const uint8_t*)&reply, (size_t)n, ctx->t1_ntp, &offset_us, &rtt_us, &stratum) != 0) return; struct NTP_TIME* ntp = &ctx->inst->ntp; ntp->offset_us = offset_us; @@ -290,8 +305,8 @@ static void ntp_query_read_cb(socket_t sock, void* arg) { static void ntp_query_timeout_cb(void* arg) { struct ntp_sync* ctx = (struct ntp_sync*)arg; ctx->timer = NULL; - DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: response timeout server=%d attempt=%d/%d", - ctx->query_idx, ctx->tries, NTP_MAX_TRIES); + const char* name = ctx->query_idx >= 0 ? ctx->inst->ntp.servers[ctx->query_idx] : "test-server"; + DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "NTP: response timeout server=%s attempt=%d/%d", name, ctx->tries, NTP_MAX_TRIES); if (ctx->tries < NTP_MAX_TRIES) { if (ntp_send_request(ctx) == 0) return; } diff --git a/tests/test_ntp_regressions.c b/tests/test_ntp_regressions.c index 4dda032b..ca04b4d4 100644 --- a/tests/test_ntp_regressions.c +++ b/tests/test_ntp_regressions.c @@ -364,6 +364,9 @@ static void test_init_failures(struct fixture* f) { fail_alloc_at = 0; assert(!f->inst.ntp.servers && !f->inst.ntp.timer && u_get_allocated_count() == baseline); } + f->config.global.ntp_server_count = 3; + assert(ntp_time_init(&f->inst) == -1 && u_get_allocated_count() == baseline); + f->config.global.ntp_server_count = 2; f->config.global.ntp_resync_interval = INT_MAX; assert(ntp_time_init(&f->inst) == -1); f->config.global.ntp_resync_interval = 3600; @@ -421,6 +424,20 @@ static void test_peer_cache(struct fixture* f) { assert(!f->inst.ntp_node.peer_count); check_time(f, wall_us + 5000000); } +static void test_sources(struct fixture* f) { + start(f, 1); + assert(!ntp_node_time_init(&f->inst)); + receive_peer(f, &f->conns[0], 1, wall_us + 5000000); + check_time(f, wall_us + 5000000); + deliver_reply(request_stamp(), wall_us + 5000000); + check_time(f, wall_us + 5000000); // смена источника не меняет знак поправки + fire_timer(f->inst.ntp.timer); + for (int i = 0; i < 3; i++) fire_query_timer(); + check_failed_cycle(f); + check_time(f, wall_us + 5000000); // отказ следующего цикла не уничтожает принятую поправку + receive_peer(f, &f->conns[0], 1, wall_us - 5000000); + check_time(f, wall_us + 5000000); // уже синхронизированный узел не принимает другую поправку пира +} static int foreign_calls; static void foreign_callback(struct ETCP_CONN* conn, int event, void* arg) { (void)conn; (void)event; (void)arg; @@ -469,7 +486,7 @@ int main(void) { debug_set_category_level(DEBUG_CATEGORY_GENERAL, DEBUG_LEVEL_INFO); void (*tests[])(struct fixture*) = {test_offsets, test_retry_timestamp, test_async_dns_failure, test_immediate_dns_failure, test_udp_exhaustion, test_immediate_udp_failures, test_timer_failures, - test_cancel, test_init_failures, test_peer_cache, test_node_lifecycle}; + test_cancel, test_init_failures, test_peer_cache, test_sources, test_node_lifecycle}; for (size_t i = 0; i < sizeof(tests) / sizeof(tests[0]); i++) { size_t baseline = u_get_allocated_count(); struct fixture f;