log: remove Trace,Warn,Crit levels

This is a BREAKING CHANGE, because logging infrastructure might need to
re-evaluate scripts/alerting/logging levels in configs, etc. also this commit
removes the logdog tool.

All Trace logs are converted to Debug.
All Crit logs are converted to Error.
All Warn logs are converted to Info.

Having more than those remaining 3 levels is not really needed:
- debug: Contains low level details for developers.
- info: Contains general information about the process, failures that
  happen as part of normal operation are also logged at this level.
- error: Contains unexpected errors that lead to mal-functioning of the
  system in severe cases the application may choose to exit after an
  error log.

This PR also removes logdog since that was a tool that was seldomly used
and is strictly tied to the log format we have now, the format might
change in the future.

The new recommended logging level for production is info.

Further audits are needed of what we need to log at info level instead
of debug/error.

Fixes scionproto#3595

.buildkite/pipeline.yml

@@ -92,7 +92,7 @@ steps:
       - bazel build //:scion //:scion-ci >/dev/null 2>&1
       - tar -xf bazel-bin/scion.tar -C bin --overwrite
       - tar -xf bazel-bin/scion-ci.tar -C bin --overwrite
-      - ./scion.sh topology -t
+      - ./scion.sh topology
       - ./scion.sh run && sleep 10
       - ./bin/end2end_integration -log.console warn
       - ./integration/revocation_test.sh
@@ -115,7 +115,7 @@ steps:
     - bazel build //:scion //:scion-ci >/dev/null 2>&1
     - tar -xf bazel-bin/scion.tar -C bin --overwrite
     - tar -xf bazel-bin/scion-ci.tar -C bin --overwrite
-    - ./scion.sh topology -t
+    - ./scion.sh topology
     - ./scion.sh run && sleep 10
     - ./bin/pp_integration -log.console warn
     - ./bin/scmp_integration -log.console warn
@@ -137,7 +137,7 @@ steps:
   - label: ":docker: Integration: end2end_integration"
     if: build.message !~ /\[doc\]/
     command:
-    - ./scion.sh topology -t -d -c topology/tiny.topo
+    - ./scion.sh topology -d -c topology/tiny.topo
     - ./scion.sh run
     - docker-compose -f gen/scion-dc.yml -p scion up -d $(docker-compose -f gen/scion-dc.yml config --services | grep tester)
     - sleep 10
@@ -161,7 +161,7 @@ steps:
   - label: ":docker: Integration: end2end_integration full topology"
     if: build.message !~ /\[doc\]/
     command:
-    - ./scion.sh topology -t -d
+    - ./scion.sh topology -d
     - ./scion.sh run
     - docker-compose -f gen/scion-dc.yml -p scion up -d $(docker-compose -f gen/scion-dc.yml config --services | grep tester)
     - sleep 10

BUILD.bazel

