dhcp: T9278: move DHCP client hook tracing to a gated debug level

Each lease event emitted some fifteen daemon.info lines tracing internal steps
rather than recording a change. Add a "debug" level to logmsg(), silenced unless
/tmp/vyos.dhclient.debug exists, following the flag file convention used for FRR
and ifconfig. Demoting alone would not help, as journald shows all priorities by
default. Fifteen tracing messages move to debug; the sixteen recording an actual
change stay at info.

Also fix logmsg(): "warn" had no case arm although it is used, and the global
LOG_PRIO leaked the preceding call's priority. It is now local.

6 files changed, 41 insertions, 19 deletions

diff --git a/src/etc/dhcp/dhclient-enter-hooks.d/01-vyos-logging b/src/etc/dhcp/dhclient-enter-hooks.d/01-vyos-logging
index 121fb21be..01dd5f496 100644
--- a/src/etc/dhcp/dhclient-enter-hooks.d/01-vyos-logging
+++ b/src/etc/dhcp/dhclient-enter-hooks.d/01-vyos-logging
@@ -3,18 +3,39 @@ LOG_ENABLE="yes"
 LOG_STDERR="no"
 LOG_TAG="dhclient-script-vyos"
 
+# Tracing the individual steps of a lease event is only of interest while
+# debugging - it is silenced unless this flag file exists. Keep in sync with
+# "dhclient_debug_enable" in python/vyos/defaults.py, the file is created by
+# src/init/vyos-router when "vyos-debug" is present on the kernel command line.
+LOG_DEBUG_ENABLE="/tmp/vyos.dhclient.debug"
+
 function logmsg () {
     # log message to journal
-    case $1 in
+    local LOG_PRIO
+    local LOG_LEVEL=$1
+    shift
+
+    case ${LOG_LEVEL} in
+        debug)
+            # Do not even build the message when debugging is not requested
+            if [ ! -f "${LOG_DEBUG_ENABLE}" ] ; then
+                return 0
+            fi
+            LOG_PRIO="daemon.debug" ;;
+        info)  LOG_PRIO="daemon.info" ;;
+        warn)  LOG_PRIO="daemon.warning" ;;
         error) LOG_PRIO="daemon.err" ;;
-        info) LOG_PRIO="daemon.info" ;;
+        *)
+            # Unknown level - do not lose the message, it was never a level
+            LOG_PRIO="daemon.info"
+            set -- "${LOG_LEVEL}" "$@" ;;
     esac
 
     if [ "${LOG_ENABLE}" == "yes" ] ; then
         if [ "${LOG_STDERR}" == "yes" ] ; then
-            /usr/bin/logger -e --id=$$ -s -p ${LOG_PRIO} -t ${LOG_TAG} "${@:2}"
+            /usr/bin/logger -e --id=$$ -s -p ${LOG_PRIO} -t ${LOG_TAG} "$@"
         else
-            /usr/bin/logger -e --id=$$ -p ${LOG_PRIO} -t ${LOG_TAG} "${@:2}"
+            /usr/bin/logger -e --id=$$ -p ${LOG_PRIO} -t ${LOG_TAG} "$@"
         fi
     fi
 }
diff --git a/src/etc/dhcp/dhclient-enter-hooks.d/02-vyos-stopdhclient b/src/etc/dhcp/dhclient-enter-hooks.d/02-vyos-stopdhclient
index ae6bf9f16..2e92c0318 100644
--- a/src/etc/dhcp/dhclient-enter-hooks.d/02-vyos-stopdhclient
+++ b/src/etc/dhcp/dhclient-enter-hooks.d/02-vyos-stopdhclient
@@ -17,7 +17,7 @@ if [ -z ${CONTROLLED_STOP} ] ; then
         dhclients_pids=(`ps --no-headers --format pid,args -C dhclient | awk "{ if(match(\\$0, /\s${interface}(\s|$)/) && !match(\\$0, /\s-6\s/)) printf(\"%s\n\", \\$1) }"`)
     fi
 
-    logmsg info "Current dhclient PID: $current_dhclient, Parent PID: $master_dhclient, IP version: $ipversion_arg, All dhclients for interface $interface: ${dhclients_pids[@]}"
+    logmsg debug "Current dhclient PID: $current_dhclient, Parent PID: $master_dhclient, IP version: $ipversion_arg, All dhclients for interface $interface: ${dhclients_pids[@]}"
     # stop all dhclients for current interface, except current one
     for dhclient in ${dhclients_pids[@]}; do
         if ([ $dhclient -ne $current_dhclient ] && [ $dhclient -ne $master_dhclient ]); then
