Download raw body.
wg(4) logging enhancement - revised patch
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 <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