From: Lloyd Subject: Re: wg(4) logging enhancement - revised patch To: Vitaliy Makkoveev Cc: Claudio Jeker , Theo de Raadt , Stuart Henderson , "tech@openbsd.org" Date: Wed, 22 Jan 2025 00:27:25 +0000 I reworked this proposed Wireguard logging patch from a few weeks ago to be much cleaner. I also corrected a few style nits. Thank you for the suggestions. Regards Lloyd --- if_wg.c.orig Thu Oct 31 12:33:11 2024 +++ if_wg.c Wed Jan 22 00:13:39 2025 @@ -30,6 +30,8 @@ #include #include #include +#include +#include #include #include @@ -70,8 +72,10 @@ #define NEW_HANDSHAKE_TIMEOUT (REKEY_TIMEOUT + KEEPALIVE_TIMEOUT) #define UNDERLOAD_TIMEOUT 1 -#define DPRINTF(sc, str, ...) do { if (ISSET((sc)->sc_if.if_flags, IFF_DEBUG))\ - printf("%s: " str, (sc)->sc_if.if_xname, ##__VA_ARGS__); } while (0) +#define WGPRINTF(loglevel, sc, mtx, str, ...) do {\ + if (ISSET((sc)->sc_if.if_flags, IFF_DEBUG)) { if (mtx) { mtx_enter(mtx); }\ + log(loglevel, "%s: " str, (sc)->sc_if.if_xname, ##__VA_ARGS__);\ + if (mtx) { mtx_leave(mtx); } } } while (0) #define CONTAINER_OF(ptr, type, member) ({ \ const __typeof( ((type *)0)->member ) *__mptr = (ptr); \ @@ -371,6 +375,7 @@ void wg_down(struct wg_softc *); int wg_clone_create(struct if_clone *, int); int wg_clone_destroy(struct ifnet *); void wgattach(int); +char* wg_log_ip(struct wg_endpoint *); uint64_t peer_counter = 0; struct pool wg_aip_pool; @@ -448,7 +453,7 @@ wg_peer_create(struct wg_softc *sc, uint8_t public[WG_ sc->sc_peer_num++; rw_exit_write(&sc->sc_peer_lock); - DPRINTF(sc, "Peer %llu created\n", peer->p_id); + WGPRINTF(LOG_INFO, sc, NULL, "Peer %llu created\n", peer->p_id); return peer; } @@ -530,7 +535,7 @@ wg_peer_destroy(struct wg_peer *peer) if (!mq_empty(&peer->p_stage_queue)) mq_purge(&peer->p_stage_queue); - DPRINTF(sc, "Peer %llu destroyed\n", peer->p_id); + WGPRINTF(LOG_INFO, sc, NULL, "Peer %llu destroyed\n", peer->p_id); explicit_bzero(peer, sizeof(*peer)); pool_put(&wg_peer_pool, peer); } @@ -674,7 +679,7 @@ wg_aip_remove(struct wg_softc *sc, struct wg_peer *pee } else { aip = (struct wg_aip *)node; if (art_delete(root, node, &d->a_addr, d->a_cidr) == NULL) - panic("art_delete failed to delete node %p", node); + panic("wg: art_delete() failed to delete node %p", node); sc->sc_aip_num--; LIST_REMOVE(aip, a_entry); @@ -753,7 +758,7 @@ void wg_socket_close(struct socket **so) { if (*so != NULL && soclose(*so, 0) != 0) - panic("Unable to close wg socket"); + panic("wg: Unable to close wg socket"); *so = NULL; } @@ -883,7 +888,7 @@ retry: } else { ret = wg_send(sc, e, m); if (ret != 0) - DPRINTF(sc, "Unable to send packet\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Unable to send packet\n"); } } @@ -1150,17 +1155,20 @@ wg_timers_run_retry_handshake(void *_t) t->t_handshake_retries++; mtx_leave(&t->t_handshake_mtx); - DPRINTF(peer->p_sc, "Handshake for peer %llu did not complete " - "after %d seconds, retrying (try %d)\n", peer->p_id, - REKEY_TIMEOUT, t->t_handshake_retries + 1); + WGPRINTF(LOG_INFO, peer->p_sc, &peer->p_endpoint_mtx, + "Handshake for peer %llu (%s) did not complete after %d " + "seconds, retrying (try %d)\n", peer->p_id, + wg_log_ip(&peer->p_endpoint), REKEY_TIMEOUT, + t->t_handshake_retries + 1); wg_peer_clear_src(peer); wg_timers_run_send_initiation(t, 1); } else { mtx_leave(&t->t_handshake_mtx); - DPRINTF(peer->p_sc, "Handshake for peer %llu did not complete " - "after %d retries, giving up\n", peer->p_id, - MAX_TIMER_HANDSHAKES + 2); + WGPRINTF(LOG_INFO, peer->p_sc, &peer->p_endpoint_mtx, + "Handshake for peer %llu (%s) did not complete after %d " + "retries, giving up\n", peer->p_id, + wg_log_ip(&peer->p_endpoint), MAX_TIMER_HANDSHAKES + 2); timeout_del(&t->t_send_keepalive); mq_purge(&peer->p_stage_queue); @@ -1189,9 +1197,10 @@ wg_timers_run_new_handshake(void *_t) struct wg_timers *t = _t; struct wg_peer *peer = CONTAINER_OF(t, struct wg_peer, p_timers); - DPRINTF(peer->p_sc, "Retrying handshake with peer %llu because we " - "stopped hearing back after %d seconds\n", - peer->p_id, NEW_HANDSHAKE_TIMEOUT); + WGPRINTF(LOG_INFO, peer->p_sc, &peer->p_endpoint_mtx, + "Retrying handshake with peer %llu (%s) because we " + "stopped hearing back after %d seconds\n", peer->p_id, + wg_log_ip(&peer->p_endpoint), NEW_HANDSHAKE_TIMEOUT); wg_peer_clear_src(peer); wg_timers_run_send_initiation(t, 0); @@ -1203,7 +1212,9 @@ wg_timers_run_zero_key_material(void *_t) struct wg_timers *t = _t; struct wg_peer *peer = CONTAINER_OF(t, struct wg_peer, p_timers); - DPRINTF(peer->p_sc, "Zeroing out keys for peer %llu\n", peer->p_id); + WGPRINTF(LOG_INFO, peer->p_sc, &peer->p_endpoint_mtx, "Zeroing out " + "keys for peer %llu (%s)\n", peer->p_id, + wg_log_ip(&peer->p_endpoint)); task_add(wg_handshake_taskq, &peer->p_clear_secrets); } @@ -1238,8 +1249,9 @@ wg_send_initiation(void *_peer) if (wg_timers_check_handshake_last_sent(&peer->p_timers) != ETIMEDOUT) return; - DPRINTF(peer->p_sc, "Sending handshake initiation to peer %llu\n", - peer->p_id); + WGPRINTF(LOG_INFO, peer->p_sc, &peer->p_endpoint_mtx, "Sending " + "handshake initiation to peer %llu (%s)\n", peer->p_id, + wg_log_ip(&peer->p_endpoint)); if (noise_create_initiation(&peer->p_remote, &pkt.s_idx, pkt.ue, pkt.es, pkt.ets) != 0) @@ -1256,8 +1268,9 @@ wg_send_response(struct wg_peer *peer) { struct wg_pkt_response pkt; - DPRINTF(peer->p_sc, "Sending handshake response to peer %llu\n", - peer->p_id); + WGPRINTF(LOG_INFO, peer->p_sc, &peer->p_endpoint_mtx, "Sending " + "handshake response to peer %llu (%s)\n", peer->p_id, + wg_log_ip(&peer->p_endpoint)); if (noise_create_response(&peer->p_remote, &pkt.s_idx, &pkt.r_idx, pkt.ue, pkt.en) != 0) @@ -1278,8 +1291,8 @@ wg_send_cookie(struct wg_softc *sc, struct cookie_macs { struct wg_pkt_cookie pkt; - DPRINTF(sc, "Sending cookie response for denied handshake message\n"); - + WGPRINTF(LOG_DEBUG, sc, NULL, "Sending cookie response for denied " + "handshake message\n"); pkt.t = WG_PKT_COOKIE; pkt.r_idx = idx; @@ -1363,29 +1376,34 @@ wg_handshake(struct wg_softc *sc, struct mbuf *m) underload, &t->t_endpoint.e_remote.r_sa); if (res == EINVAL) { - DPRINTF(sc, "Invalid initiation MAC\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Invalid initiation " + "MAC from %s\n", wg_log_ip(&t->t_endpoint)); goto error; } else if (res == ECONNREFUSED) { - DPRINTF(sc, "Handshake ratelimited\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Handshake " + "ratelimited from %s\n", wg_log_ip(&t->t_endpoint)); goto error; } else if (res == EAGAIN) { wg_send_cookie(sc, &init->m, init->s_idx, &t->t_endpoint); goto error; } else if (res != 0) { - panic("unexpected response: %d", res); + panic("wg: Unexpected response from " + "cookie_checker_validate_macs(): %d", res); } if (noise_consume_initiation(&sc->sc_local, &remote, init->s_idx, init->ue, init->es, init->ets) != 0) { - DPRINTF(sc, "Invalid handshake initiation\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Invalid handshake " + "initiation from %s\n", wg_log_ip(&t->t_endpoint)); goto error; } peer = CONTAINER_OF(remote, struct wg_peer, p_remote); - DPRINTF(sc, "Receiving handshake initiation from peer %llu\n", - peer->p_id); + WGPRINTF(LOG_INFO, sc, NULL, "Receiving handshake initiation " + "from peer %llu (%s)\n", peer->p_id, + wg_log_ip(&t->t_endpoint)); wg_peer_counters_add(peer, 0, sizeof(*init)); wg_peer_set_endpoint_from_tag(peer, t); @@ -1399,21 +1417,27 @@ wg_handshake(struct wg_softc *sc, struct mbuf *m) underload, &t->t_endpoint.e_remote.r_sa); if (res == EINVAL) { - DPRINTF(sc, "Invalid response MAC\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Invalid response " + "MAC from %s\n", wg_log_ip(&t->t_endpoint)); goto error; } else if (res == ECONNREFUSED) { - DPRINTF(sc, "Handshake ratelimited\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Handshake " + "ratelimited from %s\n", + wg_log_ip(&t->t_endpoint)); goto error; } else if (res == EAGAIN) { wg_send_cookie(sc, &resp->m, resp->s_idx, &t->t_endpoint); goto error; } else if (res != 0) { - panic("unexpected response: %d", res); + panic("wg: Unexpected response from " + "cookie_checker_validate_macs(): %d", res); } if ((remote = wg_index_get(sc, resp->r_idx)) == NULL) { - DPRINTF(sc, "Unknown handshake response\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Unknown " + "handshake response from %s\n", + wg_log_ip(&t->t_endpoint)); goto error; } @@ -1421,12 +1445,14 @@ wg_handshake(struct wg_softc *sc, struct mbuf *m) if (noise_consume_response(remote, resp->s_idx, resp->r_idx, resp->ue, resp->en) != 0) { - DPRINTF(sc, "Invalid handshake response\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Invalid handshake " + "response from %s\n", wg_log_ip(&t->t_endpoint)); goto error; } - DPRINTF(sc, "Receiving handshake response from peer %llu\n", - peer->p_id); + WGPRINTF(LOG_INFO, sc, NULL, "Receiving handshake response " + "from peer %llu (%s)\n", peer->p_id, + wg_log_ip(&t->t_endpoint)); wg_peer_counters_add(peer, 0, sizeof(*resp)); wg_peer_set_endpoint_from_tag(peer, t); @@ -1439,7 +1465,8 @@ wg_handshake(struct wg_softc *sc, struct mbuf *m) cook = mtod(m, struct wg_pkt_cookie *); if ((remote = wg_index_get(sc, cook->r_idx)) == NULL) { - DPRINTF(sc, "Unknown cookie index\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Unknown cookie " + "index from %s\n", wg_log_ip(&t->t_endpoint)); goto error; } @@ -1447,14 +1474,17 @@ wg_handshake(struct wg_softc *sc, struct mbuf *m) if (cookie_maker_consume_payload(&peer->p_cookie, cook->nonce, cook->ec) != 0) { - DPRINTF(sc, "Could not decrypt cookie response\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Could not decrypt " + "cookie response from %s\n", + wg_log_ip(&t->t_endpoint)); goto error; } - DPRINTF(sc, "Receiving cookie response\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Receiving cookie response " + "from %s\n", wg_log_ip(&t->t_endpoint)); goto error; default: - panic("invalid packet in handshake queue"); + panic("wg: Invalid packet in handshake queue"); } wg_timers_event_any_authenticated_packet_received(&peer->p_timers); @@ -1505,6 +1535,8 @@ wg_encap(struct wg_softc *sc, struct mbuf *m) struct mbuf *mc; size_t padding_len, plaintext_len, out_len; uint64_t nonce; + static struct timeval lastkeepalivemsg; + struct timeval errint = { 300, 0 }; t = wg_tag_get(m); peer = t->t_peer; @@ -1553,13 +1585,17 @@ wg_encap(struct wg_softc *sc, struct mbuf *m) } else if (__predict_false(res == ESTALE)) { wg_timers_event_want_initiation(&peer->p_timers); } else if (__predict_false(res != 0)) { - panic("unexpected result: %d", res); + panic("wg: Unexpected result %d from " + "noise_remote_encrypt()!", res); } /* A packet with length 0 is a keepalive packet */ - if (__predict_false(m->m_pkthdr.len == 0)) - DPRINTF(sc, "Sending keepalive packet to peer %llu\n", - peer->p_id); + /* Limit to once every 5 minutes to avoid flooding logs */ + if (__predict_false(m->m_pkthdr.len == 0) && + ratecheck(&lastkeepalivemsg, &errint)) + WGPRINTF(LOG_DEBUG, sc, &peer->p_endpoint_mtx, "Sending " + "keepalive packet to peer %llu (%s)\n", peer->p_id, + wg_log_ip(&peer->p_endpoint)); mc->m_pkthdr.ph_loopcnt = m->m_pkthdr.ph_loopcnt; mc->m_flags &= ~(M_MCAST | M_BCAST); @@ -1590,6 +1626,8 @@ wg_decap(struct wg_softc *sc, struct mbuf *m) struct wg_tag *t; size_t payload_len; uint64_t nonce; + static struct timeval lastkeepalivemsg; + struct timeval errint = { 300, 0 }; t = wg_tag_get(m); peer = t->t_peer; @@ -1616,7 +1654,8 @@ wg_decap(struct wg_softc *sc, struct mbuf *m) } else if (__predict_false(res == ESTALE)) { wg_timers_event_want_initiation(&peer->p_timers); } else if (__predict_false(res != 0)) { - panic("unexpected response: %d", res); + panic("wg: Unexpected response %d from" + "noise_remote_decrypt()!", res); } wg_peer_set_endpoint_from_tag(peer, t); @@ -1630,9 +1669,13 @@ wg_decap(struct wg_softc *sc, struct mbuf *m) m->m_pkthdr.len); /* A packet with length 0 is a keepalive packet */ + /* Limit to once every 5 minutes to avoid flooding logs */ if (__predict_false(m->m_pkthdr.len == 0)) { - DPRINTF(sc, "Receiving keepalive packet from peer " - "%llu\n", peer->p_id); + if (ratecheck(&lastkeepalivemsg, &errint)) + WGPRINTF(LOG_DEBUG, sc, &peer->p_endpoint_mtx, + "Receiving keepalive packet from peer %llu " + "(%s)\n", peer->p_id, + wg_log_ip(&peer->p_endpoint)); goto done; } @@ -1670,14 +1713,16 @@ wg_decap(struct wg_softc *sc, struct mbuf *m) allowed_peer = wg_aip_lookup(sc->sc_aip6, &ip6->ip6_src); #endif } else { - DPRINTF(sc, "Packet is neither ipv4 nor ipv6 from " - "peer %llu\n", peer->p_id); + WGPRINTF(LOG_WARNING, sc, &peer->p_endpoint_mtx, "Packet " + "is neither IPv4 nor IPv6 from peer %llu (%s)\n", + peer->p_id, wg_log_ip(&peer->p_endpoint)); goto error; } if (__predict_false(peer != allowed_peer)) { - DPRINTF(sc, "Packet has unallowed src IP from peer " - "%llu\n", peer->p_id); + WGPRINTF(LOG_WARNING, sc, &peer->p_endpoint_mtx, "Packet " + "has unallowed source IP from peer %llu (%s)\n", + peer->p_id, wg_log_ip(&peer->p_endpoint)); goto error; } @@ -1798,7 +1843,7 @@ wg_deliver_in(void *_peer) ipv6_input(&sc->sc_if, m); #endif else - panic("invalid ph_family"); + panic("wg: Invalid ph_family in wg_deliver_in()"); NET_UNLOCK(); wg_timers_event_data_received(&peer->p_timers); @@ -2059,7 +2104,8 @@ wg_input(void *_sc, struct mbuf *m, struct ip *ip, str *mtod(m, uint32_t *) == WG_PKT_COOKIE)) { if (mq_enqueue(&sc->sc_handshake_queue, m) != 0) - DPRINTF(sc, "Dropping handshake packet\n"); + WGPRINTF(LOG_DEBUG, sc, NULL, "Dropping handshake" + "packet from %s\n", wg_log_ip(&t->t_endpoint)); task_add(wg_handshake_taskq, &sc->sc_handshake); } else if (m->m_pkthdr.len >= sizeof(struct wg_pkt_data) + @@ -2130,10 +2176,12 @@ int wg_output(struct ifnet *ifp, struct mbuf *m, struct sockaddr *sa, struct rtentry *rt) { - struct wg_softc *sc = ifp->if_softc; - struct wg_peer *peer; - struct wg_tag *t; - int af, ret = EINVAL; + struct wg_softc *sc = ifp->if_softc; + struct wg_peer *peer; + struct wg_tag *t; + int af, ret = EINVAL; + static struct timeval lasterr, looperr, delayerr; + struct timeval errint = { 300, 0 }; NET_ASSERT_LOCKED(); @@ -2169,14 +2217,18 @@ wg_output(struct ifnet *ifp, struct mbuf *m, struct so af = peer->p_endpoint.e_remote.r_sa.sa_family; if (af != AF_INET && af != AF_INET6) { - DPRINTF(sc, "No valid endpoint has been configured or " - "discovered for peer %llu\n", peer->p_id); + if (ratecheck(&lasterr, &errint)) + WGPRINTF(LOG_DEBUG, sc, NULL, "No valid endpoint has " + "been configured or discovered for peer %llu\n", + peer->p_id); + ret = EDESTADDRREQ; goto error; } if (m->m_pkthdr.ph_loopcnt++ > M_MAXLOOP) { - DPRINTF(sc, "Packet looped\n"); + if (ratecheck(&looperr, &errint)) + WGPRINTF(LOG_DEBUG, sc, NULL, "Packet looped\n"); ret = ELOOP; goto error; } @@ -2189,7 +2241,8 @@ wg_output(struct ifnet *ifp, struct mbuf *m, struct so * another aip_lookup in wg_qstart, or refcnting as mentioned before. */ if (m->m_pkthdr.pf.delay > 0) { - DPRINTF(sc, "PF delay unsupported\n"); + if (ratecheck(&delayerr, &errint)) + WGPRINTF(LOG_DEBUG, sc, NULL, "PF delay unsupported\n"); ret = EOPNOTSUPP; goto error; } @@ -2702,7 +2755,7 @@ wg_clone_create(struct if_clone *ifc, int unit) bpfattach(&ifp->if_bpf, ifp, DLT_LOOP, sizeof(uint32_t)); #endif - DPRINTF(sc, "Interface created\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Interface created\n"); return 0; ret_05: @@ -2745,7 +2798,7 @@ wg_clone_destroy(struct ifnet *ifp) wg_crypt_taskq = NULL; } - DPRINTF(sc, "Destroyed interface\n"); + WGPRINTF(LOG_INFO, sc, NULL, "Interface destroyed\n"); hashfree(sc->sc_index, HASHTABLE_INDEX_SIZE, M_DEVBUF); hashfree(sc->sc_peer, HASHTABLE_PEER_SIZE, M_DEVBUF); @@ -2773,4 +2826,14 @@ wgattach(int nwg) IPL_NET, 0, "wgpeer", NULL); pool_init(&wg_ratelimit_pool, sizeof(struct ratelimit_entry), 0, IPL_NET, 0, "wgratelimit", NULL); +} + +char * +wg_log_ip(struct wg_endpoint *ep) +{ + static char strIPAddr[INET6_ADDRSTRLEN]; + + if (!sockaddr_ntop(&ep->e_remote.r_sa, strIPAddr, sizeof(strIPAddr))) + strIPAddr[0] = '\0'; + return strIPAddr; }