Modify sqm's logging to allow enable debug logging by default (#99)

* Modify sqm's logging to allow enable debug logging by default

Instead of the old continously growing log approach, this switches to
one log file each for start-sqm and stop-sqm. This allows to truncate
each log at the start of each of the two scripts, so that effectively
for each interface with an sqm instance there will be a log for the
most recent start-sqm and stop-sqm instance. Unlike the old growing log
this does not risk to fill up /varrun with its verbosity, and
more importantly allows to enable SQM_DEBUG by default to that for
every issue encountered in the field we will be able to get to
a log file from eactly the failed instance (unless users manually
disable this).

Signed-off-by: Sebastian Moeller <moeller0@gmx.de>
[ squash into one commit ]
Signed-off-by: Toke Høiland-Jørgensen <toke@toke.dk>

luci/sqm-cbi.lua

@@ -85,7 +85,7 @@ ul = s:taboption("tab_basic", Value, "upload", translate("Upload speed (kbit/s)
 ul.datatype = "and(uinteger,min(0))"
 ul.rmempty = false
 
-dbl = s:taboption("tab_basic", Flag, "debug_logging", translate("Create log file for this SQM instance under /var/run/sqm/${Interface_name}.debug.log. Make sure to delete log files manually."))
+dbl = s:taboption("tab_basic", Flag, "debug_logging", translate("Create log file for this SQM instance under /var/run/sqm/${Interface_name}.[start|stop]-sqm.log."))
 dbl.rmempty = false
 
 

src/defaults.sh

@@ -79,8 +79,11 @@ VERBOSITY_TRACE=10
 [ -z "$SQM_DEBUG" ] && SQM_DEBUG=0
 if [ "$SQM_DEBUG" -eq "1" ]
 then
-    SQM_DEBUG_LOG=${SQM_STATE_DIR}/${IFACE}.debug.log
-    OUTPUT_TARGET=${SQM_DEBUG_LOG}
+    SQM_DEBUG_STEM="${SQM_STATE_DIR}/${IFACE}"
+    SQM_START_LOG="${SQM_DEBUG_STEM}.start-sqm.log"
+    SQM_STOP_LOG="${SQM_DEBUG_STEM}.stop-sqm.log"
+    [ -z "SQM_DEBUG_LOG" ] &&  SQM_DEBUG_LOG="${SQM_DEBUG_STEM}.debug.log"
+    OUTPUT_TARGET="${SQM_DEBUG_LOG}"
 else
     OUTPUT_TARGET="/dev/null"
 fi
@@ -91,7 +94,7 @@ fi
 SILENT=0
 
 # Transaction log for unwinding ipt rules
-IPT_TRANS_LOG=${SQM_STATE_DIR}/${IFACE}.iptables.log
+IPT_TRANS_LOG="${SQM_STATE_DIR}/${IFACE}.iptables.log"
 
 # These are the modules that do_modules() will attempt to load
 ALL_MODULES="act_ipt sch_$QDISC sch_ingress act_mirred cls_fw cls_flow cls_u32 sch_htb sch_hfsc"

src/functions.sh

@@ -50,11 +50,11 @@ sqm_logger() {
             echo "$@" >&2
         fi
     fi
-    # slightly dangerous as this will keep adding to the log file
+    
+    # this writes into SQM_START_LOG or SQM_STOP_LOG, log files are trucated in 
+    # start-sqm/stop-sqm respectively and should only take little space
     if [ "$debug" -eq "1" ]; then
-        if [ "$level_max" -ge "$LEVEL" -o "$LEVEL" -eq "$VERBOSITY_TRACE" ]; then
-            echo "$@" >> ${SQM_DEBUG_LOG}
-        fi
+        echo "$@" >> "${SQM_DEBUG_LOG}"
     fi
 }
 
@@ -175,17 +175,16 @@ cmd_wrapper(){
     ERRLOG="sqm_error"
     if [ "$SILENT" -eq "1" ]; then
         ERRLOG="sqm_debug"
-        sqm_debug "cmd_wrapper: ${CALLERID}: invocation silenced by request, failure either expected or acceptable."
+        sqm_debug "cmd_wrapper: ${CALLERID}: invocation silenced by request, FAILURE either expected or acceptable."
         # The busybox shell doesn't understand the concept of an inline variable
         # only applying to a single command, so we need to reset SILENT
         # afterwards. Ugly, but it works...
         SILENT=0
     fi
 
-    sqm_trace "${CMD_BINARY} $@"
+    sqm_trace "cmd_wrapper: COMMAND: ${CMD_BINARY} $@"
     LAST_ERROR=$( ${CMD_BINARY} "$@" 2>&1 )
     RET=$?
-    sqm_trace "${LAST_ERROR}"
 
     if [ "$RET" -eq "0" ] ; then
         sqm_debug "cmd_wrapper: ${CALLERID}: SUCCESS: ${CMD_BINARY} $@"
@@ -503,9 +502,9 @@ sqm_start_default() {
 
 
 sqm_stop() {
-    $TC qdisc del dev $IFACE ingress #2>> ${OUTPUT_TARGET}
-    $TC qdisc del dev $IFACE root #2>> ${OUTPUT_TARGET}
-    [ -n "$CUR_IFB" ] && $TC qdisc del dev $CUR_IFB root #2>> ${OUTPUT_TARGET}
+    $TC qdisc del dev $IFACE ingress
+    $TC qdisc del dev $IFACE root
+    [ -n "$CUR_IFB" ] && $TC qdisc del dev $CUR_IFB root
     [ -n "$CUR_IFB" ] && sqm_debug "${0}: ${CUR_IFB} shaper deleted"
 
     # undo accumulated ipt commands during shutdown
@@ -515,9 +514,9 @@ sqm_stop() {
     [ -n "$CUR_IFB" ] && $IP link delete ${CUR_IFB} type ifb
     [ -n "$CUR_IFB" ] && sqm_debug "${0}: ${CUR_IFB} interface deleted"
 }
+
 # Note this has side effects on the prio variable
 # and depends on the interface global too
-
 fc() {
     $TC filter add dev $interface protocol ip parent $1 prio $prio u32 match ip tos $2 0xfc classid $3
     prio=$(($prio + 1))

src/start-sqm

@@ -16,6 +16,13 @@ STATE_FILE="${SQM_STATE_DIR}/${IFACE}.state"
 
 check_state_dir
 
+# log file for the most recent sqm instance start
+if [ "$SQM_DEBUG" -eq "1" ] ; then
+    SQM_DEBUG_LOG="${SQM_START_LOG}"
+    OUTPUT_TARGET="${SQM_DEBUG_LOG}"
+    echo "start-sqm: Log for interface ${IFACE}: $(date)"  > "${OUTPUT_TARGET}"
+fi
+
 if [ -z "${SCRIPT}" ] ; then
     sqm_error "SCRIPT value is not defined in /etc/sqm/${IFACE}.iface.conf"
     sqm_error "Please check your configuration and try again."

src/stop-sqm

@@ -15,6 +15,13 @@
 . ${SQM_LIB_DIR}/defaults.sh
 
 check_state_dir
+# log file for the most recent sqm instance stop
+if [ "$SQM_DEBUG" -eq "1" ] ; then
+    SQM_DEBUG_LOG="${SQM_STOP_LOG}"
+    OUTPUT_TARGET="${SQM_DEBUG_LOG}"
+    echo "stop-sqm: Log for interface ${IFACE}: $(date)"  > "${OUTPUT_TARGET}"
+fi
+
 if [ ! -f "${SQM_STATE_DIR}/${IFACE}.state" ] ; then
     sqm_error "State file does not exist; SQM was not running on interface ${IFACE}"
     exit 1