diff --git a/src/etc/dhcp/dhclient-enter-hooks.d/03-vyos-ipwrapper b/src/etc/dhcp/dhclient-enter-hooks.d/03-vyos-ipwrapper
index bd111d282..780af30ba 100644
--- a/src/etc/dhcp/dhclient-enter-hooks.d/03-vyos-ipwrapper
+++ b/src/etc/dhcp/dhclient-enter-hooks.d/03-vyos-ipwrapper
@@ -19,7 +19,7 @@ VRF_OPTION=$(/usr/sbin/ip --json --detail link show ${interface} | jq -r '.[0] |
 _flush_dhcp_addrs() {
     local dev="${1:-$interface}"
 
-    logmsg info "Selectively flushing only dynamic (DHCP) addresses from ${dev}"
+    logmsg debug "Selectively flushing only dynamic (DHCP) addresses from ${dev}"
 
     local addrs
     addrs=$(/usr/sbin/ip -4 -j addr show dev "${dev}" 2>&1 | jq -r '
@@ -47,10 +47,10 @@ _flush_dhcp_addrs() {
 function frr_alive () {
     /usr/lib/frr/watchfrr.sh all_status
     if [ "$?" -eq "0" ] ; then
-        logmsg info "FRR status: running"
+        logmsg debug "FRR status: running"
         return 0
     else
-        logmsg info "FRR status: not running"
+        logmsg debug "FRR status: not running"
         return 1
     fi
 }
@@ -97,12 +97,12 @@ function iptovtysh () {
     if [ "$VTYSH_ACTION" == "del" ] ; then
         VTYSH_CMD="no $VTYSH_CMD"
     fi
-    logmsg info "Converted vtysh command: \"$VTYSH_CMD\""
+    logmsg debug "Converted vtysh command: \"$VTYSH_CMD\""
 }
 
 # delete the same route from kernel before adding new one
 function delroute () {
-    logmsg info "Checking if the route presented in kernel: $@ $VRF_OPTION"
+    logmsg debug "Checking if the route presented in kernel: $@ $VRF_OPTION"
     if /usr/sbin/ip route show $@ $VRF_OPTION | grep -qx "$1 " ; then
         logmsg info "Deleting IP route: \"/usr/sbin/ip route del $@ $VRF_OPTION\""
         /usr/sbin/ip route del $@ $VRF_OPTION
@@ -114,10 +114,10 @@ function vtysh_conf () {
     # perform 10 attempts with 1 second delay for retries
     for i in {1..10} ; do
         if vtysh  -c "conf t" -c "$1" ; then
-            logmsg info "Command was executed successfully via vtysh: \"$1\""
+            logmsg debug "Command was executed successfully via vtysh: \"$1\""
             return 0
         else
-            logmsg info "Failed to send command to vtysh, retrying in 1 second"
+            logmsg warn "Failed to send command to vtysh, retrying in 1 second"
             sleep 1
         fi
     done
@@ -130,7 +130,7 @@ function ip () {
     # Intercept: ip -4 addr flush dev <interface>
     # to preserve static addresses (only remove dynamic/DHCP addresses)
     if [ "$1" = "-4" ] && [ "$2" = "addr" ] && [ "$3" = "flush" ]; then
-        logmsg info "Intercepting 'ip -4 addr flush' to preserve static addresses"
+        logmsg debug "Intercepting 'ip -4 addr flush' to preserve static addresses"
         shift 3
         local dev=""
         while [ $# -gt 0 ]; do
@@ -143,14 +143,14 @@ function ip () {
 
     # pass command to system `ip` if this is not related to routes change
     if [ "$2" != "route" ] ; then
-        logmsg info "Passing command to /usr/sbin/ip: \"$@\""
+        logmsg debug "Passing command to /usr/sbin/ip: \"$@\""
         /usr/sbin/ip $@
     else
         # if we want to work with routes, try to use FRR first
         if frr_alive ; then
             delroute ${@:4}
             iptovtysh $@
-            logmsg info "Sending command to vtysh"
+            logmsg debug "Sending command to vtysh"
             vtysh_conf "$VTYSH_CMD"
         else
             # add ip route to kernel
diff --git a/src/etc/dhcp/dhclient-enter-hooks.d/04-vyos-resolvconf b/src/etc/dhcp/dhclient-enter-hooks.d/04-vyos-resolvconf
index 9a8a53bfd..9aa3a725c 100644
--- a/src/etc/dhcp/dhclient-enter-hooks.d/04-vyos-resolvconf
+++ b/src/etc/dhcp/dhclient-enter-hooks.d/04-vyos-resolvconf
@@ -23,10 +23,10 @@ if /usr/bin/systemctl -q is-active vyos-hostsd; then
         fi
 
         if [ $hostsd_changes ]; then
-            logmsg info "Applying changes via vyos-hostsd-client"
+            logmsg debug "Applying changes via vyos-hostsd-client"
             $hostsd_client --apply
         else
-            logmsg info "No changes to apply via vyos-hostsd-client"
+            logmsg debug "No changes to apply via vyos-hostsd-client"
         fi
     }
 fi
diff --git a/src/etc/dhcp/dhclient-exit-hooks.d/01-vyos-cleanup b/src/etc/dhcp/dhclient-exit-hooks.d/01-vyos-cleanup
index da1bda137..803940ecc 100644
--- a/src/etc/dhcp/dhclient-exit-hooks.d/01-vyos-cleanup
+++ b/src/etc/dhcp/dhclient-exit-hooks.d/01-vyos-cleanup
@@ -108,8 +108,8 @@ if [[ $reason =~ ^(EXPIRE6|RELEASE6|STOP6)$ ]]; then
 fi
 
 if [ $hostsd_changes ]; then
-    logmsg info "Applying changes via vyos-hostsd-client"
+    logmsg debug "Applying changes via vyos-hostsd-client"
     $hostsd_client --apply
 else
-    logmsg info "No changes to apply via vyos-hostsd-client"
+    logmsg debug "No changes to apply via vyos-hostsd-client"
 fi
diff --git a/src/init/vyos-router b/src/init/vyos-router
index 8e0a671a6..8e270602e 100755
--- a/src/init/vyos-router
+++ b/src/init/vyos-router
@@ -590,6 +590,7 @@ start ()
         touch /tmp/vyos.ifconfig.debug
         touch /tmp/vyos.container.debug
         touch /tmp/vyos.smoketest.debug
+        touch /tmp/vyos.dhclient.debug
     fi
 
     # Cleanup PKI CAs