From: Vitaliy Makkoveev Subject: Re: wg(4) logging enhancement - revised patch To: Lloyd Cc: Vitaliy Makkoveev , Claudio Jeker , Theo de Raadt , Stuart Henderson , "tech@openbsd.org" Date: Wed, 22 Jan 2025 14:00:49 +0300 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 > #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; > } > >