From: Lloyd Subject: wg(4) logging enhancement - revised patch To: "tech@openbsd.org" Date: Sun, 29 Dec 2024 22:29:58 +0000 Some tweaks made to the log level - moves chatter to DEBUG with security-relevant messages at INFO and WARNING levels. Either way wg(4) will no longer dump bluetext to the console. Tested with both IPv4 and IPv6 endpoints. --- if_wg.c.orig Thu Oct 31 12:33:11 2024 +++ if_wg.c Sun Dec 29 20:47:57 2024 @@ -30,6 +30,8 @@ #include #include #include +#include +#include #include #include @@ -70,9 +72,6 @@ #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 CONTAINER_OF(ptr, type, member) ({ \ const __typeof( ((type *)0)->member ) *__mptr = (ptr); \ (type *)( (char *)__mptr - offsetof(type,member) );}) @@ -371,6 +370,7 @@ void wg_down(struct wg_softc *); int wg_clone_create(struct if_clone *, int); int wg_clone_destroy(struct ifnet *); void wgattach(int); +void wg_log_ip(struct wg_endpoint *); uint64_t peer_counter = 0; struct pool wg_aip_pool; @@ -448,7 +448,12 @@ 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); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Peer %llu created\n", + sc->sc_if.if_xname, peer->p_id); + } return peer; } @@ -530,7 +535,13 @@ 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); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Peer %llu destroyed\n", + sc->sc_if.if_xname, peer->p_id); + } + explicit_bzero(peer, sizeof(*peer)); pool_put(&wg_peer_pool, peer); } @@ -883,7 +894,14 @@ retry: } else { ret = wg_send(sc, e, m); if (ret != 0) - DPRINTF(sc, "Unable to send packet\n"); + { + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Unable to send packet\n", + sc->sc_if.if_xname); + } + } } } @@ -1149,19 +1167,34 @@ wg_timers_run_retry_handshake(void *_t) if (t->t_handshake_retries <= MAX_TIMER_HANDSHAKES) { t->t_handshake_retries++; mtx_leave(&t->t_handshake_mtx); + + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Handshake for peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(") did not complete after %d seconds, retrying (try %d)\n", + REKEY_TIMEOUT, t->t_handshake_retries + 1); + } - 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); wg_peer_clear_src(peer); wg_timers_run_send_initiation(t, 1); } else { mtx_leave(&t->t_handshake_mtx); + + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Handshake for peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(") did not complete after %d retries, giving up\n", + MAX_TIMER_HANDSHAKES + 2); + } - DPRINTF(peer->p_sc, "Handshake for peer %llu did not complete " - "after %d retries, giving up\n", peer->p_id, - MAX_TIMER_HANDSHAKES + 2); - timeout_del(&t->t_send_keepalive); mq_purge(&peer->p_stage_queue); if (!timeout_pending(&t->t_zero_key_material)) @@ -1188,10 +1221,18 @@ 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); + + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Retrying handshake with peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(") because we stopped hearing back after %d seconds\n", + NEW_HANDSHAKE_TIMEOUT); + } + wg_peer_clear_src(peer); wg_timers_run_send_initiation(t, 0); @@ -1203,7 +1244,15 @@ 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); + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Zeroing out keys for peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } task_add(wg_handshake_taskq, &peer->p_clear_secrets); } @@ -1237,10 +1286,17 @@ wg_send_initiation(void *_peer) if (wg_timers_check_handshake_last_sent(&peer->p_timers) != ETIMEDOUT) return; + + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Sending handshake initiation to peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } - DPRINTF(peer->p_sc, "Sending handshake initiation to peer %llu\n", - peer->p_id); - if (noise_create_initiation(&peer->p_remote, &pkt.s_idx, pkt.ue, pkt.es, pkt.ets) != 0) return; @@ -1255,10 +1311,18 @@ void wg_send_response(struct wg_peer *peer) { struct wg_pkt_response pkt; + + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Sending handshake response to peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } + - DPRINTF(peer->p_sc, "Sending handshake response to peer %llu\n", - peer->p_id); - if (noise_create_response(&peer->p_remote, &pkt.s_idx, &pkt.r_idx, pkt.ue, pkt.en) != 0) return; @@ -1277,9 +1341,14 @@ wg_send_cookie(struct wg_softc *sc, struct cookie_macs struct wg_endpoint *e) { struct wg_pkt_cookie pkt; + + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Sending cookie response for denied handshake message\n", + sc->sc_if.if_xname); + } - DPRINTF(sc, "Sending cookie response for denied handshake message\n"); - pkt.t = WG_PKT_COOKIE; pkt.r_idx = idx; @@ -1363,30 +1432,58 @@ 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"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Invalid initiation MAC from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } else if (res == ECONNREFUSED) { - DPRINTF(sc, "Handshake ratelimited\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Handshake ratelimited from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } 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: %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"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Invalid handshake initiation from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } peer = CONTAINER_OF(remote, struct wg_peer, p_remote); + + if ( ISSET(peer->p_sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Receiving handshake initiation from peer %llu (", + peer->p_sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(t->t_endpoint)); + addlog(")\n"); + } - DPRINTF(sc, "Receiving handshake initiation from peer %llu\n", - peer->p_id); - wg_peer_counters_add(peer, 0, sizeof(*init)); wg_peer_set_endpoint_from_tag(peer, t); wg_send_response(peer); @@ -1397,36 +1494,69 @@ wg_handshake(struct wg_softc *sc, struct mbuf *m) res = cookie_checker_validate_macs(&sc->sc_cookie, &resp->m, resp, sizeof(*resp) - sizeof(resp->m), underload, &t->t_endpoint.e_remote.r_sa); - if (res == EINVAL) { - DPRINTF(sc, "Invalid response MAC\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Invalid response MAC from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } else if (res == ECONNREFUSED) { - DPRINTF(sc, "Handshake ratelimited\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Handshake ratelimited from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } 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: %d", res); } if ((remote = wg_index_get(sc, resp->r_idx)) == NULL) { - DPRINTF(sc, "Unknown handshake response\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Unknown handshake response from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } peer = CONTAINER_OF(remote, struct wg_peer, p_remote); - if (noise_consume_response(remote, resp->s_idx, resp->r_idx, resp->ue, resp->en) != 0) { - DPRINTF(sc, "Invalid handshake response\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Invalid handshake response from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } - - DPRINTF(sc, "Receiving handshake response from peer %llu\n", + + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Receiving handshake response from peer %llu (", + sc->sc_if.if_xname, peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } wg_peer_counters_add(peer, 0, sizeof(*resp)); wg_peer_set_endpoint_from_tag(peer, t); @@ -1439,7 +1569,14 @@ 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"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Unknown cookie index from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } @@ -1447,14 +1584,28 @@ 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"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Could not decrypt cookie response from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } goto error; } - DPRINTF(sc, "Receiving cookie response\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Receiving cookie response from ", + sc->sc_if.if_xname); + wg_log_ip(&(t->t_endpoint)); + addlog("\n"); + } 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 +1656,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; @@ -1558,9 +1711,18 @@ wg_encap(struct wg_softc *sc, struct mbuf *m) /* 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); - + { + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) && ratecheck(&lastkeepalivemsg, &errint)) + { + log(LOG_DEBUG, + "%s: Sending keepalive packet to peer %llu (", + sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } + } + mc->m_pkthdr.ph_loopcnt = m->m_pkthdr.ph_loopcnt; mc->m_flags &= ~(M_MCAST | M_BCAST); mc->m_pkthdr.len = mc->m_len = out_len; @@ -1590,6 +1752,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; @@ -1631,8 +1795,15 @@ wg_decap(struct wg_softc *sc, struct mbuf *m) /* A packet with length 0 is a keepalive packet */ if (__predict_false(m->m_pkthdr.len == 0)) { - DPRINTF(sc, "Receiving keepalive packet from peer " - "%llu\n", peer->p_id); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) && ratecheck(&lastkeepalivemsg, &errint)) + { + log(LOG_DEBUG, + "%s: Receiving keepalive packet from peer %llu (", + sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } goto done; } @@ -1670,14 +1841,30 @@ 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); + + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_WARNING, + "%s: Packet is neither IPv4 nor IPv6 from peer %llu (", + sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } + goto error; } if (__predict_false(peer != allowed_peer)) { - DPRINTF(sc, "Packet has unallowed src IP from peer " - "%llu\n", peer->p_id); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_WARNING, + "%s: Packet has unallowed src IP from peer %llu (", + sc->sc_if.if_xname, + peer->p_id); + wg_log_ip(&(peer->p_endpoint)); + addlog(")\n"); + } goto error; } @@ -2059,7 +2246,15 @@ 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"); + { + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_DEBUG, + "%s: Dropping handshake packet\n", + sc->sc_if.if_xname); + } + } + task_add(wg_handshake_taskq, &sc->sc_handshake); } else if (m->m_pkthdr.len >= sizeof(struct wg_pkt_data) + @@ -2133,7 +2328,9 @@ wg_output(struct ifnet *ifp, struct mbuf *m, struct so struct wg_softc *sc = ifp->if_softc; struct wg_peer *peer; struct wg_tag *t; - int af, ret = EINVAL; + int af, ret = EINVAL; + static struct timeval lasterr, looperr, delayerr; + struct timeval errint = { 300, 0 }; NET_ASSERT_LOCKED(); @@ -2166,17 +2363,33 @@ wg_output(struct ifnet *ifp, struct mbuf *m, struct so ret = ENETUNREACH; goto error; } - 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 ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + if (ratecheck(&lasterr, &errint)) + { + log(LOG_DEBUG, + "%s: No valid endpoint has been configured " + "or discovered for peer %llu\n", + sc->sc_if.if_xname, peer->p_id); + } + } ret = EDESTADDRREQ; goto error; } if (m->m_pkthdr.ph_loopcnt++ > M_MAXLOOP) { - DPRINTF(sc, "Packet looped\n"); + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + if (ratecheck(&looperr, &errint)) + { + log(LOG_DEBUG, + "%s: Packet looped\n", + sc->sc_if.if_xname); + } + } ret = ELOOP; goto error; } @@ -2189,7 +2402,15 @@ 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 ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + if (ratecheck(&delayerr, &errint)) + { + log(LOG_DEBUG, + "%s: PF delay unsupported\n", + sc->sc_if.if_xname); + } + } ret = EOPNOTSUPP; goto error; } @@ -2701,9 +2922,14 @@ wg_clone_create(struct if_clone *ifc, int unit) #if NBPFILTER > 0 bpfattach(&ifp->if_bpf, ifp, DLT_LOOP, sizeof(uint32_t)); #endif + + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Interface created\n", + sc->sc_if.if_xname); + } - DPRINTF(sc, "Interface created\n"); - return 0; ret_05: hashfree(sc->sc_peer, HASHTABLE_PEER_SIZE, M_DEVBUF); @@ -2744,9 +2970,14 @@ wg_clone_destroy(struct ifnet *ifp) wg_handshake_taskq = NULL; wg_crypt_taskq = NULL; } + + if ( ISSET(sc->sc_if.if_flags, IFF_DEBUG) ) + { + log(LOG_INFO, + "%s: Interface destroyed\n", + sc->sc_if.if_xname); + } - DPRINTF(sc, "Destroyed interface\n"); - hashfree(sc->sc_index, HASHTABLE_INDEX_SIZE, M_DEVBUF); hashfree(sc->sc_peer, HASHTABLE_PEER_SIZE, M_DEVBUF); #ifdef INET6 @@ -2773,4 +3004,81 @@ wgattach(int nwg) IPL_NET, 0, "wgpeer", NULL); pool_init(&wg_ratelimit_pool, sizeof(struct ratelimit_entry), 0, IPL_NET, 0, "wgratelimit", NULL); +} + +void +wg_log_ip(struct wg_endpoint *ep) +{ + u_int32_t addr; +#ifdef INET6 + struct in6_addr addr6; +#endif + + switch(ep->e_remote.r_sa.sa_family) + { + case AF_INET: + addr = ntohl(ep->e_remote.r_sin.sin_addr.s_addr); + addlog("%u.%u.%u.%u", (addr>>24)&255, (addr>>16)&255, (addr>>8)&255, addr&255); + break; +#ifdef INET6 + case AF_INET6: + addr6 = ep->e_remote.r_sin6.sin6_addr; + u_int16_t b; + u_int8_t i, curstart, curend, maxstart, maxend; + curstart = curend = maxstart = maxend = 255; + for (i = 0; i < 8; i++) + { + if (!addr6.s6_addr16[i]) + { + if (curstart == 255) + { + curstart = i; + } + curend = i; + } + else + { + if ((curend - curstart) > + (maxend - maxstart)) + { + maxstart = curstart; + maxend = curend; + } + curstart = curend = 255; + } + } + if ((curend - curstart) > + (maxend - maxstart)) + { + maxstart = curstart; + maxend = curend; + } + for (i = 0; i < 8; i++) + { + if (i >= maxstart && i <= maxend) + { + if (i == 0) + { + addlog(":"); + } + if (i == maxend) + { + addlog(":"); + } + } + else + { + b = ntohs(addr6.s6_addr16[i]); + addlog("%x", b); + if (i < 7) + { + addlog(":"); + } + } + } + break; +#endif + default: + break; + } }