Download raw body.
wg(4) logging enhancement - revised patch
On Wed, Jan 22, 2025 at 12:27:25AM +0000, Lloyd wrote:
> 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.
>
1. Please rework macro according style(9):
#define MACRO(x, y) do { \
variable = (x) + (y); \
(y) += 2; \
} while (0)
2. We don't use camel case.
3. panic(9) is not related to your diff. Leave it as is.
4. wg_log_ip() doesn't work as you desired. The `p_endpoint_mtx'
mutex(9) protects peer->p_endpoint of this peer only, concurrent
wg_log_ip() thread working with another `peer' will break
`strIPAddr'.
> +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;
> }
> + 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,
> 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 <sys/percpu.h>
> #include <sys/ioctl.h>
> #include <sys/mbuf.h>
> +#include <sys/syslog.h>
> +#include <sys/time.h>
>
> #include <net/if.h>
> #include <net/if_var.h>
> @@ -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;
> }
>
>
wg(4) logging enhancement - revised patch