@@ -17,7 +17,6 @@ pkg_tar(
         "//go/scion-pki",
         "//go/sciond",
         "//go/sig",
-        "//go/tools/logdog",
         "//go/tools/pathdb_dump",
         "//go/tools/scmp",
         "//go/tools/showpaths",

acceptance/common/README.md

@@ -77,7 +77,7 @@ class TestSetup(CmdBase):
         # Create the tiny topology/
         self.scion.topology('topology/tiny.topo')
         # Modify the logging config for all beacon servers
-        self.scion.set_configs({'log.file.level': 'trace'},
+        self.scion.set_configs({'log.file.level': 'debug'},
                                local.path('gen/ISD1') // '*/bs*/bs.toml')
         # Run the scion topology.
         self.scion.run()

acceptance/common/scion.py

@@ -99,11 +99,11 @@ def set_configs(change_dict: Dict[str, Any], files: LocalPath):
         """
         Overwrite or set the values in the toml files with the specified
         changes. The key in the change dictionary is a dot separated path
-        to the toml value. E.g. {'log.file.level': 'trace'} result in the
+        to the toml value. E.g. {'log.file.level': 'debug'} result in the
         toml file with the following set:
 
         [log.file]
-          level = "trace"
+          level = "debug"
         """
         for f in files:
             t = toml.load(f)
@@ -122,7 +122,7 @@ class SCIONDocker(SCION):
     @LogExec(logger, "creating dockerized topology")
     def topology(self, topo_file: str, *args: str):
         """ Create the dockerized topology files. """
-        self.scion_sh('topology', '-c', topo_file, '-t', '-d', *args)
+        self.scion_sh('topology', '-c', topo_file, '-d', *args)
 
     def execute(self, isd_as: ISD_AS, cmd: str, *args: str) -> str:
         expanded = []

acceptance/reconnecting_acceptance/test

@@ -11,7 +11,7 @@ TEST_TOPOLOGY="topology/tiny.topo"
 
 test_setup() {
     set -e
-    ./scion.sh topology -c $TEST_TOPOLOGY -d -t
+    ./scion.sh topology -c $TEST_TOPOLOGY -d
     ./scion.sh run nobuild
     ./tools/dc start tester_1-ff00_0_112 tester_1-ff00_0_110
     docker_status

acceptance/sig_failover/testdata/1-ff00_0_110/dispatcher/disp.toml

@@ -5,5 +5,5 @@ id = "disp_1-ff00_0_110"
 allow_run_as_root = true
 
 [log.file]
-level = "trace"
+level = "debug"
 path = "/share/logs/disp_1-ff00_0_110.log"

acceptance/sig_failover/testdata/1-ff00_0_110/sig/sig.toml

@@ -12,5 +12,5 @@ fake_data = "/fake_sciond.json"
 
 [log.file]
 flush_interval = 1
-level = "trace"
+level = "debug"
 path = "/share/logs/sig1-ff00_0_110.log"

acceptance/sig_failover/testdata/1-ff00_0_111/dispatcher/disp.toml

@@ -5,5 +5,5 @@ id = "disp_1-ff00_0_111"
 allow_run_as_root = true
 
 [log.file]
-level = "trace"
+level = "debug"
 path = "/share/logs/disp_1-ff00_0_111.log"

acceptance/sig_failover/testdata/1-ff00_0_111/sig/sig.toml

@@ -12,5 +12,5 @@ fake_data = "/fake_sciond.json"
 
 [log.file]
 flush_interval = 1
-level = "trace"
+level = "debug"
 path = "/share/logs/sig1-ff00_0_111.log"

acceptance/sig_short_exp_time/testdata/1-ff00_0_110/dispatcher/disp.toml

@@ -5,5 +5,5 @@ id = "disp_1-ff00_0_110"
 allow_run_as_root = true
 
 [log.file]
-level = "trace"
+level = "debug"
 path = "/share/logs/disp_1-ff00_0_110.log"

acceptance/sig_short_exp_time/testdata/1-ff00_0_110/sig/sig.toml

@@ -12,5 +12,5 @@ fake_data = "/fake_sciond.json"
 
 [log.file]
 flush_interval = 1
-level = "trace"
+level = "debug"
 path = "/share/logs/sig1-ff00_0_110.log"

acceptance/sig_short_exp_time/testdata/1-ff00_0_111/dispatcher/disp.toml

@@ -5,5 +5,5 @@ id = "disp_1-ff00_0_111"
 allow_run_as_root = true
 
 [log.file]
-level = "trace"
+level = "debug"
 path = "/share/logs/disp_1-ff00_0_111.log"

acceptance/sig_short_exp_time/testdata/1-ff00_0_111/sig/sig.toml

@@ -12,5 +12,5 @@ fake_data = "/fake_sciond.json"
 
 [log.file]
 flush_interval = 1
-level = "trace"
+level = "debug"
 path = "/share/logs/sig1-ff00_0_111.log"

acceptance/sigutil/common.sh

@@ -8,7 +8,7 @@ DST_IA=${DST_IA:-1-ff00:0:112}
 
 test_setup() {
     set -e
-    ./scion.sh topology -c $TEST_TOPOLOGY -d -t --sig -n 242.254.0.0/16
+    ./scion.sh topology -c $TEST_TOPOLOGY -d --sig -n 242.254.0.0/16
     for sig in gen/ISD1/*/sig*/sig.toml; do
         sed -i '/\[log\.file\]/a flush_interval = 1' "$sig"
     done

acceptance/topo_br_reload_util/util.sh

@@ -31,7 +31,7 @@ base_setup() {
 }
 
 base_gen_topo() {
-    ./scion.sh topology -c $TEST_TOPOLOGY -d -t
+    ./scion.sh topology -c $TEST_TOPOLOGY -d
     sed -i '/\[log\.file\]/a flush_interval = 1' gen/ISD1/*/br*/br.toml
 }
 

acceptance/topo_cs_reload/testdata/cs.toml

@@ -10,7 +10,7 @@ connection = "cs1-ff00_0_110-1.trust.db"
 connection = "cs1-ff00_0_110-1.renewal.db"
 
 [log.console]
-level = "trace"
+level = "debug"
 
 [path_db]
 connection = "cs1-ff00_0_110-1.path.db"

acceptance/topo_cs_reload/testdata/disp.toml

@@ -5,4 +5,4 @@ id = "disp_1-ff00_0_110"
 allow_run_as_root = true
 
 [log.console]
-level = "trace"
+level = "debug"

acceptance/topo_cs_reload/testdata/sd.toml

@@ -7,7 +7,7 @@ id = "sd1-ff00_0_110"
 connection = "sd1-ff00_0_110.trust.db"
 
 [log.console]
-level = "trace"
+level = "debug"
 
 [sd]
 address = "242.253.100.3:30255"

acceptance/topo_sd_reload/testdata/disp.toml

@@ -5,4 +5,4 @@ id = "disp_1-ff00_0_110"
 allow_run_as_root = true
 
 [log.console]
-level = "trace"
+level = "debug"

acceptance/topo_sd_reload/testdata/sd.toml

@@ -7,7 +7,7 @@ id = "sd1-ff00_0_110"
 connection = "sd1-ff00_0_110.trust.db"
 
 [log.console]
-level = "trace"
+level = "debug"
 
 [sd]
 address = "[242.254.100.2]:0"

go/acceptance/sig_ping_acceptance/main.go

@@ -49,11 +49,11 @@ func realMain() int {
 	defer log.HandlePanic()
 	defer log.Flush()
 	if !*integration.Docker {
-		log.Crit(fmt.Sprintf("Can only run %s test with docker!", name))
+		log.Error(fmt.Sprintf("Can only run %s test with docker!", name))
 		return 1
 	}
 	if err := acceptance.ReadTestingConf(); err != nil {
-		log.Crit(fmt.Sprintf("Error reading testing conf: %s", err))
+		log.Error("Testing conf reading failed", "err", err)
 		return 1
 	}
 	args := []string{cmd, "-c", strconv.Itoa(*attempts), "-O", integration.DstHostReplace}

go/border/braccept/main.go

@@ -49,8 +49,7 @@ var (
 func init() {
 	flag.StringVar(&testName, "testName", "", "Test to run")
 	flag.StringVar(&keysDirPath, "keysDirPath", "", "AS keys directory path")
-	flag.StringVar(&logConsole, "log.console", "info",
-		"Console logging level: trace|debug|info|warn|error|crit")
+	flag.StringVar(&logConsole, "log.console", "info", "Console logging level: debug|info|error")
 }
 
 var (
@@ -77,7 +76,7 @@ func realMain() int {
 	}
 	defer log.HandlePanic()
 	if err := shared.Init(keysDirPath); err != nil {
-		log.Crit("Initialization failed", "err", err)
+		log.Error("Initialization failed", "err", err)
 		return 1
 	}
 	// We setup the select cases in main so we can easily defer device handle close on exit
@@ -87,7 +86,7 @@ func realMain() int {
 		var err error
 		di.Handle, err = afpacket.NewTPacket(afpacket.OptInterface(di.Host.Name))
 		if err != nil {
-			log.Crit("Error creating packet", "err", err)
+			log.Error("Packet creation failed", "err", err)
 			return 1
 		}
 		packetSource := gopacket.NewPacketSource(di.Handle, golayers.LinkTypeEthernet)
@@ -98,7 +97,7 @@ func realMain() int {
 	// Now that everything is set up, drop CAP_NET_ADMIN
 	caps, err := capability.NewPid(0)
 	if err != nil {
-		log.Crit("Error retrieving capabilities", "err", err)
+		log.Error("Retrieving capabilities failed", "err", err)
 		return 1
 	}
 	caps.Clear(capability.CAPS)
@@ -126,7 +125,7 @@ func realMain() int {
 	case "br_core_childIf":
 		failures += br_core_childIf()
 	default:
-		log.Crit("Wrong BR acceptance test name", "testName", testName)
+		log.Error("Wrong BR acceptance test name", "testName", testName)
 		return 1
 	}
 	return failures

go/border/ifstate/ifstate.go

@@ -111,7 +111,7 @@ func Process(ifStates *path_mgmt.IFStateInfos) {
 		}
 		intf, ok := ctx.Conf.Topo.IFInfoMap()[ifid]
 		if !ok {
-			log.Warn("Interface ID does not exist", "ifid", ifid)
+			log.Info("Interface ID does not exist", "ifid", ifid)
 			continue
 		}
 		stateInfo := NewInfo(ifid, intf.IA, info.Active, info.SRevInfo, rawSRev)

go/border/main.go

@@ -74,16 +74,16 @@ func realMain() int {
 	http.HandleFunc("/status", statusHandler)
 	http.HandleFunc("/topology", itopo.TopologyHandler)
 	if err := setup(); err != nil {
-		log.Crit("Setup failed", "err", err)
+		log.Error("Setup failed", "err", err)
 		return 1
 	}
 	if err := checkPerms(); err != nil {
-		log.Crit("Permissions checks failed", "err", err)
+		log.Error("Permissions checks failed", "err", err)
 		return 1
 	}
 	var err error
 	if r, err = NewRouter(cfg.General.ID, cfg.General.ConfigDir); err != nil {
-		log.Crit("Startup failed", "err", err)
+		log.Error("Startup failed", "err", err)
 		return 1
 	}
 	if assert.On {

go/border/rpkt/path.go

@@ -108,12 +108,12 @@ func (rp *RtrPkt) validateLocalIF(ifid *common.IFIDType) error {
 	// Interface is revoked.
 	sRevInfo := state.SRevInfo
 	if sRevInfo == nil {
-		rp.Warn("No SRevInfo for revoked interface", "ifid", *ifid)
+		rp.Info("No SRevInfo for revoked interface", "ifid", *ifid)
 		return nil
 	}
 	revInfo, err := sRevInfo.RevInfo()
 	if err != nil {
-		rp.Warn("Could not parse RevInfo for interface", "ifid", *ifid, "err", err)
+		rp.Info("Could not parse RevInfo for interface", "ifid", *ifid, "err", err)
 		return nil
 	}
 	err = revInfo.Active()

go/border/rpkt/rpkt.go

@@ -344,7 +344,7 @@ func (rp *RtrPkt) GetRaw(blk scmp.RawBlock) common.RawBytes {
 		}
 		return rp.Raw[rp.idxs.l4:end]
 	}
-	rp.Crit("Invalid raw block requested", "blk", blk)
+	rp.Error("Invalid raw block requested", "blk", blk)
 	return nil
 }
 

go/border/setup-posix.go

@@ -46,7 +46,7 @@ func (p posixLoc) Setup(r *Router, ctx *rctx.Ctx, oldCtx *rctx.Ctx) error {
 	if oldCtx != nil {
 		// The socket can be reused if the local address does not change.
 		if ctx.Conf.BR.InternalAddr.String() == oldCtx.Conf.BR.InternalAddr.String() {
-			log.Trace("No change detected for local socket.")
+			log.Debug("No change detected for local socket.")
 			// Nothing changed. Copy I/O functions from old context.
 			ctx.LocSockIn = oldCtx.LocSockIn
 			ctx.LocSockOut = oldCtx.LocSockOut
@@ -112,7 +112,7 @@ func (p posixExt) Setup(r *Router, ctx *rctx.Ctx, intf *topology.IFInfo, oldCtx
 	if oldIntf, ok := oldCtx.Conf.BR.IFs[intf.ID]; ok {
 		// Reuse socket if the interface has not changed.
 		if !interfaceChanged(intf, oldIntf) {
-			log.Trace("No change detected for external socket.", "conn", intf.Local)
+			log.Debug("No change detected for external socket.", "conn", intf.Local)
 			ctx.ExtSockIn[intf.ID] = oldCtx.ExtSockIn[intf.ID]
 			ctx.ExtSockOut[intf.ID] = oldCtx.ExtSockOut[intf.ID]
 			return nil

go/border/setup.go

@@ -156,7 +156,7 @@ func (r *Router) setupCtxFromTopoUpdate(tx itopo.Transaction, err error) (bool,
 	if !tx.IsUpdate() {
 		return false, nil
 	}
-	log.Trace("====> Setting up new context from topology update")
+	log.Debug("====> Setting up new context from topology update")
 	newConf, err := brconf.WithNewTopo(r.Id, tx.Get(), rctx.Get().Conf)
 	if err != nil {
 		return false, err
@@ -273,7 +273,7 @@ func handleRollbackErr(err error) {
 	if cfg.BR.RollbackFailAction != brconf.FailActionContinue {
 		fatal.Fatal(err)
 	}
-	log.Crit("Error in rollback", "err", err)
+	log.Error("Rollback failed", "err", err)
 }
 
 // validateCtx ensures that the socket type of existing sockets does not change

go/cs/beaconing/handler.go

@@ -95,15 +95,15 @@ func (h *handler) handle(logger log.Logger) (*infra.HandlerResult, error) {
 		metrics.Beaconing.Received(labels.WithResult(metrics.ErrParse)).Inc()
 		return res, err
 	}
-	logger.Trace("[BeaconHandler] Received", "beacon", b)
+	logger.Debug("[BeaconHandler] Received", "beacon", b)
 	if err := h.inserter.PreFilter(b); err != nil {
-		logger.Trace("[BeaconHandler] Beacon pre-filtered", "err", err)
+		logger.Debug("[BeaconHandler] Beacon pre-filtered", "err", err)
 		metrics.Beaconing.Received(labels.WithResult(metrics.ErrPrefilter)).Inc()
 		sendAck(proto.Ack_ErrCode_reject, messenger.AckRejectPolicyError)
 		return infra.MetricsErrInvalid, nil
 	}
 	if err := h.verifyBeacon(b); err != nil {
-		logger.Trace("[BeaconHandler] Beacon verification", "err", err)
+		logger.Debug("[BeaconHandler] Beacon verification", "err", err)
 		metrics.Beaconing.Received(labels.WithResult(metrics.ErrVerify)).Inc()
 		sendAck(proto.Ack_ErrCode_reject, messenger.AckRejectFailedToVerify)
 		return infra.MetricsErrInvalid, err
@@ -114,7 +114,7 @@ func (h *handler) handle(logger log.Logger) (*infra.HandlerResult, error) {
 		sendAck(proto.Ack_ErrCode_reject, messenger.AckRetryDBError)
 		return infra.MetricsErrInternal, common.NewBasicError("Unable to insert beacon", err)
 	}
-	logger.Trace("[BeaconHandler] Successfully inserted", "beacon", b)
+	logger.Debug("[BeaconHandler] Successfully inserted", "beacon", b)
 	metrics.Beaconing.Received(labels.WithResult(
 		metrics.GetResultValue(stat.Inserted, stat.Updated, stat.Filtered))).Inc()
 	sendAck(proto.Ack_ErrCode_ok, "")

go/cs/beaconing/propagator.go

@@ -236,7 +236,7 @@ func (p *beaconPropagator) propagate(ctx context.Context) error {
 	}
 	p.summary.AddSrc(p.beacon.Segment.FirstIA())
 	p.summary.Inc()
-	p.logger.Trace("[beaconing.Propagator] Successfully propagated", "beacon", p.beacon,
+	p.logger.Debug("[beaconing.Propagator] Successfully propagated", "beacon", p.beacon,
 		"expected", expected, "count", p.success.c)
 	return nil
 }
@@ -306,7 +306,7 @@ func (p *beaconPropagator) shouldIgnore(bseg beacon.Beacon, egIfid common.IFIDTy
 		return true
 	}
 	if err := beacon.FilterLoop(bseg, intf.TopoInfo().IA, p.allowIsdLoop); err != nil {
-		p.logger.Trace("[beaconing.Propagator] Ignoring beacon on loop", "ifid", egIfid, "err", err)
+		p.logger.Debug("[beaconing.Propagator] Ignoring beacon on loop", "ifid", egIfid, "err", err)
 		return true
 	}
 	return false