dhcpcd-discuss

Re: dhcpcd logging subsystem modification

Sergey Nikiforov

Mon Feb 10 13:45:20 2020

Hi Roy

On 10.02.2020 14:46, Roy Marples wrote:
Hi Sergey

On 10/02/2020 08:46, Sergey Nikiforov wrote:
Here at Kaspersky we are using dhcpcd code pulled from NetBSD project and patched to work on KasperskyOS. There is, however, an issue with logging subsystem - we use our own which uses source code file name, line number etc. The obvious solution is to replace functions like "loginfox" with macros, but this can't be done without patching several tens of places where addresses of such functions are taken to choose logging level ("debug"/"info" etc).


Will you accept a patch which will rename "loginfox" and similar functions, add macros with old names ("loginfox" etc) calling renamed functions (to keep existing logging syntax but prevent their addresses being taken) and adjust no longer compilable places in code to use "logging level" parameter instead of function pointer? This way everyone who needs logging with __LINE__ and similar macros would not need to patch several tens of places in dhcpcd code.

Please show a small patch to demonstrate the intent.
From your description I don't see an issue, but would like to see the idea first.


PoC patch is attached (not so small because dhcp.c required a lot of changes). It is not complete and is not compilable, I have implemented only "loginfox" and fixed only dhcp.c and ipv6.c. BTW code w/o indirect function calls is faster, especially if retpolines are used..

WBR,

Sergey Nikiforov, Kaspersky Developer


diff --git a/src/dhcp.c b/src/dhcp.c
index 2fdfd837..e335b167 100644
--- a/src/dhcp.c
+++ b/src/dhcp.c
@@ -56,6 +56,7 @@
 #include <stdlib.h>
 #include <string.h>
 #include <unistd.h>
+#include <syslog.h>
 
 #define ELOOP_QUEUE	ELOOP_DHCP
 #include "config.h"
@@ -2818,7 +2819,7 @@ whitelisted_ip(const struct if_options *ifo, in_addr_t addr)
 }
 
 static void
-log_dhcp(logfunc_t *logfunc, const char *msg,
+log_dhcp(int loglevel, const char *msg,
     const struct interface *ifp, const struct bootp *bootp, size_t bootp_len,
     const struct in_addr *from, int ad)
 {
@@ -2865,10 +2866,10 @@ log_dhcp(logfunc_t *logfunc, const char *msg,
 		print_string(sname, sizeof(sname), OT_STRING | OT_DOMAIN,
 		    bootp->sname, sizeof(bootp->sname));
 		if (a == NULL)
-			logfunc("%s: %s %s %s `%s'",
+			logmessage(loglevel, "%s: %s %s %s `%s'",
 			    ifp->name, msg, tfrom, inet_ntoa(addr), sname);
 		else
-			logfunc("%s: %s %s %s %s `%s'",
+			logmessage(loglevel, "%s: %s %s %s %s `%s'",
 			    ifp->name, msg, a, tfrom, inet_ntoa(addr), sname);
 	} else {
 		if (r != 0) {
@@ -2876,10 +2877,10 @@ log_dhcp(logfunc_t *logfunc, const char *msg,
 			addr = *from;
 		}
 		if (a == NULL)
-			logfunc("%s: %s %s %s",
+			logmessage(loglevel, "%s: %s %s %s",
 			    ifp->name, msg, tfrom, inet_ntoa(addr));
 		else
-			logfunc("%s: %s %s %s %s",
+			logmessage(loglevel, "%s: %s %s %s %s",
 			    ifp->name, msg, a, tfrom, inet_ntoa(addr));
 	}
 	free(a);
@@ -3011,7 +3012,7 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 		    (uint8_t *)bootp, bootp_len, 4, type,
 		    auth, auth_len) == NULL)
 		{
-			LOGDHCP0(logerrx, "authentication failed");
+			LOGDHCP0(LOG_ERR, "authentication failed");
 			return;
 		}
 		if (state->auth.token)
@@ -3021,10 +3022,10 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 			loginfox("%s: accepted reconfigure key", ifp->name);
 	} else if (ifo->auth.options & DHCPCD_AUTH_SEND) {
 		if (ifo->auth.options & DHCPCD_AUTH_REQUIRE) {
-			LOGDHCP0(logerrx, "no authentication");
+			LOGDHCP0(LOG_ERR, "no authentication");
 			return;
 		}
-		LOGDHCP0(logwarnx, "no authentication");
+		LOGDHCP0(LOG_WARNING, "no authentication");
 	}
 #endif
 
@@ -3033,20 +3034,20 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 		if (from->s_addr == INADDR_ANY ||
 		    from->s_addr == INADDR_BROADCAST)
 		{
-			LOGDHCP(logerrx, "discarding Force Renew");
+			LOGDHCP(LOG_ERR, "discarding Force Renew");
 			return;
 		}
 #ifdef AUTH
 		if (auth == NULL) {
-			LOGDHCP(logerrx, "unauthenticated Force Renew");
+			LOGDHCP(LOG_ERR, "unauthenticated Force Renew");
 			if (ifo->auth.options & DHCPCD_AUTH_REQUIRE)
 				return;
 		}
 		if (state->state != DHS_BOUND && state->state != DHS_INFORM) {
-			LOGDHCP(logdebugx, "not bound, ignoring Force Renew");
+			LOGDHCP(LOG_DEBUG, "not bound, ignoring Force Renew");
 			return;
 		}
-		LOGDHCP(loginfox, "Force Renew from");
+		LOGDHCP(LOG_INFO, "Force Renew from");
 		/* The rebind and expire timings are still the same, we just
 		 * enter the renew state early */
 		if (state->state == DHS_BOUND)
@@ -3057,19 +3058,19 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 			dhcp_inform(ifp);
 		}
 #else
-		LOGDHCP(logerrx, "unauthenticated Force Renew");
+		LOGDHCP(LOG_ERR, "unauthenticated Force Renew");
 #endif
 		return;
 	}
 
 	if (state->state == DHS_BOUND) {
-		LOGDHCP(logdebugx, "bound, ignoring");
+		LOGDHCP(LOG_DEBUG, "bound, ignoring");
 		return;
 	}
 
 	if (state->state == DHS_PROBE) {
 		/* Ignore any DHCP messages whilst probing a lease to bind. */
-		LOGDHCP(logdebugx, "probing, ignoring");
+		LOGDHCP(LOG_DEBUG, "probing, ignoring");
 		return;
 	}
 
@@ -3082,7 +3083,7 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 		    get_option_uint8(ifp->ctx, &tmp,
 		    bootp, bootp_len, (uint8_t)i) == 0)
 		{
-			LOGDHCP(logwarnx, "reject DHCP");
+			LOGDHCP(LOG_WARNING, "reject DHCP");
 			return;
 		}
 	}
@@ -3093,12 +3094,12 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 		    get_option_addr(ifp->ctx, &addr,
 		    bootp, bootp_len, DHO_SERVERID) == -1)
 		{
-			LOGDHCP(logwarnx, "reject NAK");
+			LOGDHCP(LOG_WARNING, "reject NAK");
 			return;
 		}
 
 		/* We should restart on a NAK */
-		LOGDHCP(logwarnx, "NAK:");
+		LOGDHCP(LOG_WARNING, "NAK:");
 		if ((msg = get_option_string(ifp->ctx,
 		    bootp, bootp_len, DHO_MESSAGE)))
 		{
@@ -3138,14 +3139,14 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 			 * always true. */
 			if (type == 0 && i == DHO_SERVERID)
 				continue;
-			LOGDHCP(logwarnx, "reject DHCP");
+			LOGDHCP(LOG_WARNING, "reject DHCP");
 			return;
 		}
 	}
 
 	/* DHCP Auto-Configure, RFC 2563 */
 	if (type == DHCP_OFFER && bootp->yiaddr == 0) {
-		LOGDHCP(logwarnx, "no address given");
+		LOGDHCP(LOG_WARNING, "no address given");
 		if ((msg = get_option_string(ifp->ctx,
 		    bootp, bootp_len, DHO_MESSAGE)))
 		{
@@ -3159,14 +3160,14 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 		{
 			switch (tmp) {
 			case 0:
-				LOGDHCP(logwarnx, "IPv4LL disabled from");
+				LOGDHCP(LOG_WARNING, "IPv4LL disabled from");
 				ipv4ll_drop(ifp);
 #ifdef ARP
 				arp_drop(ifp);
 #endif
 				break;
 			case 1:
-				LOGDHCP(logwarnx, "IPv4LL enabled from");
+				LOGDHCP(LOG_WARNING, "IPv4LL enabled from");
 				ipv4ll_start(ifp);
 				break;
 			default:
@@ -3189,14 +3190,14 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 	    &&
 	    (bootp->yiaddr == INADDR_ANY || bootp->yiaddr == INADDR_BROADCAST))
 	{
-		LOGDHCP(logwarnx, "reject invalid address");
+		LOGDHCP(LOG_WARNING, "reject invalid address");
 		return;
 	}
 
 #ifdef IN_IFF_DUPLICATED
 	ia = ipv4_iffindaddr(ifp, &lease->addr, NULL);
 	if (ia && ia->addr_flags & IN_IFF_DUPLICATED) {
-		LOGDHCP(logwarnx, "declined duplicate address");
+		LOGDHCP(LOG_WARNING, "declined duplicate address");
 		if (type)
 			dhcp_decline(ifp);
 		ipv4_deladdr(ia, 0);
@@ -3227,7 +3228,7 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 			goto rapidcommit;
 		}
 
-		LOGDHCP(loginfox, "offered");
+		LOGDHCP(LOG_WARNING, "offered");
 		if (state->offer_len < bootp_len) {
 			free(state->offer);
 			if ((state->offer = malloc(bootp_len)) == NULL) {
@@ -3269,13 +3270,13 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 
 	if (type) {
 		if (type == DHCP_OFFER) {
-			LOGDHCP(logwarnx, "ignoring offer of");
+			LOGDHCP(LOG_WARNING, "ignoring offer of");
 			return;
 		}
 
 		/* We should only be dealing with acks */
 		if (type != DHCP_ACK) {
-			LOGDHCP(logerr, "not ACK or OFFER");
+			LOGDHCP(LOG_ERR, "not ACK or OFFER");
 			return;
 		}
 
@@ -3287,14 +3288,14 @@ dhcp_handledhcp(struct interface *ifp, struct bootp *bootp, size_t bootp_len,
 			    DHO_RAPIDCOMMIT, NULL))
 				state->state = DHS_REQUEST;
 			else {
-				LOGDHCP(logdebugx, "ignoring ack of");
+				LOGDHCP(LOG_DEBUG, "ignoring ack of");
 				return;
 			}
 		}
 
 rapidcommit:
 		if (!(ifo->options & DHCPCD_INFORM))
-			LOGDHCP(logdebugx, "acknowledged");
+			LOGDHCP(LOG_DEBUG, "acknowledged");
 		else
 		    ifo->options &= ~DHCPCD_STATIC;
 	}
diff --git a/src/ipv6.c b/src/ipv6.c
index 0ac9f095..85049554 100644
--- a/src/ipv6.c
+++ b/src/ipv6.c
@@ -36,6 +36,7 @@
 #include <net/route.h>
 #include <netinet/in.h>
 #include <netinet/if_ether.h>
+#include <syslog.h>
 
 #include "config.h"
 
@@ -616,7 +617,7 @@ ipv6_addaddr1(struct ipv6_addr *ia, const struct timespec *now)
 {
 	struct interface *ifp;
 	uint32_t pltime, vltime;
-	__printflike(1, 2) void (*logfunc)(const char *, ...);
+	int loglevel;
 #ifdef ND6_ADVERTISE
 	bool vltime_was_zero = ia->prefix_vltime == 0;
 #endif
@@ -675,8 +676,8 @@ ipv6_addaddr1(struct ipv6_addr *ia, const struct timespec *now)
 		}
 	}
 
-	logfunc = ia->flags & IPV6_AF_NEW ? loginfox : logdebugx;
-	logfunc("%s: adding %saddress %s", ifp->name,
+	loglevel = ia->flags & IPV6_AF_NEW ? LOG_INFO : LOG_DEBUG;
+	logmessage(loglevel, "%s: adding %saddress %s", ifp->name,
 #ifdef IPV6_AF_TEMPORARY
 	    ia->flags & IPV6_AF_TEMPORARY ? "temporary " : "",
 #else
diff --git a/src/logerr.c b/src/logerr.c
index b33204d9..9804fdfd 100644
--- a/src/logerr.c
+++ b/src/logerr.c
@@ -220,7 +220,7 @@ vlogmessage(int pri, const char *fmt, va_list args)
 #pragma GCC diagnostic pop
 #endif
 
-__printflike(2, 3) static void
+__printflike(2, 3) void
 logmessage(int pri, const char *fmt, ...)
 {
 	va_list args;
@@ -271,7 +271,7 @@ loginfo(const char *fmt, ...)
 }
 
 void
-loginfox(const char *fmt, ...)
+loginfox_func(const char *fmt, ...)
 {
 	va_list args;
 
diff --git a/src/logerr.h b/src/logerr.h
index 1923ab73..82d63f29 100644
--- a/src/logerr.h
+++ b/src/logerr.h
@@ -44,12 +44,17 @@ __printflike(1, 2) typedef void logfunc_t(const char *, ...);
 __printflike(1, 2) void logdebug(const char *, ...);
 __printflike(1, 2) void logdebugx(const char *, ...);
 __printflike(1, 2) void loginfo(const char *, ...);
-__printflike(1, 2) void loginfox(const char *, ...);
+__printflike(1, 2) void loginfox_func(const char *, ...);
 __printflike(1, 2) void logwarn(const char *, ...);
 __printflike(1, 2) void logwarnx(const char *, ...);
 __printflike(1, 2) void logerr(const char *, ...);
 #define	LOGERROR	logerr("%s: %d", __FILE__, __LINE__)
 __printflike(1, 2) void logerrx(const char *, ...);
+__printflike(2, 3) void logmessage(int pri, const char *fmt, ...);
+
+/* It is a macro to prevent taking address of it so __FILE__/__LINE__ etc
+ * can easily be added */
+#define loginfox(fmt, ...) loginfox_func(fmt, ##__VA_ARGS__)
 
 void logsetopts(unsigned int);
 #define	LOGERR_DEBUG	(1U << 6)

Follow-Ups:
Re: dhcpcd logging subsystem modificationRoy Marples
References:
dhcpcd logging subsystem modificationSergey Nikiforov
Re: dhcpcd logging subsystem modificationRoy Marples
Archive administrator: postmaster@marples.name