From de85995eed0d671f500b335267c46e3a69edfbce Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Mon, 13 Jan 2025 21:08:11 +0000 Subject: [PATCH 01/12] log: switch to slog --- dv/executor/main.go | 4 - fw/core/config.go | 2 +- fw/core/logger.go | 65 ++++------ fw/executor/main.go | 2 +- fw/executor/profiler.go | 6 +- fw/executor/yanfd.go | 29 +++-- fw/face/ndnlp-link-service.go | 2 +- fw/face/table.go | 4 +- fw/face/tcp-listener.go | 2 +- fw/face/udp-listener.go | 2 +- fw/face/unicast-tcp-transport.go | 2 +- fw/face/unix-stream-listener.go | 4 +- fw/face/web-socket-listener.go | 4 +- fw/face/web-socket-transport.go | 12 +- fw/fw/thread.go | 6 +- fw/mgmt/cs.go | 6 +- fw/mgmt/face.go | 20 +-- fw/mgmt/fib.go | 4 +- fw/mgmt/nlsr_readvertiser.go | 8 +- fw/mgmt/rib.go | 10 +- fw/mgmt/strategy-choice.go | 4 +- fw/mgmt/thread.go | 4 +- std/engine/basic/engine.go | 75 +++++------ std/examples/low-level/svs/main.go | 17 +-- std/log/LICENSE | 24 ---- std/log/default.go | 75 +++++++++++ std/log/entry.go | 194 ----------------------------- std/log/entry_test.go | 73 ----------- std/log/interface.go | 22 ---- std/log/level.go | 49 ++++++++ std/log/levels.go | 84 ------------- std/log/levels_test.go | 60 --------- std/log/logger.go | 156 ----------------------- std/log/pkg.go | 151 ---------------------- std/log/slog.go | 116 +++++++++++++++++ std/log/text.go | 77 ------------ tools/catchunks.go | 2 - tools/pingclient.go | 2 - tools/pingserver.go | 2 - tools/putchunks.go | 2 - 40 files changed, 368 insertions(+), 1015 deletions(-) delete mode 100644 std/log/LICENSE create mode 100644 std/log/default.go delete mode 100644 std/log/entry.go delete mode 100644 std/log/entry_test.go delete mode 100644 std/log/interface.go create mode 100644 std/log/level.go delete mode 100644 std/log/levels.go delete mode 100644 std/log/levels_test.go delete mode 100644 std/log/logger.go delete mode 100644 std/log/pkg.go create mode 100644 std/log/slog.go delete mode 100644 std/log/text.go diff --git a/dv/executor/main.go b/dv/executor/main.go index eaa5bdc8..9f9ceb60 100644 --- a/dv/executor/main.go +++ b/dv/executor/main.go @@ -7,8 +7,6 @@ import ( "syscall" "github.com/goccy/go-yaml" - - "github.com/named-data/ndnd/std/log" ) func Main(args []string) { @@ -29,8 +27,6 @@ func Main(args []string) { os.Exit(3) } - log.SetLevel(log.InfoLevel) - dve, err := NewDvExecutor(dc) if err != nil { panic(err) diff --git a/fw/core/config.go b/fw/core/config.go index d96d2902..89e06d75 100644 --- a/fw/core/config.go +++ b/fw/core/config.go @@ -189,7 +189,7 @@ func DefaultConfig() *Config { func LoadConfig(cfg *Config, basedir string) { if cfg == nil { - LogFatal("Config", "Config is nil") + panic("config is nil") } config = cfg baseDir = basedir diff --git a/fw/core/logger.go b/fw/core/logger.go index d4475b0f..e0a2f631 100644 --- a/fw/core/logger.go +++ b/fw/core/logger.go @@ -16,41 +16,35 @@ import ( "github.com/named-data/ndnd/std/log" ) -var shouldPrintTraceLogs = false -var logLevel log.Level +var Log = log.Default() var logFileObj *os.File -// InitializeLogger initializes the logger. -func InitializeLogger(logFile string) { - if logFile == "" { - log.SetHandler(log.NewText(os.Stdout)) +// OpenLogger initializes the logger. +func OpenLogger(filename string) { + // open file if filename is not empty + if filename == "" { + logFileObj = os.Stderr } else { var err error - logFileObj, err = os.Create(logFile) + logFileObj, err = os.Create(filename) if err != nil { - os.Exit(1) + panic(err) } - log.SetHandler(log.NewText(logFileObj)) } - logLevelString := GetConfig().Core.LogLevel + // create new logger + Log = log.NewText(logFileObj) - var err error - logLevel, err = log.ParseLevel(logLevelString) - if err == nil { - log.SetLevel(logLevel) - } else if logLevelString == "TRACE" { - // Apex doesn't support the TRACE level, so we have to work around that by calling them DEBUG, - // but not printing them if not TRACE - log.SetLevel(log.DebugLevel) - shouldPrintTraceLogs = true - } else { - log.SetLevel(log.InfoLevel) + // set log level + level, err := log.ParseLevel(GetConfig().Core.LogLevel) + if err != nil { + panic(err) } + Log.SetLevel(level) } // ShutdownLogger shuts down the logger. -func ShutdownLogger() { +func CloseLogger() { if logFileObj != nil { logFileObj.Close() } @@ -98,42 +92,25 @@ func generateLogMessage(module interface{}, components ...interface{}) string { // LogFatal logs a message at the FATAL level. Note: Fatal will let the program exit func LogFatal(module interface{}, components ...interface{}) { - if logLevel <= log.FatalLevel { - log.Fatal(generateLogMessage(module, components...)) - } + log.Fatal(generateLogMessage(module, components...)) } // LogError logs a message at the ERROR level. func LogError(module interface{}, components ...interface{}) { - if logLevel <= log.ErrorLevel { - log.Error(generateLogMessage(module, components...)) - } + log.Error(generateLogMessage(module, components...)) } // LogWarn logs a message at the WARN level. func LogWarn(module interface{}, components ...interface{}) { - if logLevel <= log.WarnLevel { - log.Warn(generateLogMessage(module, components...)) - } -} - -// LogInfo logs a message at the INFO level. -func LogInfo(module interface{}, components ...interface{}) { - if logLevel <= log.InfoLevel { - log.Info(generateLogMessage(module, components...)) - } + log.Warn(generateLogMessage(module, components...)) } // LogDebug logs a message at the DEBUG level. func LogDebug(module interface{}, components ...interface{}) { - if logLevel <= log.DebugLevel { - log.Debug(generateLogMessage(module, components...)) - } + log.Debug(generateLogMessage(module, components...)) } // LogTrace logs a message at the TRACE level (really just additional DEBUG messages). func LogTrace(module interface{}, components ...interface{}) { - if shouldPrintTraceLogs { - log.Debug(generateLogMessage(module, components...)) - } + log.Trace(generateLogMessage(module, components...)) } diff --git a/fw/executor/main.go b/fw/executor/main.go index ac9a6435..2d7ed4b9 100644 --- a/fw/executor/main.go +++ b/fw/executor/main.go @@ -70,7 +70,7 @@ func Main(args []string) { sigChannel := make(chan os.Signal, 1) signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - core.LogInfo(yanfd, "Received signal ", receivedSig, " - exiting") + core.Log.Info(yanfd, "received signal - exit", "signal", receivedSig) yanfd.Stop() } diff --git a/fw/executor/profiler.go b/fw/executor/profiler.go index c5f9cd93..6738a1c7 100644 --- a/fw/executor/profiler.go +++ b/fw/executor/profiler.go @@ -29,12 +29,12 @@ func (p *Profiler) Start() (err error) { core.LogFatal(p, "Unable to open output file for CPU profile: ", err) } - core.LogInfo(p, "Profiling CPU - outputting to ", p.config.CpuProfile) + core.Log.Info(p, "Profiling CPU", "out", p.config.CpuProfile) pprof.StartCPUProfile(p.cpuFile) } if p.config.BlockProfile != "" { - core.LogInfo(p, "Profiling blocking operations - outputting to ", p.config.BlockProfile) + core.Log.Info(p, "Profiling blocking operations", "out", p.config.BlockProfile) runtime.SetBlockProfileRate(1) p.block = pprof.Lookup("block") } @@ -61,7 +61,7 @@ func (p *Profiler) Stop() { } defer memProfileFile.Close() - core.LogInfo(p, "Profiling memory - outputting to ", p.config.MemProfile) + core.Log.Info(p, "Profiling memory", "out", p.config.MemProfile) runtime.GC() if err := pprof.WriteHeapProfile(memProfileFile); err != nil { core.LogFatal(p, "Unable to write memory profile: ", err) diff --git a/fw/executor/yanfd.go b/fw/executor/yanfd.go index 6ed4f374..190cf5b7 100644 --- a/fw/executor/yanfd.go +++ b/fw/executor/yanfd.go @@ -65,7 +65,7 @@ func NewYaNFD(config *YaNFDConfig) *YaNFD { // Initialize config file core.LoadConfig(config.Config, config.BaseDir) - core.InitializeLogger(config.LogFile) + core.OpenLogger(config.LogFile) face.Configure() fw.Configure() table.Configure() @@ -80,7 +80,7 @@ func NewYaNFD(config *YaNFDConfig) *YaNFD { // Start runs YaNFD. Note: this function may exit the program when there is error. // This function is non-blocking. func (y *YaNFD) Start() { - core.LogInfo(y, "Starting YaNFD") + core.Log.Info(y, "Starting NDN forwarder") // Start profiler y.profiler.Start() @@ -126,12 +126,12 @@ func (y *YaNFD) Start() { uri := fmt.Sprintf("udp://%s", udpAddr) udpListener, err := face.MakeUDPListener(defn.DecodeURIString(uri)) if err != nil { - core.LogError(y, "Unable to create UDP listener for ", uri, ": ", err) + core.Log.Error(y, "Unable to create UDP listener", "uri", uri, "err", err) } else { listenerCount++ go udpListener.Run() y.udpListeners = append(y.udpListeners, udpListener) - core.LogInfo(y, "Created unicast UDP listener for ", uri) + core.Log.Info(y, "Created unicast UDP listener", "uri", uri) } } } @@ -150,12 +150,12 @@ func (y *YaNFD) Start() { uri := fmt.Sprintf("tcp://%s", tcpAddr) tcpListener, err := face.MakeTCPListener(defn.DecodeURIString(uri)) if err != nil { - core.LogError(y, "Unable to create TCP listener for ", uri, ": ", err) + core.Log.Error(y, "Unable to create TCP listener", "uri", uri, "err", err) } else { listenerCount++ go tcpListener.Run() y.tcpListeners = append(y.tcpListeners, tcpListener) - core.LogInfo(y, "Created unicast TCP listener for ", uri) + core.Log.Info(y, "Created unicast TCP listener", "uri", uri) } } } @@ -169,13 +169,13 @@ func (y *YaNFD) Start() { for _, iface := range ifaces { if iface.Flags&net.FlagUp == 0 { - core.LogInfo(y, "Skipping interface ", iface.Name, " because not up") + core.Log.Info(y, "Skipping interface because not up", "iface", iface.Name) continue } addrs, err := iface.Addrs() if err != nil { - core.LogError(y, "Unable to access addresses on network interface ", iface.Name, ": ", err) + core.Log.Error(y, "Unable to access addresses on network interface", "iface", iface.Name, "err", err) continue } @@ -201,7 +201,7 @@ func (y *YaNFD) Start() { ).Run(nil) listenerCount++ - core.LogInfo(y, "Created multicast UDP face for ", uri) + core.Log.Info(y, "Created multicast UDP face", "uri", uri) } } } @@ -216,7 +216,7 @@ func (y *YaNFD) Start() { listenerCount++ go unixListener.Run() y.unixListener = unixListener - core.LogInfo(y, "Created Unix stream listener for ", face.UnixSocketPath) + core.Log.Info(y, "Created Unix stream listener", "uri", face.UnixSocketPath) } } @@ -232,12 +232,12 @@ func (y *YaNFD) Start() { wsListener, err := face.NewWebSocketListener(cfg) if err != nil { - core.LogError(y, "Unable to create ", cfg, ": ", err) + core.LogError(y, "Unable to create WebSocket Listener", "cfg", cfg, "err", err) } else { listenerCount++ go wsListener.Run() y.wsListener = wsListener - core.LogInfo(y, "Created ", cfg) + core.Log.Info(y, "Created WebSocket listener", "uri", cfg.URL().String()) } } @@ -250,7 +250,7 @@ func (y *YaNFD) Start() { // Stop shuts down YaNFD. func (y *YaNFD) Stop() { - core.LogInfo(y, "Forwarder shutting down ...") + core.Log.Info(y, "Stopping NDN forwarder") core.ShouldQuit = true // Stop profiler @@ -288,4 +288,7 @@ func (y *YaNFD) Stop() { for _, fw := range fw.Threads { <-fw.HasQuit } + + // Close log file + core.CloseLogger() } diff --git a/fw/face/ndnlp-link-service.go b/fw/face/ndnlp-link-service.go index 07f156f6..021e4758 100644 --- a/fw/face/ndnlp-link-service.go +++ b/fw/face/ndnlp-link-service.go @@ -205,7 +205,7 @@ func sendPacket(l *NDNLPLinkService, out dispatch.OutPkt) { var fragments []*spec.LpPacket if len(wire) > effectiveMtu { if !l.options.IsFragmentationEnabled { - core.LogInfo(l, "Attempted to send frame over MTU on link without fragmentation - DROP") + core.Log.Info(l, "Attempted to send frame over MTU on link without fragmentation - DROP") return } diff --git a/fw/face/table.go b/fw/face/table.go index 7c4dd34d..ecfd8e59 100644 --- a/fw/face/table.go +++ b/fw/face/table.go @@ -84,7 +84,7 @@ func (t *Table) Remove(id uint64) { t.faces.Delete(id) dispatch.RemoveFace(id) table.Rib.CleanUpFace(id) - core.LogInfo(t, "Unregistered FaceID=", id) + core.Log.Info(t, "Unregistered FaceID", "faceid", id) } // ExpirationHandler stops the faces that have expired @@ -97,7 +97,7 @@ func (t *Table) ExpirationHandler() { t.faces.Range(func(_, face interface{}) bool { transport := face.(LinkService).Transport() if transport != nil && transport.ExpirationPeriod() < 0 { - core.LogInfo(transport, "Face expired") + core.Log.Info(t, "Face expired", "transport", transport) transport.Close() } return true diff --git a/fw/face/tcp-listener.go b/fw/face/tcp-listener.go index 629a1770..bbd9beef 100644 --- a/fw/face/tcp-listener.go +++ b/fw/face/tcp-listener.go @@ -82,7 +82,7 @@ func (l *TCPListener) Run() { continue } - core.LogInfo(l, "Accepting new TCP face ", newTransport.RemoteURI()) + core.Log.Info(l, "Accepting new TCP face", "uri", newTransport.RemoteURI()) options := MakeNDNLPLinkServiceOptions() options.IsFragmentationEnabled = false // reliable stream MakeNDNLPLinkService(newTransport, options).Run(nil) diff --git a/fw/face/udp-listener.go b/fw/face/udp-listener.go index 8b52422c..989ed39a 100644 --- a/fw/face/udp-listener.go +++ b/fw/face/udp-listener.go @@ -100,7 +100,7 @@ func (l *UDPListener) Run() { continue } - core.LogInfo(l, "Accepting new UDP face ", newTransport.RemoteURI()) + core.Log.Info(l, "Accepting new UDP face", "uri", newTransport.RemoteURI()) MakeNDNLPLinkService(newTransport, MakeNDNLPLinkServiceOptions()).Run(recvBuf[:readSize]) } } diff --git a/fw/face/unicast-tcp-transport.go b/fw/face/unicast-tcp-transport.go index 2f1f205c..52b2433d 100644 --- a/fw/face/unicast-tcp-transport.go +++ b/fw/face/unicast-tcp-transport.go @@ -251,7 +251,7 @@ func (t *UnicastTCPTransport) runReceive() { return // do not continue } - core.LogInfo(t, "Connected socket - Face UP") + core.Log.Info(t, "Connected socket - Face UP") t.running.Store(true) } } diff --git a/fw/face/unix-stream-listener.go b/fw/face/unix-stream-listener.go index dd4fd273..caf17bbf 100644 --- a/fw/face/unix-stream-listener.go +++ b/fw/face/unix-stream-listener.go @@ -65,7 +65,7 @@ func (l *UnixStreamListener) Run() { core.LogFatal(l, "Unable to change permissions on Unix stream listener: ", err) } - core.LogInfo(l, "Listening") + core.Log.Info(l, "Listening") // Run accept loop for !core.ShouldQuit { @@ -91,7 +91,7 @@ func (l *UnixStreamListener) Run() { continue } - core.LogInfo(l, "Accepting new Unix stream face ", remoteURI) + core.Log.Info(l, "Accepting new Unix stream face", "uri", remoteURI) options := MakeNDNLPLinkServiceOptions() options.IsFragmentationEnabled = false // reliable stream MakeNDNLPLinkService(newTransport, options).Run(nil) diff --git a/fw/face/web-socket-listener.go b/fw/face/web-socket-listener.go index a1a64270..6167fe2b 100644 --- a/fw/face/web-socket-listener.go +++ b/fw/face/web-socket-listener.go @@ -110,7 +110,7 @@ func (l *WebSocketListener) handler(w http.ResponseWriter, r *http.Request) { } newTransport := NewWebSocketTransport(l.localURI, c) - core.LogInfo(l, "Accepting new WebSocket face ", newTransport.RemoteURI()) + core.Log.Info(l, "Accepting new WebSocket face", "uri", newTransport.RemoteURI()) options := MakeNDNLPLinkServiceOptions() options.IsFragmentationEnabled = false // reliable stream @@ -118,6 +118,6 @@ func (l *WebSocketListener) handler(w http.ResponseWriter, r *http.Request) { } func (l *WebSocketListener) Close() { - core.LogInfo(l, "Stopping listener") + core.Log.Info(l, "Stopping listener") l.server.Shutdown(context.TODO()) } diff --git a/fw/face/web-socket-transport.go b/fw/face/web-socket-transport.go index abe53b02..992dae8b 100644 --- a/fw/face/web-socket-transport.go +++ b/fw/face/web-socket-transport.go @@ -75,14 +75,14 @@ func (t *WebSocketTransport) runReceive() { defer t.Close() for { - mt, message, e := t.c.ReadMessage() - if e != nil { - if websocket.IsCloseError(e) { + mt, message, err := t.c.ReadMessage() + if err != nil { + if websocket.IsCloseError(err) { // gracefully closed - } else if websocket.IsUnexpectedCloseError(e) { - core.LogInfo(t, "WebSocket closed unexpectedly (", e, ") - DROP and Face DOWN") + } else if websocket.IsUnexpectedCloseError(err) { + core.Log.Info(t, "WebSocket closed unexpectedly - DROP and Face DOWN", "err", err) } else { - core.LogWarn(t, "Unable to read from WebSocket (", e, ") - DROP and Face DOWN") + core.LogWarn(t, "Unable to read from WebSocket - DROP and Face DOWN", "err", err) } return } diff --git a/fw/fw/thread.go b/fw/fw/thread.go index 94802dac..cd12beb0 100644 --- a/fw/fw/thread.go +++ b/fw/fw/thread.go @@ -112,7 +112,7 @@ func (t *Thread) GetNumCsEntries() int { // TellToQuit tells the forwarding thread to quit func (t *Thread) TellToQuit() { - core.LogInfo(t, "Told to quit") + core.Log.Info(t, "Told to quit") t.shouldQuit <- true } @@ -140,7 +140,7 @@ func (t *Thread) Run() { t.deadNonceList.Ticker.Stop() - core.LogInfo(t, "Stopping thread") + core.Log.Info(t, "Stopping thread") t.HasQuit <- true } @@ -294,7 +294,7 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { InFace: packet.IncomingFaceID, }) } else { - core.LogInfo(t, "Non-existent face specified in NextHopFaceId for Interest ", packet.Name, " - DROP") + core.Log.Info(t, "Non-existent face specified in NextHopFaceId for Interest ", packet.Name, " - DROP") } return } diff --git a/fw/mgmt/cs.go b/fw/mgmt/cs.go index 696d58d9..d9928bce 100644 --- a/fw/mgmt/cs.go +++ b/fw/mgmt/cs.go @@ -79,20 +79,20 @@ func (c *ContentStoreModule) config(interest *Interest) { } if params.Capacity != nil { - core.LogInfo(c, "Setting CS capacity to ", *params.Capacity) + core.Log.Info(c, "Setting CS capacity", "capacity", *params.Capacity) table.SetCsCapacity(int(*params.Capacity)) } if params.Mask != nil && params.Flags != nil { if *params.Mask&mgmt.CsEnableAdmit > 0 { val := *params.Flags&mgmt.CsEnableAdmit > 0 - core.LogInfo(c, "Setting CS admit flag to ", val) + core.Log.Info(c, "Setting CS admit flag", "value", val) table.SetCsAdmit(val) } if *params.Mask&mgmt.CsEnableServe > 0 { val := *params.Flags&mgmt.CsEnableServe > 0 - core.LogInfo(c, "Setting CS serve flag to ", val) + core.Log.Info(c, "Setting CS serve flag", "value", val) table.SetCsServe(val) } } diff --git a/fw/mgmt/face.go b/fw/mgmt/face.go index a7279a7a..4cf6f74e 100644 --- a/fw/mgmt/face.go +++ b/fw/mgmt/face.go @@ -286,7 +286,7 @@ func (f *FaceModule) create(interest *Interest) { f.fillFaceProperties(responseParams, linkService) f.manager.sendCtrlResp(interest, 200, "OK", responseParams) - core.LogInfo(f, "Created face with URI ", URI) + core.Log.Info(f, "Created face ", "uri", URI) } func (f *FaceModule) update(interest *Interest) { @@ -370,13 +370,13 @@ func (f *FaceModule) update(interest *Interest) { if params.BaseCongestionMarkInterval != nil && time.Duration(*params.BaseCongestionMarkInterval)*time.Nanosecond != options.BaseCongestionMarkingInterval { options.BaseCongestionMarkingInterval = time.Duration(*params.BaseCongestionMarkInterval) * time.Nanosecond - core.LogInfo(f, "FaceID=", faceID, ", BaseCongestionMarkingInterval=", options.BaseCongestionMarkingInterval) + core.Log.Info(f, "Set BaseCongestionMarkingInterval", "faceid", faceID, "value", options.BaseCongestionMarkingInterval) } if params.DefaultCongestionThreshold != nil && *params.DefaultCongestionThreshold != options.DefaultCongestionThresholdBytes { options.DefaultCongestionThresholdBytes = *params.DefaultCongestionThreshold - core.LogInfo(f, "FaceID=", faceID, ", DefaultCongestionThreshold=", options.DefaultCongestionThresholdBytes, "B") + core.Log.Info(f, "Set DefaultCongestionThreshold", "faceid", faceID, "value", options.DefaultCongestionThresholdBytes) } // MTU @@ -384,7 +384,7 @@ func (f *FaceModule) update(interest *Interest) { oldMTU := selectedFace.MTU() newMTU := min(int(*params.Mtu), defn.MaxNDNPacketSize) selectedFace.SetMTU(newMTU) - core.LogInfo(f, "FaceID=", faceID, ", MTU ", oldMTU, " -> ", newMTU) + core.Log.Info(f, "Set MTU", "faceid", faceID, "value", newMTU, "old", oldMTU) } // Flags @@ -394,12 +394,12 @@ func (f *FaceModule) update(interest *Interest) { if mask&face.FaceFlagLocalFields > 0 { if flags&face.FaceFlagLocalFields > 0 { - core.LogInfo(f, "FaceID=", faceID, ", Enabling local fields") + core.Log.Info(f, "Enable local fields", "faceid", faceID) options.IsConsumerControlledForwardingEnabled = true options.IsIncomingFaceIndicationEnabled = true options.IsLocalCachePolicyEnabled = true } else { - core.LogInfo(f, "FaceID=", faceID, ", Disabling local fields") + core.Log.Info(f, "Disable local fields", "faceid", faceID) options.IsConsumerControlledForwardingEnabled = false options.IsIncomingFaceIndicationEnabled = false options.IsLocalCachePolicyEnabled = false @@ -409,9 +409,9 @@ func (f *FaceModule) update(interest *Interest) { if mask&face.FaceFlagCongestionMarking > 0 { options.IsCongestionMarkingEnabled = flags&face.FaceFlagCongestionMarking > 0 if flags&face.FaceFlagCongestionMarking > 0 { - core.LogInfo(f, "FaceID=", faceID, ", Enabling congestion marking") + core.Log.Info(f, "Enable congestion marking", "faceid", faceID) } else { - core.LogInfo(f, "FaceID=", faceID, ", Disabling congestion marking") + core.Log.Info(f, "Disable congestion marking", "faceid", faceID) } } } @@ -444,9 +444,9 @@ func (f *FaceModule) destroy(interest *Interest) { if link := face.FaceTable.Get(*params.FaceId); link != nil { link.Close() - core.LogInfo(f, "Destroyed face with FaceID=", *params.FaceId) + core.Log.Info(f, "Destroyed face", "faceid", *params.FaceId) } else { - core.LogInfo(f, "Ignoring attempt to delete non-existent face with FaceID=", *params.FaceId) + core.Log.Info(f, "Ignoring attempt to delete non-existent face", "faceid", *params.FaceId) } f.manager.sendCtrlResp(interest, 200, "OK", params) diff --git a/fw/mgmt/fib.go b/fw/mgmt/fib.go index 9d8201ab..49184b52 100644 --- a/fw/mgmt/fib.go +++ b/fw/mgmt/fib.go @@ -87,7 +87,7 @@ func (f *FIBModule) add(interest *Interest) { } table.FibStrategyTable.InsertNextHopEnc(params.Name, faceID, cost) - core.LogInfo(f, "Created nexthop for ", params.Name, " to FaceID=", faceID, "with Cost=", cost) + core.Log.Info(f, "Created nexthop", "name", params.Name, "faceid", faceID, "cost", cost) f.manager.sendCtrlResp(interest, 200, "OK", &mgmt.ControlArgs{ Name: params.Name, @@ -119,7 +119,7 @@ func (f *FIBModule) remove(interest *Interest) { } table.FibStrategyTable.RemoveNextHopEnc(params.Name, faceID) - core.LogInfo(f, "Removed nexthop for ", params.Name, " to FaceID=", faceID) + core.Log.Info(f, "Removed nexthop", "name", params.Name, "faceid", faceID) f.manager.sendCtrlResp(interest, 200, "OK", &mgmt.ControlArgs{ Name: params.Name, diff --git a/fw/mgmt/nlsr_readvertiser.go b/fw/mgmt/nlsr_readvertiser.go index 7367a76e..405f7d99 100644 --- a/fw/mgmt/nlsr_readvertiser.go +++ b/fw/mgmt/nlsr_readvertiser.go @@ -33,10 +33,10 @@ func (r *NlsrReadvertiser) String() string { func (r *NlsrReadvertiser) Announce(name enc.Name, route *table.Route) { if route.Origin != uint64(spec_mgmt.RouteOriginClient) { - core.LogDebug(r, "skip advertise=", name, " origin=", route.Origin) + core.LogDebug(r, "skip advertise", "name", name, "origin", route.Origin) return } - core.LogInfo(r, "advertise=", name) + core.Log.Info(r, "advertise", "name", name) r.mutex.Lock() defer r.mutex.Unlock() @@ -74,10 +74,10 @@ func (r *NlsrReadvertiser) Withdraw(name enc.Name, route *table.Route) { nhash := name.Hash() r.advertised[nhash] -= 1 if r.advertised[nhash] > 0 { - core.LogDebug(r, "skip withdraw=", name, " still advertised") + core.LogDebug(r, "skip withdraw (still advertised)", "name", name) return } - core.LogInfo(r, "withdraw=", name) + core.Log.Info(r, "withdraw", "name", name) params := &spec_mgmt.ControlArgs{ Name: name, diff --git a/fw/mgmt/rib.go b/fw/mgmt/rib.go index 1d604fbb..6657f5be 100644 --- a/fw/mgmt/rib.go +++ b/fw/mgmt/rib.go @@ -110,11 +110,11 @@ func (r *RIBModule) register(interest *Interest) { ExpirationPeriod: expirationPeriod, }) if expirationPeriod != nil { - core.LogInfo(r, "Created route for Prefix=", params.Name, ", FaceID=", faceID, ", Origin=", origin, - ", Cost=", cost, ", Flags=0x", strconv.FormatUint(flags, 16), ", ExpirationPeriod=", expirationPeriod) + core.Log.Info(r, "Created route", "name", params.Name, "faceid", faceID, "origin", origin, + "cost", cost, "flags", strconv.FormatUint(flags, 16), "expires", expirationPeriod) } else { - core.LogInfo(r, "Created route for Prefix=", params.Name, ", FaceID=", faceID, ", Origin=", origin, - ", Cost=", cost, ", Flags=0x", strconv.FormatUint(flags, 16)) + core.Log.Info(r, "Created route", "name", params.Name, "faceid", faceID, "origin", origin, + "cost", cost, "flags", strconv.FormatUint(flags, 16)) } responseParams := &mgmt.ControlArgs{ Name: params.Name, @@ -163,7 +163,7 @@ func (r *RIBModule) unregister(interest *Interest) { Origin: utils.IdPtr(origin), }) - core.LogInfo(r, "Removed route for Prefix=", params.Name, ", FaceID=", faceID, ", Origin=", origin) + core.Log.Info(r, "Removed route", "name", params.Name, "faceid", faceID, "origin", origin) } func (r *RIBModule) announce(interest *Interest) { diff --git a/fw/mgmt/strategy-choice.go b/fw/mgmt/strategy-choice.go index 080d0c5a..0658400e 100644 --- a/fw/mgmt/strategy-choice.go +++ b/fw/mgmt/strategy-choice.go @@ -132,7 +132,7 @@ func (s *StrategyChoiceModule) set(interest *Interest) { Strategy: params.Strategy, }) - core.LogInfo(s, "Set strategy for Name=", params.Name, " to Strategy=", params.Strategy.Name) + core.Log.Info(s, "Set strategy", "name", params.Name, "strategy", params.Strategy.Name) } func (s *StrategyChoiceModule) unset(interest *Interest) { @@ -158,7 +158,7 @@ func (s *StrategyChoiceModule) unset(interest *Interest) { } table.FibStrategyTable.UnSetStrategyEnc(params.Name) - core.LogInfo(s, "Unset Strategy for Name=", params.Name) + core.Log.Info(s, "Unset Strategy", "name", params.Name) s.manager.sendCtrlResp(interest, 200, "OK", &mgmt.ControlArgs{Name: params.Name}) } diff --git a/fw/mgmt/thread.go b/fw/mgmt/thread.go index e0f630f3..e99be980 100644 --- a/fw/mgmt/thread.go +++ b/fw/mgmt/thread.go @@ -75,7 +75,7 @@ func (m *Thread) registerModule(name string, module Module) { // Run management thread func (m *Thread) Run() { - core.LogInfo(m, "Starting management thread") + core.Log.Info(m, "Starting management thread") // Create and register Internal transport m.face, m.transport = face.RegisterInternalTransport() @@ -88,7 +88,7 @@ func (m *Thread) Run() { lpPkt := m.transport.Receive() if lpPkt == nil { // Indicates that internal face has quit, which means it's time for us to quit - core.LogInfo(m, "Face quit, so management quitting") + core.Log.Info(m, "Face quit, so management quitting") break } diff --git a/std/engine/basic/engine.go b/std/engine/basic/engine.go index 12c0ee8d..7666520f 100644 --- a/std/engine/basic/engine.go +++ b/std/engine/basic/engine.go @@ -50,10 +50,6 @@ type Engine struct { fibLock sync.Mutex pitLock sync.Mutex - // log is used to log events, with "module=DefaultEngine". Need apex/log initialized. - // Use WithField to set "name=". - log *log.Entry - // mgmtConf is the configuration for the management protocol. mgmtConf *mgmt.MgmtConfig @@ -102,14 +98,14 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { var incomingFaceId *uint64 = nil var raw enc.Wire = nil - if e.log.Level <= log.TraceLevel { + if log.HasTrace() { wire := reader.Range(0, reader.Length()) - e.log.Tracef("Received packet bytes: %v", wire.Join()) + log.Trace("received packet bytes", "wire", wire.Join()) } pkt, ctx, err := spec.ReadPacket(reader) if err != nil { - e.log.Errorf("Failed to parse packet: %v", err) + log.Errorf("failed to parse packet", "err", err) // Recoverable error. Should continue. return nil } @@ -118,7 +114,7 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { if pkt.LpPacket != nil { lpPkt := pkt.LpPacket if lpPkt.FragIndex != nil || lpPkt.FragCount != nil { - e.log.Warnf("Fragmented LpPackets are not supported. Drop.") + log.Warn("fragmented LpPackets are not supported - DROP") return nil } // Parse the inner packet. @@ -129,10 +125,10 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { pkt, ctx, err = spec.ReadPacket(enc.NewWireReader(raw)) } if err != nil || (pkt.Data == nil) == (pkt.Interest == nil) { - e.log.Errorf("Failed to parse packet in LpPacket: %v", err) - if e.log.Level <= log.TraceLevel { + log.Errorf("failed to parse packet in LpPacket", "err", err) + if log.HasTrace() { wire := reader.Range(0, reader.Length()) - e.log.Tracef("Failed packet bytes: %v", wire.Join()) + log.Trace("failed packet bytes", "wire", wire.Join()) } // Recoverable error. Should continue. return nil @@ -149,18 +145,16 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { // Now pkt is either Data or Interest (including Nack). if nackReason != spec.NackReasonNone { if pkt.Interest == nil { - e.log.Errorf("Received nack for an Data") + log.Error("received nack for an Data") return nil } - if e.log.Level <= log.TraceLevel { - e.log.WithField("name", pkt.Interest.NameV.String()). - Tracef("Nack received for %v", nackReason) + if log.HasTrace() { + log.Trace("nack received", "reason", nackReason, "name", pkt.Interest.Name()) } e.onNack(pkt.Interest.NameV, nackReason) } else if pkt.Interest != nil { - if e.log.Level <= log.TraceLevel { - e.log.WithField("name", pkt.Interest.NameV.String()). - Trace("Interest received.") + if log.HasTrace() { + log.Trace("interest received", "name", pkt.Interest.Name()) } e.onInterest(ndn.InterestHandlerArgs{ Interest: pkt.Interest, @@ -170,14 +164,13 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { IncomingFaceId: incomingFaceId, }) } else if pkt.Data != nil { - if e.log.Level <= log.TraceLevel { - e.log.WithField("name", pkt.Data.NameV.String()). - Trace("Data received.") + if log.HasTrace() { + log.Trace("data received", "name", pkt.Data.Name()) } // PitToken is not used for now e.onData(pkt.Data, ctx.Data_context.SigCovered(), raw, pitToken) } else { - log.Fatalf("Unreachable. Check spec implementation.") + panic("unexpected packet type") } return nil } @@ -212,7 +205,7 @@ func (e *Engine) onInterest(args ndn.InterestHandlerArgs) { return nil }() if handler == nil { - e.log.WithField("name", name.String()).Warn("No handler. Drop.") + log.Warn("no handler for interest", "name", name) return } @@ -220,11 +213,11 @@ func (e *Engine) onInterest(args ndn.InterestHandlerArgs) { args.Reply = func(encodedData enc.Wire) error { now := e.timer.Now() if args.Deadline.Before(now) { - e.log.WithField("name", name).Warn("Deadline exceeded. Drop.") + log.Warn("deadline exceeded - DROP", "name", name) return ndn.ErrDeadlineExceed } if !e.face.IsRunning() { - e.log.WithField("name", name).Error("Cannot send through a closed face. Drop.") + log.Error("cannot send through a closed face - DROP", "name", name) return ndn.ErrFaceDown } if args.PitToken != nil { @@ -257,7 +250,7 @@ func (e *Engine) onData(pkt *spec.Data, sigCovered enc.Wire, raw enc.Wire, pitTo n := e.pit.PrefixMatch(pkt.NameV) if n == nil { - e.log.WithField("name", pkt.NameV.String()).Warn("Received Data for an unknown interest. Drop.") + log.Warn("received data for an unknown interest - DROP", "name", pkt.Name()) return } @@ -318,7 +311,7 @@ func (e *Engine) onNack(name enc.Name, reason uint64) { defer e.pitLock.Unlock() n := e.pit.ExactMatch(name) if n == nil { - e.log.WithField("name", name.String()).Warn("Received Nack for an unknown interest. Drop.") + log.Warn("received Nack for an unknown interest - DROP", "name", name) return } for _, entry := range n.Value() { @@ -329,14 +322,14 @@ func (e *Engine) onNack(name enc.Name, reason uint64) { NackReason: reason, }) } else { - e.log.Fatalf("PIT has empty entry. This should not happen. Please check the implementation.") + panic("[BUG] PIT has empty entry") } } n.Delete() } func (e *Engine) onError(err error) error { - e.log.Errorf("error on face, quit: %v", err) + log.Error("error on face", "err", err) // TODO: Handle Interest cancellation return err } @@ -413,7 +406,7 @@ func (e *Engine) Express(interest *ndn.EncodedInterest, callback ndn.ExpressCall NackReason: spec.NackReasonNone, }) } else { - e.log.Fatalf("PIT has empty entry. This should not happen. Please check the implementation.") + panic("[BUG] PIT has empty entry") } } } @@ -436,10 +429,9 @@ func (e *Engine) Express(interest *ndn.EncodedInterest, callback ndn.ExpressCall // Send interest err := e.face.Send(interest.Wire) if err != nil { - e.log.Errorf("Failed to send Interest: %v", err) - } else if e.log.Level <= log.TraceLevel { - e.log.WithField("name", finalName.String()). - Trace("Interest sent.") + log.Error("failed to send interest", "err", err) + } else if log.HasTrace() { + log.Trace("interest sent", "name", finalName) } return err @@ -515,12 +507,10 @@ func (e *Engine) ExecMgmtCmd(module string, cmd string, args any) (any, error) { func (e *Engine) RegisterRoute(prefix enc.Name) error { _, err := e.ExecMgmtCmd("rib", "register", &mgmt.ControlArgs{Name: prefix}) if err != nil { - e.log.WithField("name", prefix.String()). - Errorf("Failed to register prefix: %v", err) + log.Error("failed to register prefix", "err", err, "name", prefix) return err } else { - e.log.WithField("name", prefix.String()). - Info("Prefix registered.") + log.Info("prefix registered", "name", prefix) } return nil } @@ -528,12 +518,10 @@ func (e *Engine) RegisterRoute(prefix enc.Name) error { func (e *Engine) UnregisterRoute(prefix enc.Name) error { _, err := e.ExecMgmtCmd("rib", "unregister", &mgmt.ControlArgs{Name: prefix}) if err != nil { - e.log.WithField("name", prefix.String()). - Errorf("Failed to register prefix: %v", err) + log.Error("failed to unregister prefix", "err", err, "name", prefix) return err } else { - e.log.WithField("name", prefix.String()). - Info("Prefix registered.") + log.Info("prefix unregistered", "name", prefix) } return nil } @@ -542,15 +530,12 @@ func NewEngine(face face.Face, timer ndn.Timer, cmdSigner ndn.Signer, cmdChecker if face == nil || timer == nil || cmdSigner == nil || cmdChecker == nil { return nil } - logger := log.WithField("module", "basic_engine") - logger.Level = log.InfoLevel mgmtCfg := mgmt.NewConfig(face.IsLocal(), cmdSigner, spec.Spec{}) return &Engine{ face: face, timer: timer, mgmtConf: mgmtCfg, cmdChecker: cmdChecker, - log: logger, fib: NewNameTrie[fibEntry](), pit: NewNameTrie[pitEntry](), fibLock: sync.Mutex{}, diff --git a/std/examples/low-level/svs/main.go b/std/examples/low-level/svs/main.go index 672292cc..163767d8 100644 --- a/std/examples/low-level/svs/main.go +++ b/std/examples/low-level/svs/main.go @@ -10,6 +10,8 @@ import ( "github.com/named-data/ndnd/std/sync" ) +const TAG = "svs" + func main() { // Before running this example, make sure the strategy is correctly setup // to multicast for the /ndn/svs prefix. For example, using the following: @@ -17,8 +19,7 @@ func main() { // ndnd fw strategy set prefix=/ndn/svs strategy=/localhost/nfd/strategy/multicast // - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") + logger := log.NewText(os.Stderr) if len(os.Args) < 2 { log.Fatalf("Usage: %s ", os.Args[0]) @@ -34,7 +35,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + logger.Fatal(TAG, "Unable to start engine", "err", err) return } defer app.Stop() @@ -45,21 +46,21 @@ func main() { Engine: app, GroupPrefix: group, OnUpdate: func(ssu sync.SvSyncUpdate) { - logger.Infof("Received update: %+v", ssu) + logger.Info(TAG, "Received update", "update", ssu) }, }) // Register group prefix route err = app.RegisterRoute(group) if err != nil { - logger.Errorf("Unable to register route: %+v", err) + logger.Error(TAG, "Unable to register route", "err", err) return } defer app.UnregisterRoute(group) err = svsync.Start() if err != nil { - logger.Errorf("Unable to create SvSync: %+v", err) + logger.Error(TAG, "Unable to create SvSync", "err", err) return } @@ -67,7 +68,7 @@ func main() { ticker := time.NewTicker(3 * time.Second) for range ticker.C { - new := svsync.IncrSeqNo(name) - logger.Infof("Published new sequence number: %d", new) + seq := svsync.IncrSeqNo(name) + logger.Info(TAG, "Published new sequence number", "seq", seq) } } diff --git a/std/log/LICENSE b/std/log/LICENSE deleted file mode 100644 index 56f1d390..00000000 --- a/std/log/LICENSE +++ /dev/null @@ -1,24 +0,0 @@ -This package is adapted from apex/log - -(The MIT License) - -Copyright (c) 2015 TJ Holowaychuk tj@tjholowaychuk.com - -Permission is hereby granted, free of charge, to any person obtaining -a copy of this software and associated documentation files (the -'Software'), to deal in the Software without restriction, including -without limitation the rights to use, copy, modify, merge, publish, -distribute, sublicense, and/or sell copies of the Software, and to -permit persons to whom the Software is furnished to do so, subject to -the following conditions: - -The above copyright notice and this permission notice shall be -included in all copies or substantial portions of the Software. - -THE SOFTWARE IS PROVIDED 'AS IS', WITHOUT WARRANTY OF ANY KIND, -EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF -MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. -IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY -CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, -TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE -SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. diff --git a/std/log/default.go b/std/log/default.go new file mode 100644 index 00000000..ba7e36ab --- /dev/null +++ b/std/log/default.go @@ -0,0 +1,75 @@ +package log + +import "os" + +var defaultLogger *Logger = NewText(os.Stderr) + +// Default returns the default logger. +func Default() *Logger { + return defaultLogger +} + +// Trace level message. +func Trace(msg string, v ...any) { + defaultLogger.log(nil, msg, LevelTrace, v...) +} + +// Debug level message. +func Debug(msg string, v ...any) { + defaultLogger.log(nil, msg, LevelDebug, v...) +} + +// Info level message. +func Info(msg string, v ...any) { + defaultLogger.Info(nil, msg, v...) +} + +// Warn level message. +func Warn(msg string, v ...any) { + defaultLogger.Warn(nil, msg, v...) +} + +// Error level message. +func Error(msg string, v ...any) { + defaultLogger.Error(nil, msg, v...) +} + +// Fatal level message, followed by an exit. +func Fatal(msg string, v ...any) { + defaultLogger.Fatal(nil, msg, v...) +} + +// Tracef level formatted message. +func Tracef(msg string, v ...any) { + defaultLogger.Trace(nil, msg, v...) +} + +// Debugf level formatted message. +func Debugf(msg string, v ...any) { + defaultLogger.Debug(nil, msg, v...) +} + +// Infof level formatted message. +func Infof(msg string, v ...any) { + defaultLogger.Info(nil, msg, v...) +} + +// Warnf level formatted message. +func Warnf(msg string, v ...any) { + defaultLogger.Warn(nil, msg, v...) +} + +// Errorf level formatted message. +func Errorf(msg string, v ...any) { + defaultLogger.Error(nil, msg, v...) +} + +// Fatalf level formatted message, followed by an exit. +func Fatalf(msg string, v ...any) { + defaultLogger.Fatal(nil, msg, v...) +} + +// HasTrace returns if trace level is enabled. +func HasTrace() bool { + return defaultLogger.level <= LevelTrace +} diff --git a/std/log/entry.go b/std/log/entry.go deleted file mode 100644 index 3a99c2ed..00000000 --- a/std/log/entry.go +++ /dev/null @@ -1,194 +0,0 @@ -package log - -import ( - "fmt" - "os" - "strings" - "time" - - "github.com/pkg/errors" -) - -// assert interface compliance. -var _ Interface = (*Entry)(nil) - -// Now returns the current time. -var Now = time.Now - -// Entry represents a single log entry. -type Entry struct { - Logger *Logger `json:"-"` - Fields Fields `json:"fields"` - Level Level `json:"level"` - Timestamp time.Time `json:"timestamp"` - Message string `json:"message"` - start time.Time - fields []Fields -} - -// stackTracer interface. -type stackTracer interface { - StackTrace() errors.StackTrace -} - -// NewEntry returns a new entry for `log`. -func NewEntry(log *Logger) *Entry { - return &Entry{ - Logger: log, - } -} - -// WithFields returns a new entry with `fields` set. -func (e *Entry) WithFields(fields Fielder) *Entry { - f := []Fields{} - f = append(f, e.fields...) - f = append(f, fields.Fields()) - return &Entry{ - Logger: e.Logger, - fields: f, - } -} - -// WithField returns a new entry with the `key` and `value` set. -func (e *Entry) WithField(key string, value interface{}) *Entry { - return e.WithFields(Fields{key: value}) -} - -// WithDuration returns a new entry with the "duration" field set -// to the given duration in milliseconds. -func (e *Entry) WithDuration(d time.Duration) *Entry { - return e.WithField("duration", d.Milliseconds()) -} - -// WithError returns a new entry with the "error" set to `err`. -// -// The given error may implement .Fielder, if it does the method -// will add all its `.Fields()` into the returned entry. -func (e *Entry) WithError(err error) *Entry { - if err == nil { - return e - } - - ctx := e.WithField("error", err.Error()) - - if s, ok := err.(stackTracer); ok { - frame := s.StackTrace()[0] - - name := fmt.Sprintf("%n", frame) - file := fmt.Sprintf("%+s", frame) - line := fmt.Sprintf("%d", frame) - - parts := strings.Split(file, "\n\t") - if len(parts) > 1 { - file = parts[1] - } - - ctx = ctx.WithField("source", fmt.Sprintf("%s: %s:%s", name, file, line)) - } - - if f, ok := err.(Fielder); ok { - ctx = ctx.WithFields(f.Fields()) - } - - return ctx -} - -// Debug level message. -func (e *Entry) Debug(msg string) { - e.Logger.log(DebugLevel, e, msg) -} - -// Info level message. -func (e *Entry) Info(msg string) { - e.Logger.log(InfoLevel, e, msg) -} - -// Warn level message. -func (e *Entry) Warn(msg string) { - e.Logger.log(WarnLevel, e, msg) -} - -// Error level message. -func (e *Entry) Error(msg string) { - e.Logger.log(ErrorLevel, e, msg) -} - -// Fatal level message, followed by an exit. -func (e *Entry) Fatal(msg string) { - e.Logger.log(FatalLevel, e, msg) - os.Exit(1) -} - -// Tracef level formatted message. -func (e *Entry) Tracef(msg string, v ...interface{}) { - e.Trace(fmt.Sprintf(msg, v...)) -} - -// Debugf level formatted message. -func (e *Entry) Debugf(msg string, v ...interface{}) { - e.Debug(fmt.Sprintf(msg, v...)) -} - -// Infof level formatted message. -func (e *Entry) Infof(msg string, v ...interface{}) { - e.Info(fmt.Sprintf(msg, v...)) -} - -// Warnf level formatted message. -func (e *Entry) Warnf(msg string, v ...interface{}) { - e.Warn(fmt.Sprintf(msg, v...)) -} - -// Errorf level formatted message. -func (e *Entry) Errorf(msg string, v ...interface{}) { - e.Error(fmt.Sprintf(msg, v...)) -} - -// Fatalf level formatted message, followed by an exit. -func (e *Entry) Fatalf(msg string, v ...interface{}) { - e.Fatal(fmt.Sprintf(msg, v...)) -} - -// Trace returns a new entry with a Stop method to fire off -// a corresponding completion log, useful with defer. -func (e *Entry) Trace(msg string) *Entry { - e.Info(msg) - v := e.WithFields(e.Fields) - v.Message = msg - v.start = time.Now() - return v -} - -// Stop should be used with Trace, to fire off the completion message. When -// an `err` is passed the "error" field is set, and the log level is error. -func (e *Entry) Stop(err *error) { - if err == nil || *err == nil { - e.WithDuration(time.Since(e.start)).Info(e.Message) - } else { - e.WithDuration(time.Since(e.start)).WithError(*err).Error(e.Message) - } -} - -// mergedFields returns the fields list collapsed into a single map. -func (e *Entry) mergedFields() Fields { - f := Fields{} - - for _, fields := range e.fields { - for k, v := range fields { - f[k] = v - } - } - - return f -} - -// finalize returns a copy of the Entry with Fields merged. -func (e *Entry) finalize(level Level, msg string) *Entry { - return &Entry{ - Logger: e.Logger, - Fields: e.mergedFields(), - Level: level, - Message: msg, - Timestamp: Now(), - } -} diff --git a/std/log/entry_test.go b/std/log/entry_test.go deleted file mode 100644 index 1af38cc3..00000000 --- a/std/log/entry_test.go +++ /dev/null @@ -1,73 +0,0 @@ -package log - -import ( - "fmt" - "testing" - "time" - - "github.com/stretchr/testify/assert" -) - -func TestEntry_WithFields(t *testing.T) { - a := NewEntry(nil) - assert.Nil(t, a.Fields) - - b := a.WithFields(Fields{"foo": "bar"}) - assert.Equal(t, Fields{}, a.mergedFields()) - assert.Equal(t, Fields{"foo": "bar"}, b.mergedFields()) - - c := a.WithFields(Fields{"foo": "hello", "bar": "world"}) - - e := c.finalize(InfoLevel, "upload") - assert.Equal(t, e.Message, "upload") - assert.Equal(t, e.Fields, Fields{"foo": "hello", "bar": "world"}) - assert.Equal(t, e.Level, InfoLevel) - assert.NotEmpty(t, e.Timestamp) -} - -func TestEntry_WithField(t *testing.T) { - a := NewEntry(nil) - b := a.WithField("foo", "bar") - assert.Equal(t, Fields{}, a.mergedFields()) - assert.Equal(t, Fields{"foo": "bar"}, b.mergedFields()) -} - -func TestEntry_WithError(t *testing.T) { - a := NewEntry(nil) - b := a.WithError(fmt.Errorf("boom")) - assert.Equal(t, Fields{}, a.mergedFields()) - assert.Equal(t, Fields{"error": "boom"}, b.mergedFields()) -} - -func TestEntry_WithError_fields(t *testing.T) { - a := NewEntry(nil) - b := a.WithError(errFields("boom")) - assert.Equal(t, Fields{}, a.mergedFields()) - assert.Equal(t, Fields{ - "error": "boom", - "reason": "timeout", - }, b.mergedFields()) -} - -func TestEntry_WithError_nil(t *testing.T) { - a := NewEntry(nil) - b := a.WithError(nil) - assert.Equal(t, Fields{}, a.mergedFields()) - assert.Equal(t, Fields{}, b.mergedFields()) -} - -func TestEntry_WithDuration(t *testing.T) { - a := NewEntry(nil) - b := a.WithDuration(time.Second * 2) - assert.Equal(t, Fields{"duration": int64(2000)}, b.mergedFields()) -} - -type errFields string - -func (ef errFields) Error() string { - return string(ef) -} - -func (ef errFields) Fields() Fields { - return Fields{"reason": "timeout"} -} diff --git a/std/log/interface.go b/std/log/interface.go deleted file mode 100644 index 9daa0465..00000000 --- a/std/log/interface.go +++ /dev/null @@ -1,22 +0,0 @@ -package log - -import "time" - -// Interface represents the API of both Logger and Entry. -type Interface interface { - WithFields(Fielder) *Entry - WithField(string, interface{}) *Entry - WithDuration(time.Duration) *Entry - WithError(error) *Entry - Debug(string) - Info(string) - Warn(string) - Error(string) - Fatal(string) - Debugf(string, ...interface{}) - Infof(string, ...interface{}) - Warnf(string, ...interface{}) - Errorf(string, ...interface{}) - Fatalf(string, ...interface{}) - Trace(string) *Entry -} diff --git a/std/log/level.go b/std/log/level.go new file mode 100644 index 00000000..c8e5f8d3 --- /dev/null +++ b/std/log/level.go @@ -0,0 +1,49 @@ +package log + +import ( + "errors" +) + +type Level int + +const LevelTrace Level = -8 +const LevelDebug Level = -4 +const LevelInfo Level = 0 +const LevelWarn Level = 4 +const LevelError Level = 8 +const LevelFatal Level = 12 + +func ParseLevel(s string) (Level, error) { + switch s { + case "TRACE": + return LevelTrace, nil + case "DEBUG": + return LevelDebug, nil + case "INFO": + return LevelInfo, nil + case "WARN": + return LevelWarn, nil + case "ERROR": + return LevelError, nil + case "FATAL": + return LevelFatal, nil + } + return LevelInfo, errors.New("invalid log level") +} + +func (level Level) String() string { + switch level { + case LevelTrace: + return "TRACE" + case LevelDebug: + return "DEBUG" + case LevelInfo: + return "INFO" + case LevelWarn: + return "WARN" + case LevelError: + return "ERROR" + default: + return "UNKNOWN" + } +} diff --git a/std/log/levels.go b/std/log/levels.go deleted file mode 100644 index 184d3b4d..00000000 --- a/std/log/levels.go +++ /dev/null @@ -1,84 +0,0 @@ -package log - -import ( - "bytes" - "errors" - "strings" -) - -// ErrInvalidLevel is returned if the severity level is invalid. -var ErrInvalidLevel = errors.New("invalid level") - -// Level of severity. -type Level int - -// Log levels. -const ( - InvalidLevel Level = iota - 1 - TraceLevel - DebugLevel - InfoLevel - WarnLevel - ErrorLevel - FatalLevel -) - -var levelNames = [...]string{ - TraceLevel: "trace", - DebugLevel: "debug", - InfoLevel: "info", - WarnLevel: "warn", - ErrorLevel: "error", - FatalLevel: "fatal", -} - -var levelStrings = map[string]Level{ - "trace": TraceLevel, - "debug": DebugLevel, - "info": InfoLevel, - "warn": WarnLevel, - "warning": WarnLevel, - "error": ErrorLevel, - "fatal": FatalLevel, -} - -// String implementation. -func (l Level) String() string { - return levelNames[l] -} - -// MarshalJSON implementation. -func (l Level) MarshalJSON() ([]byte, error) { - return []byte(`"` + l.String() + `"`), nil -} - -// UnmarshalJSON implementation. -func (l *Level) UnmarshalJSON(b []byte) error { - v, err := ParseLevel(string(bytes.Trim(b, `"`))) - if err != nil { - return err - } - - *l = v - return nil -} - -// ParseLevel parses level string. -func ParseLevel(s string) (Level, error) { - l, ok := levelStrings[strings.ToLower(s)] - if !ok { - return InvalidLevel, ErrInvalidLevel - } - - return l, nil -} - -// MustParseLevel parses level string or panics. -func MustParseLevel(s string) Level { - l, err := ParseLevel(s) - if err != nil { - panic("invalid log level") - } - - return l -} diff --git a/std/log/levels_test.go b/std/log/levels_test.go deleted file mode 100644 index e2d84f15..00000000 --- a/std/log/levels_test.go +++ /dev/null @@ -1,60 +0,0 @@ -package log - -import ( - "encoding/json" - "testing" - - "github.com/stretchr/testify/assert" -) - -func TestParseLevel(t *testing.T) { - cases := []struct { - String string - Level Level - Num int - }{ - {"debug", DebugLevel, 0}, - {"info", InfoLevel, 1}, - {"warn", WarnLevel, 2}, - {"warning", WarnLevel, 3}, - {"error", ErrorLevel, 4}, - {"fatal", FatalLevel, 5}, - } - - for _, c := range cases { - t.Run(c.String, func(t *testing.T) { - l, err := ParseLevel(c.String) - assert.NoError(t, err, "parse") - assert.Equal(t, c.Level, l) - }) - } - - t.Run("invalid", func(t *testing.T) { - l, err := ParseLevel("something") - assert.Equal(t, ErrInvalidLevel, err) - assert.Equal(t, InvalidLevel, l) - }) -} - -func TestLevel_MarshalJSON(t *testing.T) { - e := Entry{ - Level: InfoLevel, - Message: "hello", - Fields: Fields{}, - } - - expect := `{"fields":{},"level":"info","timestamp":"0001-01-01T00:00:00Z","message":"hello"}` - - b, err := json.Marshal(e) - assert.NoError(t, err) - assert.Equal(t, expect, string(b)) -} - -func TestLevel_UnmarshalJSON(t *testing.T) { - s := `{"fields":{},"level":"info","timestamp":"0001-01-01T00:00:00Z","message":"hello"}` - e := new(Entry) - - err := json.Unmarshal([]byte(s), e) - assert.NoError(t, err) - assert.Equal(t, InfoLevel, e.Level) -} diff --git a/std/log/logger.go b/std/log/logger.go deleted file mode 100644 index c7d9b730..00000000 --- a/std/log/logger.go +++ /dev/null @@ -1,156 +0,0 @@ -package log - -import ( - stdlog "log" - "sort" - "time" -) - -// assert interface compliance. -var _ Interface = (*Logger)(nil) - -// Fielder is an interface for providing fields to custom types. -type Fielder interface { - Fields() Fields -} - -// Fields represents a map of entry level data used for structured logging. -type Fields map[string]interface{} - -// Fields implements Fielder. -func (f Fields) Fields() Fields { - return f -} - -// Get field value by name. -func (f Fields) Get(name string) interface{} { - return f[name] -} - -// Names returns field names sorted. -func (f Fields) Names() (v []string) { - for k := range f { - v = append(v, k) - } - - sort.Strings(v) - return -} - -// The HandlerFunc type is an adapter to allow the use of ordinary functions as -// log handlers. If f is a function with the appropriate signature, -// HandlerFunc(f) is a Handler object that calls f. -type HandlerFunc func(*Entry) error - -// HandleLog calls f(e). -func (f HandlerFunc) HandleLog(e *Entry) error { - return f(e) -} - -// Handler is used to handle log events, outputting them to -// stdio or sending them to remote services. See the "handlers" -// directory for implementations. -// -// It is left up to Handlers to implement thread-safety. -type Handler interface { - HandleLog(*Entry) error -} - -// Logger represents a logger with configurable Level and Handler. -type Logger struct { - Handler Handler - Level Level -} - -// WithFields returns a new entry with `fields` set. -func (l *Logger) WithFields(fields Fielder) *Entry { - return NewEntry(l).WithFields(fields.Fields()) -} - -// WithField returns a new entry with the `key` and `value` set. -// -// Note that the `key` should not have spaces in it - use camel -// case or underscores -func (l *Logger) WithField(key string, value interface{}) *Entry { - return NewEntry(l).WithField(key, value) -} - -// WithDuration returns a new entry with the "duration" field set -// to the given duration in milliseconds. -func (l *Logger) WithDuration(d time.Duration) *Entry { - return NewEntry(l).WithDuration(d) -} - -// WithError returns a new entry with the "error" set to `err`. -func (l *Logger) WithError(err error) *Entry { - return NewEntry(l).WithError(err) -} - -// Debug level message. -func (l *Logger) Debug(msg string) { - NewEntry(l).Debug(msg) -} - -// Info level message. -func (l *Logger) Info(msg string) { - NewEntry(l).Info(msg) -} - -// Warn level message. -func (l *Logger) Warn(msg string) { - NewEntry(l).Warn(msg) -} - -// Error level message. -func (l *Logger) Error(msg string) { - NewEntry(l).Error(msg) -} - -// Fatal level message, followed by an exit. -func (l *Logger) Fatal(msg string) { - NewEntry(l).Fatal(msg) -} - -// Debugf level formatted message. -func (l *Logger) Debugf(msg string, v ...interface{}) { - NewEntry(l).Debugf(msg, v...) -} - -// Infof level formatted message. -func (l *Logger) Infof(msg string, v ...interface{}) { - NewEntry(l).Infof(msg, v...) -} - -// Warnf level formatted message. -func (l *Logger) Warnf(msg string, v ...interface{}) { - NewEntry(l).Warnf(msg, v...) -} - -// Errorf level formatted message. -func (l *Logger) Errorf(msg string, v ...interface{}) { - NewEntry(l).Errorf(msg, v...) -} - -// Fatalf level formatted message, followed by an exit. -func (l *Logger) Fatalf(msg string, v ...interface{}) { - NewEntry(l).Fatalf(msg, v...) -} - -// Trace returns a new entry with a Stop method to fire off -// a corresponding completion log, useful with defer. -func (l *Logger) Trace(msg string) *Entry { - return NewEntry(l).Trace(msg) -} - -// log the message, invoking the handler. We clone the entry here -// to bypass the overhead in Entry methods when the level is not -// met. -func (l *Logger) log(level Level, e *Entry, msg string) { - if level < l.Level { - return - } - - if err := l.Handler.HandleLog(e.finalize(level, msg)); err != nil { - stdlog.Printf("error logging: %s", err) - } -} diff --git a/std/log/pkg.go b/std/log/pkg.go deleted file mode 100644 index e0b54d33..00000000 --- a/std/log/pkg.go +++ /dev/null @@ -1,151 +0,0 @@ -package log - -import ( - "bytes" - "fmt" - "log" - "sort" - "time" -) - -// field used for sorting. -type field struct { - Name string - Value interface{} -} - -// by sorts fields by name. -type byName []field - -func (a byName) Len() int { return len(a) } -func (a byName) Swap(i, j int) { a[i], a[j] = a[j], a[i] } -func (a byName) Less(i, j int) bool { return a[i].Name < a[j].Name } - -// handleStdLog outpouts to the stlib log. -func handleStdLog(e *Entry) error { - level := levelNames[e.Level] - - var fields []field - - for k, v := range e.Fields { - fields = append(fields, field{k, v}) - } - - sort.Sort(byName(fields)) - - var b bytes.Buffer - fmt.Fprintf(&b, "%5s %-25s", level, e.Message) - - for _, f := range fields { - fmt.Fprintf(&b, " %s=%v", f.Name, f.Value) - } - - log.Println(b.String()) - - return nil -} - -// singletons ftw? -var Log Interface = &Logger{ - Handler: HandlerFunc(handleStdLog), - Level: InfoLevel, -} - -// SetHandler sets the handler. This is not thread-safe. -// The default handler outputs to the stdlib log. -func SetHandler(h Handler) { - if logger, ok := Log.(*Logger); ok { - logger.Handler = h - } -} - -// SetLevel sets the log level. This is not thread-safe. -func SetLevel(l Level) { - if logger, ok := Log.(*Logger); ok { - logger.Level = l - } -} - -// SetLevelFromString sets the log level from a string, panicing when invalid. This is not thread-safe. -func SetLevelFromString(s string) { - if logger, ok := Log.(*Logger); ok { - logger.Level = MustParseLevel(s) - } -} - -// WithFields returns a new entry with `fields` set. -func WithFields(fields Fielder) *Entry { - return Log.WithFields(fields) -} - -// WithField returns a new entry with the `key` and `value` set. -func WithField(key string, value interface{}) *Entry { - return Log.WithField(key, value) -} - -// WithDuration returns a new entry with the "duration" field set -// to the given duration in milliseconds. -func WithDuration(d time.Duration) *Entry { - return Log.WithDuration(d) -} - -// WithError returns a new entry with the "error" set to `err`. -func WithError(err error) *Entry { - return Log.WithError(err) -} - -// Debug level message. -func Debug(msg string) { - Log.Debug(msg) -} - -// Info level message. -func Info(msg string) { - Log.Info(msg) -} - -// Warn level message. -func Warn(msg string) { - Log.Warn(msg) -} - -// Error level message. -func Error(msg string) { - Log.Error(msg) -} - -// Fatal level message, followed by an exit. -func Fatal(msg string) { - Log.Fatal(msg) -} - -// Debugf level formatted message. -func Debugf(msg string, v ...interface{}) { - Log.Debugf(msg, v...) -} - -// Infof level formatted message. -func Infof(msg string, v ...interface{}) { - Log.Infof(msg, v...) -} - -// Warnf level formatted message. -func Warnf(msg string, v ...interface{}) { - Log.Warnf(msg, v...) -} - -// Errorf level formatted message. -func Errorf(msg string, v ...interface{}) { - Log.Errorf(msg, v...) -} - -// Fatalf level formatted message, followed by an exit. -func Fatalf(msg string, v ...interface{}) { - Log.Fatalf(msg, v...) -} - -// Trace returns a new entry with a Stop method to fire off -// a corresponding completion log, useful with defer. -func Trace(msg string) *Entry { - return Log.Trace(msg) -} diff --git a/std/log/slog.go b/std/log/slog.go new file mode 100644 index 00000000..173c42bb --- /dev/null +++ b/std/log/slog.go @@ -0,0 +1,116 @@ +package log + +import ( + "context" + "io" + "log/slog" + "runtime" +) + +type Logger struct { + slog *slog.Logger + level Level +} + +type Tag interface { + String() string +} + +func NewText(w io.Writer) *Logger { + return &Logger{ + slog: slog.New(slog.NewTextHandler(w, &slog.HandlerOptions{ + Level: slog.Level(LevelTrace), + ReplaceAttr: replaceAttr, + })), + level: LevelInfo, + } +} + +func NewJson(w io.Writer) *Logger { + return &Logger{ + slog: slog.New(slog.NewJSONHandler(w, &slog.HandlerOptions{ + Level: slog.Level(LevelTrace), + ReplaceAttr: replaceAttr, + })), + level: LevelInfo, + } +} + +// SetLevel sets the logging level and returns the previous level. +func (l *Logger) SetLevel(level Level) (prev Level) { + prev = l.level + l.level = level + return +} + +// Level returns the current logging level. +func (l *Logger) Level() Level { + return l.level +} + +// Generic level message. +func (l *Logger) log(t any, msg string, level Level, v ...any) { + if l.level > level { + return + } + + // Get source information if debug logs + if level <= LevelDebug { + if pc, _, _, ok := runtime.Caller(2); ok { + if f := runtime.FuncForPC(pc); f != nil { + v = append(v, slog.SourceKey, f.Name()) + } + } + } + + // Get tag + if t != nil { + if tag, ok := t.(Tag); ok { + v = append([]any{"tag", tag.String()}, v...) + } else { + v = append([]any{"tag", t}, v...) + } + } + + // Log the message + l.slog.Log(context.Background(), slog.Level(level), msg, v...) +} + +// Trace level message. +func (l *Logger) Trace(t any, msg string, v ...any) { + l.log(t, msg, LevelTrace, v...) +} + +// Debug level message. +func (l *Logger) Debug(t any, msg string, v ...any) { + l.log(t, msg, LevelDebug, v...) +} + +// Info level message. +func (l *Logger) Info(t any, msg string, v ...any) { + l.log(t, msg, LevelInfo, v...) +} + +// Warn level message. +func (l *Logger) Warn(t any, msg string, v ...any) { + l.log(t, msg, LevelWarn, v...) +} + +// Error level message. +func (l *Logger) Error(t any, msg string, v ...any) { + l.log(t, msg, LevelError, v...) +} + +// Fatal level message, followed by an exit. +func (l *Logger) Fatal(t any, msg string, v ...any) { + l.log(t, msg, LevelFatal, v...) +} + +func replaceAttr(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.LevelKey { + level := a.Value.Any().(slog.Level) + a.Value = slog.StringValue(Level(level).String()) + } + + return a +} diff --git a/std/log/text.go b/std/log/text.go deleted file mode 100644 index c588db9c..00000000 --- a/std/log/text.go +++ /dev/null @@ -1,77 +0,0 @@ -package log - -import ( - "fmt" - "io" - "os" - "sync" - "time" -) - -// Default handler outputting to stderr. -var Default = NewText(os.Stderr) - -// start time. -var start = time.Now() - -// colors. -const ( - none = 0 - red = 31 - green = 32 - yellow = 33 - blue = 34 - gray = 37 -) - -// Colors mapping. -var Colors = [...]int{ - DebugLevel: gray, - InfoLevel: blue, - WarnLevel: yellow, - ErrorLevel: red, - FatalLevel: red, -} - -// Strings mapping. -var Strings = [...]string{ - DebugLevel: "DEBUG", - InfoLevel: "INFO", - WarnLevel: "WARN", - ErrorLevel: "ERROR", - FatalLevel: "FATAL", -} - -// Handler implementation. -type TextHandler struct { - mu sync.Mutex - Writer io.Writer -} - -// NewText handler. -func NewText(w io.Writer) Handler { - return &TextHandler{ - Writer: w, - } -} - -// HandleLog implements Handler. -func (h *TextHandler) HandleLog(e *Entry) error { - color := Colors[e.Level] - level := Strings[e.Level] - names := e.Fields.Names() - - h.mu.Lock() - defer h.mu.Unlock() - - ts := time.Since(start) / time.Second - fmt.Fprintf(h.Writer, "\033[%dm%6s\033[0m[%04d] %-25s", color, level, ts, e.Message) - - for _, name := range names { - fmt.Fprintf(h.Writer, " \033[%dm%s\033[0m=%v", color, name, e.Fields.Get(name)) - } - - fmt.Fprintln(h.Writer) - - return nil -} diff --git a/tools/catchunks.go b/tools/catchunks.go index 3eef19f4..f8b8a085 100644 --- a/tools/catchunks.go +++ b/tools/catchunks.go @@ -27,8 +27,6 @@ func (cc *CatChunks) usage() { } func (cc *CatChunks) run() { - log.SetLevel(log.InfoLevel) - if len(cc.args) < 2 { cc.usage() os.Exit(3) diff --git a/tools/pingclient.go b/tools/pingclient.go index af374fb5..fc51e131 100644 --- a/tools/pingclient.go +++ b/tools/pingclient.go @@ -121,8 +121,6 @@ func (pc *PingClient) stats() { } func (pc *PingClient) run() { - log.SetLevel(log.InfoLevel) - flagset := flag.NewFlagSet("ping", flag.ExitOnError) flagset.Usage = func() { pc.usage() diff --git a/tools/pingserver.go b/tools/pingserver.go index ff7d8cb9..5ae995ca 100644 --- a/tools/pingserver.go +++ b/tools/pingserver.go @@ -37,8 +37,6 @@ func (ps *PingServer) usage() { } func (ps *PingServer) run() { - log.SetLevel(log.InfoLevel) - if len(ps.args) < 2 { ps.usage() os.Exit(3) diff --git a/tools/putchunks.go b/tools/putchunks.go index 08162253..b7b9031d 100644 --- a/tools/putchunks.go +++ b/tools/putchunks.go @@ -29,8 +29,6 @@ func (pc *PutChunks) usage() { } func (pc *PutChunks) run() { - log.SetLevel(log.InfoLevel) - if len(pc.args) < 2 { pc.usage() os.Exit(3) From b1b0d3688a7afc2a425e50da91dd15fcc7d86b80 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Mon, 13 Jan 2025 21:13:44 +0000 Subject: [PATCH 02/12] slog: fix src output --- std/log/slog.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/std/log/slog.go b/std/log/slog.go index 173c42bb..e1af74dd 100644 --- a/std/log/slog.go +++ b/std/log/slog.go @@ -55,7 +55,7 @@ func (l *Logger) log(t any, msg string, level Level, v ...any) { } // Get source information if debug logs - if level <= LevelDebug { + if l.level <= LevelDebug { if pc, _, _, ok := runtime.Caller(2); ok { if f := runtime.FuncForPC(pc); f != nil { v = append(v, slog.SourceKey, f.Name()) From c6b163939e8f952d928d132beab9be6268477c56 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Mon, 13 Jan 2025 22:07:54 +0000 Subject: [PATCH 03/12] fw: log adapt --- fw/core/logger.go | 68 ------------------------- fw/executor/profiler.go | 10 ++-- fw/executor/yanfd.go | 14 ++--- fw/face/impl/syscalls_darwin.go | 2 +- fw/face/impl/syscalls_linux.go | 2 +- fw/face/internal-transport.go | 10 ++-- fw/face/link-service.go | 14 ++--- fw/face/multicast-udp-transport.go | 12 ++--- fw/face/ndnlp-link-service.go | 24 +++++---- fw/face/null-link-service.go | 2 +- fw/face/table.go | 4 +- fw/face/tcp-listener.go | 6 +-- fw/face/udp-listener.go | 10 ++-- fw/face/unicast-tcp-transport.go | 12 ++--- fw/face/unicast-udp-transport.go | 8 +-- fw/face/unix-stream-listener.go | 12 ++--- fw/face/unix-stream-transport.go | 8 +-- fw/face/web-socket-listener.go | 2 +- fw/face/web-socket-transport.go | 10 ++-- fw/fw/bestroute.go | 14 ++--- fw/fw/multicast.go | 12 ++--- fw/fw/strategy-loader.go | 2 +- fw/fw/thread.go | 56 ++++++++++---------- fw/mgmt/cs.go | 8 +-- fw/mgmt/face.go | 22 ++++---- fw/mgmt/fib.go | 2 +- fw/mgmt/forwarder-status.go | 2 +- fw/mgmt/helpers.go | 2 +- fw/mgmt/nlsr_readvertiser.go | 10 ++-- fw/mgmt/strategy-choice.go | 12 ++--- fw/mgmt/thread.go | 28 +++++----- fw/table/init.go | 6 +-- fw/table/pit-cs-tree.go | 2 +- std/examples/low-level/consumer/main.go | 11 ++-- std/examples/low-level/producer/main.go | 16 +++--- std/examples/low-level/svs/main.go | 12 ++--- std/log/level.go | 2 + std/log/slog.go | 38 ++++++++------ 38 files changed, 212 insertions(+), 275 deletions(-) diff --git a/fw/core/logger.go b/fw/core/logger.go index e0a2f631..1619a8b5 100644 --- a/fw/core/logger.go +++ b/fw/core/logger.go @@ -8,10 +8,7 @@ package core import ( - "fmt" "os" - "strconv" - "strings" "github.com/named-data/ndnd/std/log" ) @@ -49,68 +46,3 @@ func CloseLogger() { logFileObj.Close() } } - -func generateLogMessage(module interface{}, components ...interface{}) string { - var message strings.Builder - message.WriteString(fmt.Sprintf("[%v] ", module)) - for _, component := range components { - switch v := component.(type) { - case string: - message.WriteString(v) - case int: - message.WriteString(strconv.Itoa(v)) - case int8: - message.WriteString(strconv.FormatInt(int64(v), 10)) - case int16: - message.WriteString(strconv.FormatInt(int64(v), 10)) - case int32: - message.WriteString(strconv.FormatInt(int64(v), 10)) - case int64: - message.WriteString(strconv.FormatInt(v, 10)) - case uint: - message.WriteString(strconv.FormatUint(uint64(v), 10)) - case uint8: - message.WriteString(strconv.FormatUint(uint64(v), 10)) - case uint16: - message.WriteString(strconv.FormatUint(uint64(v), 10)) - case uint32: - message.WriteString(strconv.FormatUint(uint64(v), 10)) - case uint64: - message.WriteString(strconv.FormatUint(v, 10)) - case uintptr: - message.WriteString(strconv.FormatUint(uint64(v), 10)) - case bool: - message.WriteString(strconv.FormatBool(v)) - case error: - message.WriteString(v.Error()) - default: - message.WriteString(fmt.Sprintf("%v", component)) - } - } - return message.String() -} - -// LogFatal logs a message at the FATAL level. Note: Fatal will let the program exit -func LogFatal(module interface{}, components ...interface{}) { - log.Fatal(generateLogMessage(module, components...)) -} - -// LogError logs a message at the ERROR level. -func LogError(module interface{}, components ...interface{}) { - log.Error(generateLogMessage(module, components...)) -} - -// LogWarn logs a message at the WARN level. -func LogWarn(module interface{}, components ...interface{}) { - log.Warn(generateLogMessage(module, components...)) -} - -// LogDebug logs a message at the DEBUG level. -func LogDebug(module interface{}, components ...interface{}) { - log.Debug(generateLogMessage(module, components...)) -} - -// LogTrace logs a message at the TRACE level (really just additional DEBUG messages). -func LogTrace(module interface{}, components ...interface{}) { - log.Trace(generateLogMessage(module, components...)) -} diff --git a/fw/executor/profiler.go b/fw/executor/profiler.go index 6738a1c7..89718e97 100644 --- a/fw/executor/profiler.go +++ b/fw/executor/profiler.go @@ -26,7 +26,7 @@ func (p *Profiler) Start() (err error) { if p.config.CpuProfile != "" { p.cpuFile, err = os.Create(p.config.CpuProfile) if err != nil { - core.LogFatal(p, "Unable to open output file for CPU profile: ", err) + core.Log.Fatal(p, "Unable to open output file for CPU profile", "err", err) } core.Log.Info(p, "Profiling CPU", "out", p.config.CpuProfile) @@ -46,10 +46,10 @@ func (p *Profiler) Stop() { if p.block != nil { blockProfileFile, err := os.Create(p.config.BlockProfile) if err != nil { - core.LogFatal(p, "Unable to open output file for block profile: ", err) + core.Log.Fatal(p, "Unable to open output file for block profile", "err", err) } if err := p.block.WriteTo(blockProfileFile, 0); err != nil { - core.LogFatal(p, "Unable to write block profile: ", err) + core.Log.Fatal(p, "Unable to write block profile", "err", err) } blockProfileFile.Close() } @@ -57,14 +57,14 @@ func (p *Profiler) Stop() { if p.config.MemProfile != "" { memProfileFile, err := os.Create(p.config.MemProfile) if err != nil { - core.LogFatal(p, "Unable to open output file for memory profile: ", err) + core.Log.Fatal(p, "Unable to open output file for memory profile", "err", err) } defer memProfileFile.Close() core.Log.Info(p, "Profiling memory", "out", p.config.MemProfile) runtime.GC() if err := pprof.WriteHeapProfile(memProfileFile); err != nil { - core.LogFatal(p, "Unable to write memory profile: ", err) + core.Log.Fatal(p, "Unable to write memory profile", "err", err) } } diff --git a/fw/executor/yanfd.go b/fw/executor/yanfd.go index 190cf5b7..8de354f2 100644 --- a/fw/executor/yanfd.go +++ b/fw/executor/yanfd.go @@ -96,7 +96,7 @@ func (y *YaNFD) Start() { // Create forwarding threads if fw.NumFwThreads < 1 || fw.NumFwThreads > fw.MaxFwThreads { - core.LogFatal(y, "Number of forwarding threads must be in range [1, ", fw.MaxFwThreads, "]") + core.Log.Fatal(y, "Number of forwarding threads out of range", "range", fmt.Sprintf("[1, %d]", fw.MaxFwThreads)) os.Exit(2) } fw.Threads = make([]*fw.Thread, fw.NumFwThreads) @@ -164,7 +164,7 @@ func (y *YaNFD) Start() { if core.GetConfig().Faces.Udp.EnabledMulticast { ifaces, err := net.Interfaces() if err != nil { - core.LogError(y, "Unable to access network interfaces: ", err) + core.Log.Error(y, "Unable to access network interfaces", "err", err) } for _, iface := range ifaces { @@ -191,7 +191,7 @@ func (y *YaNFD) Start() { if !addr.(*net.IPNet).IP.IsLoopback() { multicastUDPTransport, err := face.MakeMulticastUDPTransport(defn.DecodeURIString(uri)) if err != nil { - core.LogError(y, "Unable to create MulticastUDPTransport for ", uri, ": ", err) + core.Log.Error(y, "Unable to create MulticastUDPTransport", "uri", uri, "err", err) continue } @@ -211,12 +211,12 @@ func (y *YaNFD) Start() { if core.GetConfig().Faces.Unix.Enabled { unixListener, err := face.MakeUnixStreamListener(defn.MakeUnixFaceURI(face.UnixSocketPath)) if err != nil { - core.LogError(y, "Unable to create Unix stream listener at ", face.UnixSocketPath, ": ", err) + core.Log.Error(y, "Unable to create Unix stream listener", "path", face.UnixSocketPath, "err", err) } else { listenerCount++ go unixListener.Run() y.unixListener = unixListener - core.Log.Info(y, "Created Unix stream listener", "uri", face.UnixSocketPath) + core.Log.Info(y, "Created unix stream listener", "uri", face.UnixSocketPath) } } @@ -232,7 +232,7 @@ func (y *YaNFD) Start() { wsListener, err := face.NewWebSocketListener(cfg) if err != nil { - core.LogError(y, "Unable to create WebSocket Listener", "cfg", cfg, "err", err) + core.Log.Error(y, "Unable to create WebSocket Listener", "cfg", cfg, "err", err) } else { listenerCount++ go wsListener.Run() @@ -243,7 +243,7 @@ func (y *YaNFD) Start() { // Check if any faces were created if listenerCount <= 0 { - core.LogFatal(y, "No face or listener is successfully created. Quit.") + core.Log.Fatal(y, "No face or listener is successfully created. Quit.") os.Exit(2) } } diff --git a/fw/face/impl/syscalls_darwin.go b/fw/face/impl/syscalls_darwin.go index 9950b0d0..59e8eaa7 100644 --- a/fw/face/impl/syscalls_darwin.go +++ b/fw/face/impl/syscalls_darwin.go @@ -23,7 +23,7 @@ func SyscallGetSocketSendQueueSize(c syscall.RawConn) uint64 { var err error val, err = unix.GetsockoptInt(int(fd), unix.SOL_SOCKET, unix.SO_NWRITE) if err != nil { - core.LogWarn("Face-Syscall", "Unable to get size of socket send queue for fd=", fd, ": ", err) + core.Log.Warn("Face-Syscall", "Unable to get size of socket send queue for fd", "fd", fd, "err", err) val = 0 } }) diff --git a/fw/face/impl/syscalls_linux.go b/fw/face/impl/syscalls_linux.go index 47034424..8ef49262 100644 --- a/fw/face/impl/syscalls_linux.go +++ b/fw/face/impl/syscalls_linux.go @@ -23,7 +23,7 @@ func SyscallGetSocketSendQueueSize(c syscall.RawConn) uint64 { var err error val, err = unix.IoctlGetInt(int(fd), unix.SIOCOUTQ) if err != nil { - core.LogWarn("Face-Syscall", "Unable to get size of socket send queue for fd=", fd, ": ", err) + core.Log.Warn(nil, "Unable to get size of socket send queue", "fd", fd, "err", err) val = 0 } }) diff --git a/fw/face/internal-transport.go b/fw/face/internal-transport.go index 54e35b19..135d09fa 100644 --- a/fw/face/internal-transport.go +++ b/fw/face/internal-transport.go @@ -84,7 +84,7 @@ func (t *InternalTransport) Send(lpPkt *spec.LpPacket) { encoder.Init(pkt) lpPacketWire := encoder.Encode(pkt) if lpPacketWire == nil { - core.LogWarn(t, "Unable to encode block to send - DROP") + core.Log.Warn(t, "Unable to encode block to send") return } t.sendQueue <- lpPacketWire.Join() @@ -95,13 +95,13 @@ func (t *InternalTransport) Receive() *spec.LpPacket { for frame := range t.recvQueue { packet, _, err := spec.ReadPacket(enc.NewBufferReader(frame)) if err != nil { - core.LogWarn(t, "Unable to decode received block - DROP: ", err) + core.Log.Warn(t, "Unable to decode received block", "err", err) continue } lpPkt := packet.LpPacket if packet.LpPacket == nil || lpPkt.Fragment.Length() == 0 { - core.LogWarn(t, "Received empty fragment - DROP") + core.Log.Warn(t, "Received empty fragment") continue } @@ -113,7 +113,7 @@ func (t *InternalTransport) Receive() *spec.LpPacket { func (t *InternalTransport) sendFrame(frame []byte) { if len(frame) > t.MTU() { - core.LogWarn(t, "Attempted to send frame larger than MTU - DROP") + core.Log.Warn(t, "Attempted to send frame larger than MTU") return } @@ -127,7 +127,7 @@ func (t *InternalTransport) sendFrame(frame []byte) { func (t *InternalTransport) runReceive() { for frame := range t.sendQueue { if len(frame) > defn.MaxNDNPacketSize { - core.LogWarn(t, "Component trying to send too much data - DROP") + core.Log.Warn(t, "Caller trying to send too much data") continue } diff --git a/fw/face/link-service.go b/fw/face/link-service.go index 062e51ec..2264d7b3 100644 --- a/fw/face/link-service.go +++ b/fw/face/link-service.go @@ -212,10 +212,10 @@ func (l *linkServiceBase) SendPacket(out dispatch.OutPkt) { select { case l.sendQueue <- out: // Packet queued successfully - core.LogTrace(l, "Queued packet for Link Service") + core.Log.Trace(l, "Queued packet for link service") default: // Drop packet due to congestion - core.LogDebug(l, "Dropped packet due to congestion") + core.Log.Debug(l, "Dropped packet due to congestion") // TODO: Signal congestion } @@ -231,7 +231,7 @@ func (l *linkServiceBase) dispatchInterest(pkt *defn.Pkt) { // Hash name to thread thread := fw.HashNameToFwThread(pkt.Name) - core.LogTrace(l, "Dispatched Interest to thread ", thread) + core.Log.Trace(l, "Dispatched Interest", "thread", thread) dispatch.GetFWThread(thread).QueueInterest(pkt) } @@ -248,11 +248,11 @@ func (l *linkServiceBase) dispatchData(pkt *defn.Pkt) { thread := binary.BigEndian.Uint16(pkt.PitToken) fwThread := dispatch.GetFWThread(int(thread)) if fwThread == nil { - core.LogError(l, "Invalid PIT token attached to Data packet - DROP") + core.Log.Error(l, "Invalid PIT token attached to Data packet") return } - core.LogTrace(l, "Dispatched Data to thread ", thread) + core.Log.Trace(l, "Dispatched Data", "thread", thread) fwThread.QueueData(pkt) return } @@ -263,7 +263,7 @@ func (l *linkServiceBase) dispatchData(pkt *defn.Pkt) { if l.Scope() == defn.Local { for i, match := range fw.HashNameToAllPrefixFwThreads(pkt.Name) { if match { - core.LogTrace(l, "Prefix dispatched local-origin Data packet to thread ", i) + core.Log.Trace(l, "Prefix dispatched local-origin Data", "thread", i) dispatch.GetFWThread(i).QueueData(pkt) } } @@ -272,6 +272,6 @@ func (l *linkServiceBase) dispatchData(pkt *defn.Pkt) { // Only exact-match for now (no CanBePrefix) thread := fw.HashNameToFwThread(pkt.Name) - core.LogTrace(l, "Dispatched Data to thread ", thread) + core.Log.Trace(l, "Dispatched Data", "thread", thread) dispatch.GetFWThread(thread).QueueData(pkt) } diff --git a/fw/face/multicast-udp-transport.go b/fw/face/multicast-udp-transport.go index dd3dd52a..175387e2 100644 --- a/fw/face/multicast-udp-transport.go +++ b/fw/face/multicast-udp-transport.go @@ -124,7 +124,7 @@ func (t *MulticastUDPTransport) SetPersistency(persistency spec_mgmt.Persistency func (t *MulticastUDPTransport) GetSendQueueSize() uint64 { rawConn, err := t.recvConn.SyscallConn() if err != nil { - core.LogWarn(t, "Unable to get raw connection to get socket length: ", err) + core.Log.Warn(t, "Unable to get raw connection to get socket length", "err", err) } return impl.SyscallGetSocketSendQueueSize(rawConn) } @@ -135,19 +135,19 @@ func (t *MulticastUDPTransport) sendFrame(frame []byte) { } if len(frame) > t.MTU() { - core.LogWarn(t, "Attempted to send frame larger than MTU - DROP") + core.Log.Warn(t, "Attempted to send frame larger than MTU") return } _, err := t.sendConn.Write(frame) if err != nil { - core.LogWarn(t, "Unable to send on socket - DROP") + core.Log.Warn(t, "Unable to send on socket") // Re-create the socket if connection is still running if t.running.Load() { err = t.connectSend() if err != nil { - core.LogError(t, "Unable to re-create send connection: ", err) + core.Log.Error(t, "Unable to re-create send connection", "err", err) return } } @@ -169,10 +169,10 @@ func (t *MulticastUDPTransport) runReceive() { }) if err != nil && t.running.Load() { // Re-create the socket if connection is still running - core.LogWarn(t, "Unable to read from socket (", err, ") - Face DOWN") + core.Log.Warn(t, "Unable to read from socket - Face DOWN", "err", err) err = t.connectRecv() if err != nil { - core.LogError(t, "Unable to re-create receive connection: ", err) + core.Log.Error(t, "Unable to re-create receive connection", "err", err) return } } diff --git a/fw/face/ndnlp-link-service.go b/fw/face/ndnlp-link-service.go index 021e4758..e8581b72 100644 --- a/fw/face/ndnlp-link-service.go +++ b/fw/face/ndnlp-link-service.go @@ -132,7 +132,7 @@ func (l *NDNLPLinkService) computeHeaderOverhead() { // Run starts the face and associated goroutines func (l *NDNLPLinkService) Run(initial []byte) { if l.transport == nil { - core.LogError(l, "Unable to start face due to unset transport") + core.Log.Error(l, "Unable to start face due to unset transport") return } @@ -188,7 +188,7 @@ func sendPacket(l *NDNLPLinkService, out dispatch.OutPkt) { // Congestion marking congestionMark := pkt.CongestionMark // from upstream if l.checkCongestion(wire) && congestionMark == nil { - core.LogWarn(l, "Marking congestion") + core.Log.Warn(l, "Marking congestion") congestionMark = utils.IdPtr(uint64(1)) // ours } @@ -224,7 +224,7 @@ func sendPacket(l *NDNLPLinkService, out dispatch.OutPkt) { frag, err := reader.ReadWire(readSize) if err != nil { - core.LogFatal(l, "Unexpected Wire reading error") + core.Log.Fatal(l, "Unexpected wire reading error") } // Create fragment with sequence and index @@ -266,7 +266,7 @@ func sendPacket(l *NDNLPLinkService, out dispatch.OutPkt) { encoder.Init(pkt) frameWire := encoder.Encode(pkt) if frameWire == nil { - core.LogError(l, "Unable to encode fragment - DROP") + core.Log.Error(l, "Unable to encode fragment - DROP") break } @@ -292,7 +292,7 @@ func (l *NDNLPLinkService) handleIncomingFrame(frame []byte) { L2, err := readPacketUnverified(enc.NewBufferReader(wire)) if err != nil { - core.LogError(l, err) + core.Log.Error(l, "Unable to decode incoming frame", "err", err) return } @@ -307,7 +307,7 @@ func (l *NDNLPLinkService) handleIncomingFrame(frame []byte) { // If there is no fragment, then IDLE packet, drop. if len(fragment) == 0 { - core.LogTrace(l, "IDLE frame - DROP") + core.Log.Trace(l, "IDLE frame - DROP") return } @@ -323,7 +323,7 @@ func (l *NDNLPLinkService) handleIncomingFrame(frame []byte) { } baseSequence := *LP.Sequence - fragIndex - core.LogTrace(l, "Received fragment ", fragIndex, " of ", fragCount, " for ", baseSequence) + core.Log.Trace(l, "Received fragment", "index", fragIndex, "count", fragCount, "base", baseSequence) if fragIndex == 0 && fragCount == 1 { // Bypass reassembly since only one fragment } else { @@ -334,7 +334,7 @@ func (l *NDNLPLinkService) handleIncomingFrame(frame []byte) { } } } else if LP.FragCount != nil || LP.FragIndex != nil { - core.LogWarn(l, "Received NDNLPv2 frame containing fragmentation fields but reassembly disabled - DROP") + core.Log.Warn(l, "Received NDNLPv2 frame with fragmentation fields but reassembly disabled - DROP") return } @@ -380,7 +380,7 @@ func (l *NDNLPLinkService) handleIncomingFrame(frame []byte) { l.nInData++ l.dispatchData(pkt) } else { - core.LogError(l, "Attempted dispatch packet of unknown type") + core.Log.Error(l, "Received packet of unknown type") } } @@ -413,13 +413,15 @@ func (l *NDNLPLinkService) reassemble( // Validate fragCount has not changed if fragCount != uint64(len(buffer)) { - core.LogWarn(l, "Received fragment count ", fragCount, " does not match expected count ", len(buffer), " for base sequence ", baseSequence, " - DROP") + core.Log.Warn(l, "Received fragment count does not match expected count", + "count", fragCount, "expected", len(buffer), "base", baseSequence) return nil } // Validate fragIndex is valid if fragIndex >= uint64(len(buffer)) { - core.LogWarn(l, "Received fragment index ", fragIndex, " out of range for base sequence ", baseSequence, " - DROP") + core.Log.Warn(l, "Received fragment index out of range", + "index", fragIndex, "count", fragCount, "base", baseSequence) return nil } diff --git a/fw/face/null-link-service.go b/fw/face/null-link-service.go index ea9af3ec..75251df4 100644 --- a/fw/face/null-link-service.go +++ b/fw/face/null-link-service.go @@ -46,5 +46,5 @@ func (l *NullLinkService) Run(initial []byte) { func (l *NullLinkService) handleIncomingFrame(frame []byte) { // Do nothing - core.LogDebug(l, "Received frame on null link service - DROP") + core.Log.Debug(l, "Received frame on null link service - DROP") } diff --git a/fw/face/table.go b/fw/face/table.go index ecfd8e59..82b11579 100644 --- a/fw/face/table.go +++ b/fw/face/table.go @@ -43,7 +43,7 @@ func (t *Table) Add(face LinkService) { face.SetFaceID(faceID) t.faces.Store(faceID, face) dispatch.AddFace(faceID, face) - core.LogDebug(t, "Registered FaceID=", faceID) + core.Log.Debug(t, "Registered face", "faceid", faceID) } // Get gets the face with the specified ID (if any) from the face table. @@ -84,7 +84,7 @@ func (t *Table) Remove(id uint64) { t.faces.Delete(id) dispatch.RemoveFace(id) table.Rib.CleanUpFace(id) - core.Log.Info(t, "Unregistered FaceID", "faceid", id) + core.Log.Info(t, "Unregistered face", "faceid", id) } // ExpirationHandler stops the faces that have expired diff --git a/fw/face/tcp-listener.go b/fw/face/tcp-listener.go index bbd9beef..33fd9a74 100644 --- a/fw/face/tcp-listener.go +++ b/fw/face/tcp-listener.go @@ -61,7 +61,7 @@ func (l *TCPListener) Run() { var err error l.conn, err = listenConfig.Listen(context.Background(), l.localURI.Scheme(), remote) if err != nil { - core.LogError(l, "Unable to start TCP listener: ", err) + core.Log.Error(l, "Unable to start TCP listener", "err", err) return } @@ -72,13 +72,13 @@ func (l *TCPListener) Run() { if errors.Is(err, net.ErrClosed) { return } - core.LogWarn(l, "Unable to accept connection: ", err) + core.Log.Warn(l, "Unable to accept connection", "err", err) continue } newTransport, err := AcceptUnicastTCPTransport(remoteConn, l.localURI, mgmt_2022.PersistencyPersistent) if err != nil { - core.LogError(l, "Failed to create new unicast TCP transport: ", err) + core.Log.Error(l, "Failed to create new unicast TCP transport", "err", err) continue } diff --git a/fw/face/udp-listener.go b/fw/face/udp-listener.go index 989ed39a..5dc647d7 100644 --- a/fw/face/udp-listener.go +++ b/fw/face/udp-listener.go @@ -62,7 +62,7 @@ func (l *UDPListener) Run() { var err error l.conn, err = listenConfig.ListenPacket(context.Background(), l.localURI.Scheme(), remote) if err != nil { - core.LogError(l, "Unable to start UDP listener: ", err) + core.Log.Error(l, "Unable to start UDP listener", "err", err) return } @@ -74,14 +74,14 @@ func (l *UDPListener) Run() { if errors.Is(err, net.ErrClosed) { return } - core.LogWarn(l, "Unable to read from socket (", err, ") - DROP ") + core.Log.Warn(l, "Unable to read from socket", "err", err) return } // Construct remote URI remoteURI := defn.DecodeURIString(fmt.Sprintf("udp://%s", remoteAddr)) if remoteURI == nil || !remoteURI.IsCanonical() { - core.LogWarn(l, "Unable to create face from ", remoteURI, ": remote URI is not canonical") + core.Log.Warn(l, "Unable to create face remote URI is not canonical", "uri", remoteURI) continue } @@ -89,14 +89,14 @@ func (l *UDPListener) Run() { // This is probably because it was received too fast. // For now just drop the frame, ideally we should pass it to face. if face := FaceTable.GetByURI(remoteURI); face != nil { - core.LogTrace(l, "Received frame for existing face ", face) + core.Log.Trace(l, "Received frame for existing", "face", face) continue } // If frame received here, must be for new remote endpoint newTransport, err := MakeUnicastUDPTransport(remoteURI, l.localURI, spec_mgmt.PersistencyOnDemand) if err != nil { - core.LogError(l, "Failed to create new unicast UDP transport: ", err) + core.Log.Error(l, "Failed to create new unicast UDP transport", "err", err) continue } diff --git a/fw/face/unicast-tcp-transport.go b/fw/face/unicast-tcp-transport.go index 52b2433d..e7b3df12 100644 --- a/fw/face/unicast-tcp-transport.go +++ b/fw/face/unicast-tcp-transport.go @@ -103,7 +103,7 @@ func AcceptUnicastTCPTransport( var success bool t.conn, success = remoteConn.(*net.TCPConn) if !success { - core.LogError("UnicastTCPTransport", "Specified connection ", remoteConn, " is not a net.TCPConn") + core.Log.Error(t, "Specified connection is not a net.TCPConn", "conn", remoteConn) return nil, errors.New("specified connection is not a net.TCPConn") } t.running.Store(true) @@ -143,7 +143,7 @@ func (t *UnicastTCPTransport) SetPersistency(persistency spec_mgmt.Persistency) func (t *UnicastTCPTransport) GetSendQueueSize() uint64 { rawConn, err := t.conn.SyscallConn() if err != nil { - core.LogWarn(t, "Unable to get raw connection to get socket length: ", err) + core.Log.Warn(t, "Unable to get raw connection to get socket length", "err", err) } return impl.SyscallGetSocketSendQueueSize(rawConn) } @@ -186,7 +186,7 @@ func (t *UnicastTCPTransport) reconnect() { remote := net.JoinHostPort(t.remoteURI.Path(), strconv.Itoa(int(t.remoteURI.Port()))) conn, err := t.dialer.Dial(t.remoteURI.Scheme(), remote) if err != nil { - core.LogWarn(t, "Unable to connect to remote endpoint [", attempt, "]: ", err) + core.Log.Warn(t, "Unable to connect to remote endpoint", "err", err, "attempt", attempt) time.Sleep(5 * time.Second) // TODO: configurable continue } @@ -211,13 +211,13 @@ func (t *UnicastTCPTransport) sendFrame(frame []byte) { } if len(frame) > t.MTU() { - core.LogWarn(t, "Attempted to send frame larger than MTU - DROP") + core.Log.Warn(t, "Attempted to send frame larger than MTU") return } _, err := t.conn.Write(frame) if err != nil { - core.LogWarn(t, "Unable to send on socket - DROP") + core.Log.Warn(t, "Unable to send on socket") t.CloseConn() // receive might restart if needed return } @@ -242,7 +242,7 @@ func (t *UnicastTCPTransport) runReceive() { break // EOF } - core.LogWarn(t, "Unable to read from socket (", err, ") - Face DOWN") + core.Log.Warn(t, "Unable to read from socket - Face DOWN", "err", err) } // Persistent faces will reconnect, otherwise close diff --git a/fw/face/unicast-udp-transport.go b/fw/face/unicast-udp-transport.go index e48165cc..d194392a 100644 --- a/fw/face/unicast-udp-transport.go +++ b/fw/face/unicast-udp-transport.go @@ -103,7 +103,7 @@ func (t *UnicastUDPTransport) SetPersistency(persistency spec_mgmt.Persistency) func (t *UnicastUDPTransport) GetSendQueueSize() uint64 { rawConn, err := t.conn.SyscallConn() if err != nil { - core.LogWarn(t, "Unable to get raw connection to get socket length: ", err) + core.Log.Warn(t, "Unable to get raw connection to get socket length", "err", err) } return impl.SyscallGetSocketSendQueueSize(rawConn) } @@ -114,13 +114,13 @@ func (t *UnicastUDPTransport) sendFrame(frame []byte) { } if len(frame) > t.MTU() { - core.LogWarn(t, "Attempted to send frame larger than MTU - DROP") + core.Log.Warn(t, "Attempted to send frame larger than MTU") return } _, err := t.conn.Write(frame) if err != nil { - core.LogWarn(t, "Unable to send on socket - DROP and Face DOWN") + core.Log.Warn(t, "Unable to send on socket - Face DOWN") t.Close() return } @@ -142,7 +142,7 @@ func (t *UnicastUDPTransport) runReceive() { return strings.Contains(err.Error(), "connection refused") }) if err != nil && t.running.Load() { - core.LogWarn(t, "Unable to read from socket (", err, ") - Face DOWN") + core.Log.Warn(t, "Unable to read from socket - Face DOWN", "err", err) } } diff --git a/fw/face/unix-stream-listener.go b/fw/face/unix-stream-listener.go index caf17bbf..e0f1fdd3 100644 --- a/fw/face/unix-stream-listener.go +++ b/fw/face/unix-stream-listener.go @@ -57,15 +57,15 @@ func (l *UnixStreamListener) Run() { // Create listener var err error if l.conn, err = net.Listen(l.localURI.Scheme(), sockPath); err != nil { - core.LogFatal(l, "Unable to start Unix stream listener: ", err) + core.Log.Fatal(l, "Unable to start Unix stream listener", "err", err) } // Set permissions to allow all local apps to communicate with us if err := os.Chmod(sockPath, os.ModePerm); err != nil { - core.LogFatal(l, "Unable to change permissions on Unix stream listener: ", err) + core.Log.Fatal(l, "Unable to change permissions on Unix stream listener", "err", err) } - core.Log.Info(l, "Listening") + core.Log.Info(l, "Listening for connections") // Run accept loop for !core.ShouldQuit { @@ -74,20 +74,20 @@ func (l *UnixStreamListener) Run() { if errors.Is(err, net.ErrClosed) { return } - core.LogWarn(l, "Unable to accept connection: ", err) + core.Log.Warn(l, "Unable to accept connection", "err", err) return } remoteURI := defn.MakeFDFaceURI(l.nextFD) l.nextFD++ if !remoteURI.IsCanonical() { - core.LogWarn(l, "Unable to create face from ", remoteURI, " as remote URI is not canonical") + core.Log.Warn(l, "Unable to create face remote URI is not canonical", "uri", remoteURI) continue } newTransport, err := MakeUnixStreamTransport(remoteURI, l.localURI, newConn) if err != nil { - core.LogError(l, "Failed to create new Unix stream transport: ", err) + core.Log.Error(l, "Failed to create new Unix stream transport", "err", err) continue } diff --git a/fw/face/unix-stream-transport.go b/fw/face/unix-stream-transport.go index d5f4967a..5d59bc8e 100644 --- a/fw/face/unix-stream-transport.go +++ b/fw/face/unix-stream-transport.go @@ -62,7 +62,7 @@ func (t *UnixStreamTransport) SetPersistency(persistency spec_mgmt.Persistency) func (t *UnixStreamTransport) GetSendQueueSize() uint64 { rawConn, err := t.conn.SyscallConn() if err != nil { - core.LogWarn(t, "Unable to get raw connection to get socket length: ", err) + core.Log.Warn(t, "Unable to get raw connection to get socket length", "err", err) } return impl.SyscallGetSocketSendQueueSize(rawConn) } @@ -73,13 +73,13 @@ func (t *UnixStreamTransport) sendFrame(frame []byte) { } if len(frame) > t.MTU() { - core.LogWarn(t, "Attempted to send frame larger than MTU - DROP") + core.Log.Warn(t, "Attempted to send frame larger than MTU") return } _, err := t.conn.Write(frame) if err != nil { - core.LogWarn(t, "Unable to send on socket - DROP and Face DOWN") + core.Log.Warn(t, "Unable to send on socket - Face DOWN") t.Close() return } @@ -95,7 +95,7 @@ func (t *UnixStreamTransport) runReceive() { t.linkService.handleIncomingFrame(b) }, nil) if err != nil && t.running.Load() { - core.LogWarn(t, "Unable to read from socket (", err, ") - Face DOWN") + core.Log.Warn(t, "Unable to read from socket - Face DOWN", "err", err) } } diff --git a/fw/face/web-socket-listener.go b/fw/face/web-socket-listener.go index 6167fe2b..29c9dd2d 100644 --- a/fw/face/web-socket-listener.go +++ b/fw/face/web-socket-listener.go @@ -99,7 +99,7 @@ func (l *WebSocketListener) Run() { err = l.server.ListenAndServeTLS("", "") } if !errors.Is(err, http.ErrServerClosed) { - core.LogFatal(l, "Unable to start listener: ", err) + core.Log.Fatal(l, "Unable to start listener", "err", err) } } diff --git a/fw/face/web-socket-transport.go b/fw/face/web-socket-transport.go index 992dae8b..f12bcd61 100644 --- a/fw/face/web-socket-transport.go +++ b/fw/face/web-socket-transport.go @@ -57,13 +57,13 @@ func (t *WebSocketTransport) sendFrame(frame []byte) { } if len(frame) > t.MTU() { - core.LogWarn(t, "Attempted to send frame larger than MTU - DROP") + core.Log.Warn(t, "Attempted to send frame larger than MTU") return } e := t.c.WriteMessage(websocket.BinaryMessage, frame) if e != nil { - core.LogWarn(t, "Unable to send on socket - DROP and Face DOWN") + core.Log.Warn(t, "Unable to send on socket - Face DOWN") t.Close() return } @@ -82,18 +82,18 @@ func (t *WebSocketTransport) runReceive() { } else if websocket.IsUnexpectedCloseError(err) { core.Log.Info(t, "WebSocket closed unexpectedly - DROP and Face DOWN", "err", err) } else { - core.LogWarn(t, "Unable to read from WebSocket - DROP and Face DOWN", "err", err) + core.Log.Warn(t, "Unable to read from WebSocket - DROP and Face DOWN", "err", err) } return } if mt != websocket.BinaryMessage { - core.LogWarn(t, "Ignored non-binary message") + core.Log.Warn(t, "Ignored non-binary message") continue } if len(message) > defn.MaxNDNPacketSize { - core.LogWarn(t, "Received too much data without valid TLV block - DROP") + core.Log.Warn(t, "Received too much data without valid TLV block") continue } diff --git a/fw/fw/bestroute.go b/fw/fw/bestroute.go index fd856cb6..391bf286 100644 --- a/fw/fw/bestroute.go +++ b/fw/fw/bestroute.go @@ -43,7 +43,7 @@ func (s *BestRoute) AfterContentStoreHit( pitEntry table.PitEntry, inFace uint64, ) { - core.LogTrace(s, "AfterContentStoreHit: Forwarding content store hit Data=", packet.Name, " to FaceID=", inFace) + core.Log.Trace(s, "AfterContentStoreHit", "name", packet.Name, "faceid", inFace) s.SendData(packet, pitEntry, inFace, 0) // 0 indicates ContentStore is source } @@ -52,9 +52,9 @@ func (s *BestRoute) AfterReceiveData( pitEntry table.PitEntry, inFace uint64, ) { - core.LogTrace(s, "AfterReceiveData: Data=", ", ", len(pitEntry.InRecords()), " In-Records") + core.Log.Trace(s, "AfterReceiveData", "name", packet.Name, "inrecords", len(pitEntry.InRecords())) for faceID := range pitEntry.InRecords() { - core.LogTrace(s, "AfterReceiveData: Forwarding Data=", packet.Name, " to FaceID=", faceID) + core.Log.Trace(s, "Forwarding Data", "name", packet.Name, "faceid", faceID) s.SendData(packet, pitEntry, faceID, inFace) } } @@ -66,7 +66,7 @@ func (s *BestRoute) AfterReceiveInterest( nexthops []*table.FibNextHopEntry, ) { if len(nexthops) == 0 { - core.LogDebug(s, "AfterReceiveInterest: No nexthop for Interest=", packet.Name, " - DROP") + core.Log.Debug(s, "No nexthop found - DROP", "name", packet.Name) return } @@ -75,7 +75,7 @@ func (s *BestRoute) AfterReceiveInterest( for _, outRecord := range pitEntry.OutRecords() { if outRecord.LatestNonce != *packet.L3.Interest.NonceV && outRecord.LatestTimestamp.Add(BestRouteSuppressionTime).After(time.Now()) { - core.LogDebug(s, "AfterReceiveInterest: Suppressed Interest=", packet.Name, " - DROP") + core.Log.Debug(s, "Suppressed Interest - DROP", "name", packet.Name) return } } @@ -83,13 +83,13 @@ func (s *BestRoute) AfterReceiveInterest( // Sort nexthops by cost and send to best-possible nexthop sort.Slice(nexthops, func(i, j int) bool { return nexthops[i].Cost < nexthops[j].Cost }) for _, nh := range nexthops { - core.LogTrace(s, "AfterReceiveInterest: Forwarding Interest=", packet.Name, " to FaceID=", nh.Nexthop) + core.Log.Trace(s, "Forwarding Interest", "name", packet.Name, "faceid", nh.Nexthop) if sent := s.SendInterest(packet, pitEntry, nh.Nexthop, inFace); sent { return } } - core.LogDebug(s, "AfterReceiveInterest: No usable nexthop for Interest=", packet.Name, " - DROP") + core.Log.Debug(s, "No usable nexthop for Interest - DROP", "name", packet.Name) } func (s *BestRoute) BeforeSatisfyInterest(pitEntry table.PitEntry, inFace uint64) { diff --git a/fw/fw/multicast.go b/fw/fw/multicast.go index 8642b3fb..75b2a5e5 100644 --- a/fw/fw/multicast.go +++ b/fw/fw/multicast.go @@ -41,7 +41,7 @@ func (s *Multicast) AfterContentStoreHit( pitEntry table.PitEntry, inFace uint64, ) { - core.LogTrace(s, "AfterContentStoreHit: Forwarding content store hit Data=", packet.Name, " to FaceID=", inFace) + core.Log.Trace(s, "AfterContentStoreHit", "name", packet.Name, "faceid", inFace) s.SendData(packet, pitEntry, inFace, 0) // 0 indicates ContentStore is source } @@ -50,9 +50,9 @@ func (s *Multicast) AfterReceiveData( pitEntry table.PitEntry, inFace uint64, ) { - core.LogTrace(s, "AfterReceiveData: Data=", packet.Name, ", ", len(pitEntry.InRecords()), " In-Records") + core.Log.Trace(s, "AfterReceiveData", "name", packet.Name, "inrecords", len(pitEntry.InRecords())) for faceID := range pitEntry.InRecords() { - core.LogTrace(s, "AfterReceiveData: Forwarding Data=", packet.Name, " to FaceID=", faceID) + core.Log.Trace(s, "Forwarding Data", "name", packet.Name, "faceid", faceID) s.SendData(packet, pitEntry, faceID, inFace) } } @@ -64,7 +64,7 @@ func (s *Multicast) AfterReceiveInterest( nexthops []*table.FibNextHopEntry, ) { if len(nexthops) == 0 { - core.LogDebug(s, "AfterReceiveInterest: No nexthop for Interest=", packet.Name, " - DROP") + core.Log.Debug(s, "No nexthop for Interest", "name", packet.Name) return } @@ -73,14 +73,14 @@ func (s *Multicast) AfterReceiveInterest( for _, outRecord := range pitEntry.OutRecords() { if outRecord.LatestNonce != *packet.L3.Interest.NonceV && outRecord.LatestTimestamp.Add(MulticastSuppressionTime).After(time.Now()) { - core.LogDebug(s, "AfterReceiveInterest: Suppressed Interest=", packet.Name, " - DROP") + core.Log.Debug(s, "Suppressed Interest", "name", packet.Name) return } } // Send interest to all nexthops for _, nexthop := range nexthops { - core.LogTrace(s, "AfterReceiveInterest: Forwarding Interest=", packet.Name, " to FaceID=", nexthop.Nexthop) + core.Log.Trace(s, "Forwarding Interest", "name", packet.Name, "faceid", nexthop.Nexthop) s.SendInterest(packet, pitEntry, nexthop.Nexthop, inFace) } } diff --git a/fw/fw/strategy-loader.go b/fw/fw/strategy-loader.go index 704f677d..0189c545 100644 --- a/fw/fw/strategy-loader.go +++ b/fw/fw/strategy-loader.go @@ -24,7 +24,7 @@ func InstantiateStrategies(fwThread *Thread) map[uint64]Strategy { strategy := strategyType() strategy.Instantiate(fwThread) strategies[strategy.GetName().Hash()] = strategy - core.LogDebug("StrategyLoader", "Instantiated Strategy=", strategy.GetName(), " for Thread=", fwThread.GetID()) + core.Log.Debug(nil, "Instantiated Strategy", "strategy", strategy.GetName(), "thread", fwThread.GetID()) } return strategies diff --git a/fw/fw/thread.go b/fw/fw/thread.go index cd12beb0..1dc925d5 100644 --- a/fw/fw/thread.go +++ b/fw/fw/thread.go @@ -149,7 +149,7 @@ func (t *Thread) QueueInterest(interest *defn.Pkt) { select { case t.pendingInterests <- interest: default: - core.LogError(t, "Interest dropped due to full queue") + core.Log.Error(t, "Interest dropped due to full queue") } } @@ -158,7 +158,7 @@ func (t *Thread) QueueData(data *defn.Pkt) { select { case t.pendingDatas <- data: default: - core.LogError(t, "Data dropped due to full queue") + core.Log.Error(t, "Data dropped due to full queue") } } @@ -172,13 +172,12 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { // Get incoming face incomingFace := dispatch.GetFace(packet.IncomingFaceID) if incomingFace == nil { - core.LogError(t, "Non-existent incoming FaceID=", packet.IncomingFaceID, - " for Interest=", packet.Name, " - DROP") + core.Log.Error(t, "Interest has non-existent incoming face", "faceid", packet.IncomingFaceID, "name", packet.Name) return } if interest.HopLimitV != nil { - core.LogTrace(t, "Interest ", packet.Name, " has HopLimit=", *interest.HopLimitV) + core.Log.Trace(t, "HopLimit check", "name", packet.Name, "hoplimit", *interest.HopLimitV) if *interest.HopLimitV == 0 { return } @@ -186,11 +185,11 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { } // Log PIT token (if any) - core.LogTrace(t, "OnIncomingInterest: ", packet.Name, ", FaceID=", incomingFace.FaceID(), ", PitTokenL=", len(packet.PitToken)) + core.Log.Trace(t, "OnIncomingInterest", "name", packet.Name, "faceid", incomingFace.FaceID(), "pittoken", len(packet.PitToken)) // Check if violates /localhost if incomingFace.Scope() == defn.NonLocal && len(packet.Name) > 0 && packet.Name[0].Equal(enc.LOCALHOST) { - core.LogWarn(t, "Interest ", packet.Name, " from non-local face=", incomingFace.FaceID(), " violates /localhost scope - DROP") + core.Log.Warn(t, "Interest from non-local face violates /localhost scope", "name", packet.Name, "faceid", incomingFace.FaceID()) return } @@ -219,13 +218,13 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { // Drop packet if no nonce is found if interest.NonceV == nil { - core.LogDebug(t, "Interest ", packet.Name, " is missing Nonce - DROP") + core.Log.Debug(t, "Interest is missing Nonce", "name", packet.Name) return } // Check if packet is in dead nonce list if exists := t.deadNonceList.Find(interest.NameV, *interest.NonceV); exists { - core.LogDebug(t, "Interest ", packet.Name, " is dropped by DeadNonce: ", *interest.NonceV) + core.Log.Debug(t, "Interest is looping (DNL)", "name", packet.Name, "nonce", *interest.NonceV) return } @@ -234,7 +233,7 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { pitEntry, isDuplicate := t.pitCS.InsertInterest(interest, fhName, incomingFace.FaceID()) if isDuplicate { // Interest loop - since we don't use Nacks, just drop - core.LogDebug(t, "Interest ", packet.Name, " is looping - DROP") + core.Log.Debug(t, "Interest is looping (PIT)", "name", packet.Name) return } @@ -248,7 +247,7 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { interest, incomingFace.FaceID(), packet.PitToken) if !isAlreadyPending { - core.LogTrace(t, "Interest ", packet.Name, " is not pending") + core.Log.Trace(t, "Interest is not pending", "name", packet.Name) // Check CS for matching entry if t.pitCS.IsCsServing() { @@ -266,15 +265,15 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { strategy.AfterContentStoreHit(packet, pitEntry, incomingFace.FaceID()) return } else if err != nil { - core.LogError(t, "Error copying CS entry: ", err) + core.Log.Error(t, "Error copying CS entry", "err", err) } else { - core.LogError(t, "Error copying CS entry: csData is nil") + core.Log.Error(t, "Error copying CS entry", "err", "csData is nil") } } } } else { - core.LogTrace(t, "Interest ", packet.Name, " is already pending") + core.Log.Trace(t, "Interest is already pending", "name", packet.Name) // Add the previous nonce to the dead nonce list to prevent further looping // TODO: review this design, not specified in NFD dev guide @@ -287,14 +286,15 @@ func (t *Thread) processIncomingInterest(packet *defn.Pkt) { // If NextHopFaceId set, forward to that face (if it exists) or drop if packet.NextHopFaceID != nil { if face := dispatch.GetFace(*packet.NextHopFaceID); face != nil { - core.LogTrace(t, "NextHopFaceId is set for Interest ", packet.Name, " - dispatching directly to face") + core.Log.Trace(t, "NextHopFaceId is set for Interest", "name", packet.Name) face.SendPacket(dispatch.OutPkt{ Pkt: packet, PitToken: packet.PitToken, // TODO: ?? InFace: packet.IncomingFaceID, }) } else { - core.Log.Info(t, "Non-existent face specified in NextHopFaceId for Interest ", packet.Name, " - DROP") + core.Log.Info(t, "Non-existent face specified in NextHopFaceId for Interest", + "name", packet.Name, "faceid", *packet.NextHopFaceID) } return } @@ -349,23 +349,23 @@ func (t *Thread) processOutgoingInterest( panic("processOutgoingInterest called with non-Interest packet") } - core.LogTrace(t, "OnOutgoingInterest: ", packet.Name, ", FaceID=", nexthop) + core.Log.Trace(t, "OnOutgoingInterest", "name", packet.Name, "faceid", nexthop) // Get outgoing face outgoingFace := dispatch.GetFace(nexthop) if outgoingFace == nil { - core.LogError(t, "Non-existent nexthop FaceID=", nexthop, " for Interest=", packet.Name, " - DROP") + core.Log.Error(t, "Non-existent nexthop", "name", packet.Name, "faceid", nexthop) return false } if outgoingFace.FaceID() == inFace && outgoingFace.LinkType() != defn.AdHoc { - core.LogDebug(t, "Attempting to send Interest=", packet.Name, " back to incoming face - DROP") + core.Log.Debug(t, "Prevent send Interest back to incoming face", "name", packet.Name, "faceid", nexthop) return false } // Drop if HopLimit (if present) on Interest going to non-local face is 0. If so, drop if interest.HopLimitV != nil && int(*interest.HopLimitV) == 0 && outgoingFace.Scope() == defn.NonLocal { - core.LogDebug(t, "Attempting to send Interest=", packet.Name, " with HopLimit=0 to non-local face - DROP") + core.Log.Debug(t, "Prevent send Interest with HopLimit=0 to non-local face", "name", packet.Name, "faceid", nexthop) return false } @@ -417,7 +417,7 @@ func (t *Thread) processIncomingData(packet *defn.Pkt) { // Get incoming face incomingFace := dispatch.GetFace(packet.IncomingFaceID) if incomingFace == nil { - core.LogError(t, "Non-existent nexthop FaceID=", packet.IncomingFaceID, " for Data=", packet.Name, " DROP") + core.Log.Error(t, "Non-existent nexthop for Data", "name", packet.Name, "faceid", packet.IncomingFaceID) return } @@ -425,7 +425,7 @@ func (t *Thread) processIncomingData(packet *defn.Pkt) { // Check if violates /localhost if incomingFace.Scope() == defn.NonLocal && len(packet.Name) > 0 && packet.Name[0].Equal(enc.LOCALHOST) { - core.LogWarn(t, "Data ", packet.Name, " from non-local FaceID=", packet.IncomingFaceID, " violates /localhost scope - DROP") + core.Log.Warn(t, "Data from non-local face violates /localhost scope", "name", packet.Name, "faceid", packet.IncomingFaceID) return } @@ -438,7 +438,7 @@ func (t *Thread) processIncomingData(packet *defn.Pkt) { pitEntries := t.pitCS.FindInterestPrefixMatchByDataEnc(data, pitToken) if len(pitEntries) == 0 { // Unsolicited Data - nothing more to do - core.LogDebug(t, "Unsolicited data ", packet.Name, " FaceID=", packet.IncomingFaceID, " - DROP") + core.Log.Debug(t, "Unsolicited data", "name", packet.Name, "faceid", packet.IncomingFaceID) return } @@ -455,7 +455,7 @@ func (t *Thread) processIncomingData(packet *defn.Pkt) { table.SetExpirationTimerToNow(pitEntry) // Invoke strategy's AfterReceiveData - core.LogTrace(t, "Sending Data=", packet.Name, " to strategy=", strategyName) + core.Log.Trace(t, "Sending Data", "name", packet.Name, "strategy", strategyName) strategy.AfterReceiveData(packet, pitEntry, packet.IncomingFaceID) // Mark PIT entry as satisfied @@ -505,7 +505,7 @@ func (t *Thread) processIncomingData(packet *defn.Pkt) { // Call outgoing Data pipeline for each pending downstream for face, token := range downstreams { - core.LogTrace(t, "Multiple PIT entries Data=", packet.Name) + core.Log.Trace(t, "Multiple PIT entries for Data", "name", packet.Name) t.processOutgoingData(packet, face, token, packet.IncomingFaceID) } } @@ -523,18 +523,18 @@ func (t *Thread) processOutgoingData( panic("processOutgoingData called with non-Data packet") } - core.LogTrace(t, "OnOutgoingData: ", packet.Name, ", FaceID=", nexthop) + core.Log.Trace(t, "OnOutgoingData", "name", packet.Name, "faceid", nexthop) // Get outgoing face outgoingFace := dispatch.GetFace(nexthop) if outgoingFace == nil { - core.LogError(t, "Non-existent nexthop FaceID=", nexthop, " for Data=", packet.Name, " - DROP") + core.Log.Error(t, "Non-existent nexthop for Data", "name", packet.Name, "faceid", nexthop) return } // Check if violates /localhost if outgoingFace.Scope() == defn.NonLocal && len(packet.Name) > 0 && packet.Name[0].Equal(enc.LOCALHOST) { - core.LogWarn(t, "Data ", packet.Name, " cannot be sent to non-local FaceID=", nexthop, " since violates /localhost scope - DROP") + core.Log.Warn(t, "Data cannot be sent to non-local face since violates /localhost scope", "name", packet.Name, "faceid", nexthop) return } diff --git a/fw/mgmt/cs.go b/fw/mgmt/cs.go index d9928bce..33eff242 100644 --- a/fw/mgmt/cs.go +++ b/fw/mgmt/cs.go @@ -37,7 +37,7 @@ func (c *ContentStoreModule) getManager() *Thread { func (c *ContentStoreModule) handleIncomingInterest(interest *Interest) { // Only allow from /localhost if !LOCAL_PREFIX.IsPrefix(interest.Name()) { - core.LogWarn(c, "Received CS management Interest from non-local source - DROP") + core.Log.Warn(c, "Received CS management Interest from non-local source") return } @@ -52,7 +52,7 @@ func (c *ContentStoreModule) handleIncomingInterest(interest *Interest) { case "info": c.info(interest) default: - core.LogWarn(c, "Received Interest for non-existent verb '", verb, "'") + core.Log.Warn(c, "Received Interest for non-existent verb", "verb", verb) c.manager.sendCtrlResp(interest, 501, "Unknown verb", nil) return } @@ -61,7 +61,7 @@ func (c *ContentStoreModule) handleIncomingInterest(interest *Interest) { func (c *ContentStoreModule) config(interest *Interest) { if len(interest.Name()) < len(LOCAL_PREFIX)+3 { // Name not long enough to contain ControlParameters - core.LogWarn(c, "Missing ControlParameters in ", interest.Name()) + core.Log.Warn(c, "Missing ControlParameters", "name", interest.Name()) c.manager.sendCtrlResp(interest, 400, "ControlParameters is incorrect", nil) return } @@ -73,7 +73,7 @@ func (c *ContentStoreModule) config(interest *Interest) { } if (params.Flags == nil && params.Mask != nil) || (params.Flags != nil && params.Mask == nil) { - core.LogWarn(c, "Flags and Mask fields must either both be present or both be not present") + core.Log.Warn(c, "Flags and Mask fields must either both be present or both be not present") c.manager.sendCtrlResp(interest, 409, "ControlParameters are incorrect", nil) return } diff --git a/fw/mgmt/face.go b/fw/mgmt/face.go index 4cf6f74e..2a511487 100644 --- a/fw/mgmt/face.go +++ b/fw/mgmt/face.go @@ -41,7 +41,7 @@ func (f *FaceModule) getManager() *Thread { func (f *FaceModule) handleIncomingInterest(interest *Interest) { // Only allow from /localhost if !LOCAL_PREFIX.IsPrefix(interest.Name()) { - core.LogWarn(f, "Received face management Interest from non-local source - DROP") + core.Log.Warn(f, "Received face management Interest from non-local source - DROP") return } @@ -59,7 +59,7 @@ func (f *FaceModule) handleIncomingInterest(interest *Interest) { case "query": f.query(interest) default: - core.LogWarn(f, "Received Interest for non-existent verb '", verb, "'") + core.Log.Warn(f, "Received Interest for non-existent verb", "verb", verb) f.manager.sendCtrlResp(interest, 501, "Unknown verb", nil) return } @@ -96,8 +96,8 @@ func (f *FaceModule) create(interest *Interest) { // Ensure does not conflict with existing face existingFace := face.FaceTable.GetByURI(URI) if existingFace != nil { - core.LogWarn(f, "Cannot create face ", URI, ": Conflicts with existing face FaceID=", - existingFace.FaceID(), ", RemoteURI=", existingFace.RemoteURI()) + core.Log.Warn(f, "Cannot create face, conflicts with existing face", + "faceid", existingFace.FaceID(), "uri", existingFace.RemoteURI()) responseParams := &mgmt.ControlArgs{} f.fillFaceProperties(responseParams, existingFace) f.manager.sendCtrlResp(interest, 409, "Conflicts with existing face", responseParams) @@ -144,7 +144,7 @@ func (f *FaceModule) create(interest *Interest) { // Create new UDP face transport, err := face.MakeUnicastUDPTransport(URI, nil, persistency) if err != nil { - core.LogWarn(f, "Unable to create unicast UDP face with URI ", URI, ": ", err.Error()) + core.Log.Warn(f, "Unable to create unicast UDP face", "uri", URI, "err", err) f.manager.sendCtrlResp(interest, 406, "Transport error", nil) return } @@ -226,7 +226,7 @@ func (f *FaceModule) create(interest *Interest) { // Create new TCP face transport, err := face.MakeUnicastTCPTransport(URI, nil, persistency) if err != nil { - core.LogWarn(f, "Unable to create unicast TCP face with URI ", URI, ":", err.Error()) + core.Log.Warn(f, "Unable to create unicast TCP face", "uri", URI, "err", err) f.manager.sendCtrlResp(interest, 406, "Transport error", nil) return } @@ -277,7 +277,7 @@ func (f *FaceModule) create(interest *Interest) { } if linkService == nil { // Internal failure - core.LogWarn(f, "Transport error when creating face ", URI) + core.Log.Warn(f, "Transport error when creating face", "uri", URI) f.manager.sendCtrlResp(interest, 504, "Transport error when creating face", nil) return } @@ -312,7 +312,7 @@ func (f *FaceModule) update(interest *Interest) { selectedFace := face.FaceTable.Get(faceID) if selectedFace == nil { - core.LogWarn(f, "Cannot update specified (or implicit) FaceID=", faceID, " because it does not exist") + core.Log.Warn(f, "Cannot update specified (or implicit) face because it does not exist", "faceid", faceID) f.manager.sendCtrlResp(interest, 404, "Face does not exist", &mgmt.ControlArgs{FaceId: utils.IdPtr(faceID)}) return } @@ -482,7 +482,7 @@ func (f *FaceModule) list(interest *Interest) { func (f *FaceModule) query(interest *Interest) { if len(interest.Name()) < len(LOCAL_PREFIX)+3 { // Name not long enough to contain FaceQueryFilter - core.LogWarn(f, "Missing FaceQueryFilter in ", interest.Name()) + core.Log.Warn(f, "Missing FaceQueryFilter", "name", interest.Name()) return } filterV, err := mgmt.ParseFaceQueryFilter(enc.NewBufferReader(interest.Name()[len(LOCAL_PREFIX)+2].Val), true) @@ -496,12 +496,12 @@ func (f *FaceModule) query(interest *Interest) { if filter.Uri != nil { filterUri = defn.DecodeURIString(*filter.Uri) if filterUri == nil { - core.LogWarn(f, "Cannot decode URI in FaceQueryFilter ", filterUri) + core.Log.Warn(f, "Cannot decode URI in FaceQueryFilter", "uri", filterUri) return } err = filterUri.Canonize() if err != nil { - core.LogWarn(f, "Cannot canonize URI in FaceQueryFilter ", filterUri) + core.Log.Warn(f, "Cannot canonize URI in FaceQueryFilter", "uri", filterUri) return } } diff --git a/fw/mgmt/fib.go b/fw/mgmt/fib.go index 49184b52..b19e234b 100644 --- a/fw/mgmt/fib.go +++ b/fw/mgmt/fib.go @@ -36,7 +36,7 @@ func (f *FIBModule) getManager() *Thread { func (f *FIBModule) handleIncomingInterest(interest *Interest) { // Only allow from /localhost if !LOCAL_PREFIX.IsPrefix(interest.Name()) { - core.LogWarn(f, "Received FIB management Interest from non-local source - DROP") + core.Log.Warn(f, "Received FIB management Interest from non-local source - DROP") return } diff --git a/fw/mgmt/forwarder-status.go b/fw/mgmt/forwarder-status.go index d54c7228..f9753591 100644 --- a/fw/mgmt/forwarder-status.go +++ b/fw/mgmt/forwarder-status.go @@ -38,7 +38,7 @@ func (f *ForwarderStatusModule) getManager() *Thread { func (f *ForwarderStatusModule) handleIncomingInterest(interest *Interest) { // Only allow from /localhost if !LOCAL_PREFIX.IsPrefix(interest.Name()) { - core.LogWarn(f, "Received forwarder status management Interest from non-local source - DROP") + core.Log.Warn(f, "Received forwarder status management Interest from non-local source - DROP") return } diff --git a/fw/mgmt/helpers.go b/fw/mgmt/helpers.go index 66d25a32..dd2db1fa 100644 --- a/fw/mgmt/helpers.go +++ b/fw/mgmt/helpers.go @@ -17,7 +17,7 @@ func decodeControlParameters(m Module, interest *Interest) *mgmt.ControlArgs { paramVal := interest.Name()[len(LOCAL_PREFIX)+2].Val params, err := mgmt.ParseControlParameters(enc.NewBufferReader(paramVal), true) if err != nil { - core.LogWarn(m, "Could not decode ControlParameters in ", interest.Name(), ": ", err) + core.Log.Warn(m, "Could not decode ControlParameters", "name", interest.Name(), "err", err) return nil } return params.Val diff --git a/fw/mgmt/nlsr_readvertiser.go b/fw/mgmt/nlsr_readvertiser.go index 405f7d99..2a19b85a 100644 --- a/fw/mgmt/nlsr_readvertiser.go +++ b/fw/mgmt/nlsr_readvertiser.go @@ -33,10 +33,10 @@ func (r *NlsrReadvertiser) String() string { func (r *NlsrReadvertiser) Announce(name enc.Name, route *table.Route) { if route.Origin != uint64(spec_mgmt.RouteOriginClient) { - core.LogDebug(r, "skip advertise", "name", name, "origin", route.Origin) + core.Log.Debug(r, "Skip advertise", "name", name, "origin", route.Origin) return } - core.Log.Info(r, "advertise", "name", name) + core.Log.Info(r, "Advertise", "name", name) r.mutex.Lock() defer r.mutex.Unlock() @@ -64,7 +64,7 @@ func (r *NlsrReadvertiser) Announce(name enc.Name, route *table.Route) { func (r *NlsrReadvertiser) Withdraw(name enc.Name, route *table.Route) { if route.Origin != uint64(spec_mgmt.RouteOriginClient) { - core.LogDebug(r, "skip withdraw=", name, " origin=", route.Origin) + core.Log.Debug(r, "Skip withdraw", "name", name, "origin", route.Origin) return } @@ -74,10 +74,10 @@ func (r *NlsrReadvertiser) Withdraw(name enc.Name, route *table.Route) { nhash := name.Hash() r.advertised[nhash] -= 1 if r.advertised[nhash] > 0 { - core.LogDebug(r, "skip withdraw (still advertised)", "name", name) + core.Log.Debug(r, "Skip withdraw (still advertised)", "name", name) return } - core.Log.Info(r, "withdraw", "name", name) + core.Log.Info(r, "Withdraw", "name", name) params := &spec_mgmt.ControlArgs{ Name: name, diff --git a/fw/mgmt/strategy-choice.go b/fw/mgmt/strategy-choice.go index 0658400e..30d1c763 100644 --- a/fw/mgmt/strategy-choice.go +++ b/fw/mgmt/strategy-choice.go @@ -36,7 +36,7 @@ func (s *StrategyChoiceModule) getManager() *Thread { func (s *StrategyChoiceModule) handleIncomingInterest(interest *Interest) { // Only allow from /localhost if !LOCAL_PREFIX.IsPrefix(interest.Name()) { - core.LogWarn(s, "Received strategy management Interest from non-local source - DROP") + core.Log.Warn(s, "Received strategy management Interest from non-local source - DROP") return } @@ -78,7 +78,7 @@ func (s *StrategyChoiceModule) set(interest *Interest) { } if !defn.STRATEGY_PREFIX.IsPrefix(params.Strategy.Name) { - core.LogWarn(s, "Invalid Strategy=", params.Strategy.Name) + core.Log.Warn(s, "Invalid strategy", "strategy", params.Strategy.Name) s.manager.sendCtrlResp(interest, 404, "Invalid strategy", nil) return } @@ -86,7 +86,7 @@ func (s *StrategyChoiceModule) set(interest *Interest) { strategyName := params.Strategy.Name[len(defn.STRATEGY_PREFIX)].String() availableVersions, ok := fw.StrategyVersions[strategyName] if !ok { - core.LogWarn(s, "Unknown Strategy=", params.Strategy) + core.Log.Warn(s, "Unknown strategy", "strategy", params.Strategy.Name) s.manager.sendCtrlResp(interest, 404, "Unknown strategy", nil) return } @@ -99,14 +99,14 @@ func (s *StrategyChoiceModule) set(interest *Interest) { } } if len(params.Strategy.Name) > len(defn.STRATEGY_PREFIX)+1 && params.Strategy.Name[len(defn.STRATEGY_PREFIX)+1].Typ != enc.TypeVersionNameComponent { - core.LogWarn(s, "Invalid Version=", params.Strategy.Name[len(defn.STRATEGY_PREFIX)+1], " for Strategy=", params.Strategy) + core.Log.Warn(s, "Unknown strategy version", "strategy", params.Strategy.Name, "version", params.Strategy.Name[len(defn.STRATEGY_PREFIX)+1]) s.manager.sendCtrlResp(interest, 404, "Unknown strategy version", nil) return } else if len(params.Strategy.Name) > len(defn.STRATEGY_PREFIX)+1 { strategyVersionBytes := params.Strategy.Name[len(defn.STRATEGY_PREFIX)+1].Val strategyVersion, _, err := enc.ParseNat(strategyVersionBytes) if err != nil { - core.LogWarn(s, "Invalid Version=", params.Strategy.Name[len(defn.STRATEGY_PREFIX)+1], " for Strategy=", params.Strategy) + core.Log.Warn(s, "Invalid strategy version", "strategy", params.Strategy.Name, "version", params.Strategy.Name[len(defn.STRATEGY_PREFIX)+1]) s.manager.sendCtrlResp(interest, 404, "Invalid strategy version", nil) return } @@ -117,7 +117,7 @@ func (s *StrategyChoiceModule) set(interest *Interest) { } } if !foundMatchingVersion { - core.LogWarn(s, "Unknown Version=", strategyVersion, " for Strategy=", params.Strategy) + core.Log.Warn(s, "Unknown strategy version", "strategy", params.Strategy.Name, "version", strategyVersion) s.manager.sendCtrlResp(interest, 404, "Unknown strategy version", nil) return } diff --git a/fw/mgmt/thread.go b/fw/mgmt/thread.go index e99be980..bf31f294 100644 --- a/fw/mgmt/thread.go +++ b/fw/mgmt/thread.go @@ -93,19 +93,19 @@ func (m *Thread) Run() { } if lpPkt.IncomingFaceId == nil || len(lpPkt.Fragment) == 0 { - core.LogWarn(m, "Received malformed packet on internal face, drop") + core.Log.Warn(m, "Received malformed packet on internal face - DROP") continue } pkt, _, err := spec.ReadPacket(enc.NewWireReader(lpPkt.Fragment)) if err != nil { - core.LogWarn(m, "Unable to decode internal packet, drop") + core.Log.Warn(m, "Unable to decode internal packet - DROP", "err", err) continue } // We only expect Interests, so drop Data packets if pkt.Interest == nil { - core.LogDebug(m, "Dropping received non-Interest packet") + core.Log.Debug(m, "Dropping received non-Interest packet") continue } @@ -118,15 +118,15 @@ func (m *Thread) Run() { // Ensure Interest name matches expectations if len(interest.Name()) < len(LOCAL_PREFIX)+2 { // Module + Verb - core.LogWarn(m, "Control command name ", interest.Name(), " has unexpected number of components - DROP") + core.Log.Warn(m, "Control command name has unexpected number of components - DROP", "name", interest.Name()) continue } if !LOCAL_PREFIX.IsPrefix(interest.Name()) && !NON_LOCAL_PREFIX.IsPrefix(interest.Name()) { - core.LogWarn(m, "Control command name ", interest.Name(), " has unexpected prefix - DROP") + core.Log.Warn(m, "Control command name has unexpected prefix - DROP", "name", interest.Name()) continue } - core.LogTrace(m, "Received management Interest ", interest.Name()) + core.Log.Trace(m, "Received management Interest", "name", interest.Name()) // Look for any matching data in object store. // We only use exact match here since RDR is unnecessary. @@ -145,7 +145,7 @@ func (m *Thread) Run() { if module, ok := m.modules[moduleName]; ok { module.handleIncomingInterest(interest) } else { - core.LogWarn(m, "Received management Interest for unknown module ", moduleName) + core.Log.Warn(m, "Received management Interest for unknown module", "module", moduleName) m.sendCtrlResp(interest, 501, "Unknown module", nil) } } @@ -159,12 +159,12 @@ func (m *Thread) sendInterest(name enc.Name, params enc.Wire) { } interest, err := spec.Spec{}.MakeInterest(name, &config, params, sec.NewSha256IntSigner(m.timer)) if err != nil { - core.LogWarn(m, "Unable to encode Interest for ", name, ": ", err) + core.Log.Warn(m, "Unable to encode Interest", "name", name, "err", err) return } m.transport.Send(&spec.LpPacket{Fragment: interest.Wire}) - core.LogTrace(m, "Sent management Interest for ", interest.FinalName) + core.Log.Trace(m, "Sent management Interest", "name", interest.FinalName) } // Send a Data packet to the internal transport @@ -178,7 +178,7 @@ func (m *Thread) sendData(interest *Interest, name enc.Name, content enc.Wire) { sec.NewSha256Signer(), ) if err != nil { - core.LogWarn(m, "Unable to encode Data for ", interest.Name(), ": ", err) + core.Log.Warn(m, "Unable to encode Data", "name", interest.Name(), "err", err) return } @@ -187,7 +187,7 @@ func (m *Thread) sendData(interest *Interest, name enc.Name, content enc.Wire) { PitToken: interest.pitToken, NextHopFaceId: interest.inFace, }) - core.LogTrace(m, "Sent management Data for ", name) + core.Log.Trace(m, "Sent management Data", "name", name) } // Send a ControlResponse Data packet to the internal transport @@ -216,7 +216,7 @@ func (m *Thread) sendStatusDataset(interest *Interest, name enc.Name, dataset en NoMetadata: true, }, m.store, sec.NewSha256Signer()) if err != nil { - core.LogWarn(m, "Unable to produce status dataset: ", err) + core.Log.Warn(m, "Unable to produce status dataset", "err", err) return } m.objDir.Push(objName) @@ -224,14 +224,14 @@ func (m *Thread) sendStatusDataset(interest *Interest, name enc.Name, dataset en // Evict oldest object if we have too many if old := m.objDir.Pop(); old != nil { if err := m.store.Remove(old, true); err != nil { - core.LogWarn(m, "Unable to clean up old status dataset: ", err) + core.Log.Warn(m, "Unable to clean up old status dataset", "err", err) } } // Get first segment from object name segment, err := m.store.Get(objName.Append(enc.NewSegmentComponent(0)), false) if err != nil || segment == nil { - core.LogWarn(m, "Unable to get first segment of status dataset: ", err) + core.Log.Warn(m, "Unable to get first segment of status dataset", "err", err) return } diff --git a/fw/table/init.go b/fw/table/init.go index e5f75c0f..0dfcae9f 100644 --- a/fw/table/init.go +++ b/fw/table/init.go @@ -58,10 +58,10 @@ func Configure() { for _, region := range producerRegions { name, err := enc.NameFromStr(region) if err != nil { - core.LogFatal("NetworkRegionTable", "Could not add name=", region, " to table: ", err) + core.Log.Fatal(nil, "Could not add producer region", "name", region, "err", err) } NetworkRegion.Add(name) - core.LogDebug("NetworkRegionTable", "Added name=", region, " to table") + core.Log.Debug(nil, "Added producer region", "name", region) } } @@ -73,7 +73,7 @@ func CreateFIBTable(algo string) { case "nametree": newFibStrategyTableTree() default: - core.LogFatal("CreateFIBTable", "Unrecognized FIB table algorithm specified: ", algo) + core.Log.Fatal(nil, "Unknown FIB table algorithm", "algo", algo) } } diff --git a/fw/table/pit-cs-tree.go b/fw/table/pit-cs-tree.go index 4741bf8d..5731d6e8 100644 --- a/fw/table/pit-cs-tree.go +++ b/fw/table/pit-cs-tree.go @@ -73,7 +73,7 @@ func NewPitCS(onExpiration OnPitExpiration) *PitCsTree { case "lru": pitCs.csReplacement = NewCsLRU(pitCs) default: - core.LogFatal(pitCs, "Unknown CS replacement policy ", csReplacementPolicy) + core.Log.Fatal(nil, "Unknown CS replacement policy", "policy", csReplacementPolicy) } pitCs.csMap = make(map[uint64]*nameTreeCsEntry) diff --git a/std/examples/low-level/consumer/main.go b/std/examples/low-level/consumer/main.go index 977f534e..c45f775f 100644 --- a/std/examples/low-level/consumer/main.go +++ b/std/examples/low-level/consumer/main.go @@ -11,14 +11,13 @@ import ( "github.com/named-data/ndnd/std/utils" ) -func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") +var logger = log.Default() +func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + logger.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -33,7 +32,7 @@ func main() { } interest, err := app.Spec().MakeInterest(name, intCfg, nil, nil) if err != nil { - logger.Errorf("Unable to make Interest: %+v", err) + logger.Error(nil, "Unable to make Interest", "err", err) return } @@ -56,7 +55,7 @@ func main() { ch <- struct{}{} }) if err != nil { - logger.Errorf("Unable to send Interest: %+v", err) + logger.Error(nil, "Unable to send Interest", "err", err) return } diff --git a/std/examples/low-level/producer/main.go b/std/examples/low-level/producer/main.go index 4611d6d3..a64c8ff4 100644 --- a/std/examples/low-level/producer/main.go +++ b/std/examples/low-level/producer/main.go @@ -18,6 +18,7 @@ import ( var app ndn.Engine var pib *sec_pib.SqlitePib +var logger = log.Default() func onInterest(args ndn.InterestHandlerArgs) { interest := args.Interest @@ -39,12 +40,12 @@ func onInterest(args ndn.InterestHandlerArgs) { enc.Wire{content}, signer) if err != nil { - log.WithField("module", "main").Errorf("unable to encode data: %+v", err) + logger.Error(nil, "Unable to encode data", "err", err) return } err = args.Reply(data.Wire) if err != nil { - log.WithField("module", "main").Errorf("unable to reply with data: %+v", err) + logger.Error(nil, "Unable to reply with data", "err", err) return } fmt.Printf("<< D: %s\n", interest.Name().String()) @@ -53,13 +54,10 @@ func onInterest(args ndn.InterestHandlerArgs) { } func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + logger.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -71,12 +69,12 @@ func main() { prefix, _ := enc.NameFromStr("/example/testApp") err = app.AttachHandler(prefix, onInterest) if err != nil { - logger.Errorf("Unable to register handler: %+v", err) + logger.Error(nil, "Unable to register handler", "err", err) return } err = app.RegisterRoute(prefix) if err != nil { - logger.Errorf("Unable to register route: %+v", err) + logger.Error(nil, "Unable to register route", "err", err) return } @@ -84,5 +82,5 @@ func main() { sigChannel := make(chan os.Signal, 1) signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting", receivedSig) + logger.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/std/examples/low-level/svs/main.go b/std/examples/low-level/svs/main.go index 163767d8..a5826c20 100644 --- a/std/examples/low-level/svs/main.go +++ b/std/examples/low-level/svs/main.go @@ -10,8 +10,6 @@ import ( "github.com/named-data/ndnd/std/sync" ) -const TAG = "svs" - func main() { // Before running this example, make sure the strategy is correctly setup // to multicast for the /ndn/svs prefix. For example, using the following: @@ -35,7 +33,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatal(TAG, "Unable to start engine", "err", err) + logger.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -46,21 +44,21 @@ func main() { Engine: app, GroupPrefix: group, OnUpdate: func(ssu sync.SvSyncUpdate) { - logger.Info(TAG, "Received update", "update", ssu) + logger.Info(nil, "Received update", "update", ssu) }, }) // Register group prefix route err = app.RegisterRoute(group) if err != nil { - logger.Error(TAG, "Unable to register route", "err", err) + logger.Error(nil, "Unable to register route", "err", err) return } defer app.UnregisterRoute(group) err = svsync.Start() if err != nil { - logger.Error(TAG, "Unable to create SvSync", "err", err) + logger.Error(nil, "Unable to create SvSync", "err", err) return } @@ -69,6 +67,6 @@ func main() { for range ticker.C { seq := svsync.IncrSeqNo(name) - logger.Info(TAG, "Published new sequence number", "seq", seq) + logger.Info(nil, "Published new sequence number", "seq", seq) } } diff --git a/std/log/level.go b/std/log/level.go index c8e5f8d3..204476b0 100644 --- a/std/log/level.go +++ b/std/log/level.go @@ -43,6 +43,8 @@ func (level Level) String() string { return "WARN" case LevelError: return "ERROR" + case LevelFatal: + return "FATAL" default: return "UNKNOWN" } diff --git a/std/log/slog.go b/std/log/slog.go index e1af74dd..c6ce1c46 100644 --- a/std/log/slog.go +++ b/std/log/slog.go @@ -5,6 +5,7 @@ import ( "io" "log/slog" "runtime" + "strings" ) type Logger struct { @@ -49,27 +50,32 @@ func (l *Logger) Level() Level { } // Generic level message. -func (l *Logger) log(t any, msg string, level Level, v ...any) { +func (l *Logger) log(t Tag, msg string, level Level, v ...any) { if l.level > level { return } - // Get source information if debug logs - if l.level <= LevelDebug { + // Get source information + var source string + if l.level <= LevelDebug || t == nil { if pc, _, _, ok := runtime.Caller(2); ok { if f := runtime.FuncForPC(pc); f != nil { - v = append(v, slog.SourceKey, f.Name()) + source = f.Name() } } } - // Get tag + // Keep source information if debug + if l.level <= LevelDebug { + v = append(v, slog.SourceKey, source) + } + + // Get tag or use source as tag if t != nil { - if tag, ok := t.(Tag); ok { - v = append([]any{"tag", tag.String()}, v...) - } else { - v = append([]any{"tag", t}, v...) - } + v = append([]any{"tag", t.String()}, v...) + } else if source != "" { + parts := strings.Split(source, "/") + v = append([]any{"tag", parts[len(parts)-1]}, v...) } // Log the message @@ -77,32 +83,32 @@ func (l *Logger) log(t any, msg string, level Level, v ...any) { } // Trace level message. -func (l *Logger) Trace(t any, msg string, v ...any) { +func (l *Logger) Trace(t Tag, msg string, v ...any) { l.log(t, msg, LevelTrace, v...) } // Debug level message. -func (l *Logger) Debug(t any, msg string, v ...any) { +func (l *Logger) Debug(t Tag, msg string, v ...any) { l.log(t, msg, LevelDebug, v...) } // Info level message. -func (l *Logger) Info(t any, msg string, v ...any) { +func (l *Logger) Info(t Tag, msg string, v ...any) { l.log(t, msg, LevelInfo, v...) } // Warn level message. -func (l *Logger) Warn(t any, msg string, v ...any) { +func (l *Logger) Warn(t Tag, msg string, v ...any) { l.log(t, msg, LevelWarn, v...) } // Error level message. -func (l *Logger) Error(t any, msg string, v ...any) { +func (l *Logger) Error(t Tag, msg string, v ...any) { l.log(t, msg, LevelError, v...) } // Fatal level message, followed by an exit. -func (l *Logger) Fatal(t any, msg string, v ...any) { +func (l *Logger) Fatal(t Tag, msg string, v ...any) { l.log(t, msg, LevelFatal, v...) } From 528d7f07fe4cc03e52ab5ba0c00d7093f97b120a Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 00:13:05 +0000 Subject: [PATCH 04/12] std: adapt to log --- dv/dv/advert_data.go | 54 +++++++++++----------- dv/dv/advert_sync.go | 74 ++++++++++++++++++------------ dv/dv/prefix_sync.go | 4 +- dv/dv/readvertise.go | 12 ++--- dv/dv/router.go | 37 ++++++++------- dv/dv/status.go | 2 +- dv/dv/table_algo.go | 8 ++-- dv/nfdc/nfdc.go | 7 ++- dv/table/neighbor_table.go | 6 ++- dv/table/prefix_table.go | 28 ++++++----- dv/table/rib.go | 11 +++-- fw/executor/main.go | 2 +- fw/executor/profiler.go | 2 +- fw/executor/yanfd.go | 2 +- fw/face/internal-transport.go | 5 +- fw/face/link-service.go | 6 +-- fw/face/multicast-udp-transport.go | 2 +- fw/face/ndnlp-link-service.go | 9 ---- fw/face/null-link-service.go | 10 ---- fw/face/null-transport.go | 4 +- fw/face/table.go | 2 +- fw/face/tcp-listener.go | 2 +- fw/face/udp-listener.go | 2 +- fw/face/unicast-tcp-transport.go | 2 +- fw/face/unicast-udp-transport.go | 2 +- fw/face/unix-stream-listener.go | 7 +-- fw/face/unix-stream-transport.go | 2 +- fw/face/web-socket-listener.go | 8 +--- fw/face/web-socket-transport.go | 2 +- fw/fw/bestroute.go | 2 +- fw/fw/multicast.go | 2 +- fw/fw/strategy.go | 4 +- fw/fw/thread.go | 4 +- fw/mgmt/cs.go | 2 +- fw/mgmt/face.go | 2 +- fw/mgmt/fib.go | 2 +- fw/mgmt/forwarder-status.go | 2 +- fw/mgmt/nlsr_readvertiser.go | 4 +- fw/mgmt/rib.go | 2 +- fw/mgmt/strategy-choice.go | 2 +- fw/mgmt/thread.go | 2 +- std/engine/basic/engine.go | 62 +++++++++++++------------ std/log/default.go | 59 +++++------------------- std/object/client.go | 5 ++ std/object/client_consume.go | 4 +- std/object/client_consume_seg.go | 9 +++- std/object/client_expressr.go | 2 +- std/sync/svs.go | 22 +++++---- tools/catchunks.go | 23 ++++++---- tools/pingclient.go | 13 ++++-- tools/pingserver.go | 17 ++++--- tools/putchunks.go | 17 ++++--- 52 files changed, 297 insertions(+), 280 deletions(-) diff --git a/dv/dv/advert_data.go b/dv/dv/advert_data.go index e7784d35..833c597b 100644 --- a/dv/dv/advert_data.go +++ b/dv/dv/advert_data.go @@ -10,37 +10,37 @@ import ( "github.com/named-data/ndnd/std/utils" ) -func (dv *Router) advertGenerateNew() { - dv.mutex.Lock() - defer dv.mutex.Unlock() +func (a *advertModule) generate() { + a.dv.mutex.Lock() + defer a.dv.mutex.Unlock() // Increment sequence number - dv.advertSyncSeq++ + a.seq++ // Produce the advertisement - name, err := dv.client.Produce(object.ProduceArgs{ - Name: dv.config.AdvertisementDataPrefix().Append( - enc.NewTimestampComponent(dv.advertBootTime), + name, err := a.dv.client.Produce(object.ProduceArgs{ + Name: a.dv.config.AdvertisementDataPrefix().Append( + enc.NewTimestampComponent(a.bootTime), ), - Content: dv.rib.Advert().Encode(), - Version: utils.IdPtr(dv.advertSyncSeq), + Content: a.dv.rib.Advert().Encode(), + Version: utils.IdPtr(a.seq), FreshnessPeriod: 10 * time.Second, }) if err != nil { - log.Errorf("advert-data: failed to produce advertisement: %+v", err) + log.Error(a, "Failed to produce advertisement", "err", err) } - dv.advertDir.Push(name) - dv.advertDir.Evict(dv.client) + a.objDir.Push(name) + a.objDir.Evict(a.dv.client) // Notify neighbors with sync for new advertisement - go dv.advertSyncSendInterest() + go a.sendSyncInterest() } -func (dv *Router) advertDataFetch(nName enc.Name, bootTime uint64, seqNo uint64) { +func (a *advertModule) dataFetch(nName enc.Name, bootTime uint64, seqNo uint64) { // debounce; wait before fetching, then check if this is still the latest // sequence number known for this neighbor time.Sleep(10 * time.Millisecond) - if ns := dv.neighbors.Get(nName); ns == nil || ns.AdvertBoot != bootTime || ns.AdvertSeq != seqNo { + if ns := a.dv.neighbors.Get(nName); ns == nil || ns.AdvertBoot != bootTime || ns.AdvertSeq != seqNo { return } @@ -52,7 +52,7 @@ func (dv *Router) advertDataFetch(nName enc.Name, bootTime uint64, seqNo uint64) enc.NewVersionComponent(seqNo), )...) - dv.client.Consume(advName, func(state *object.ConsumeState) bool { + a.dv.client.Consume(advName, func(state *object.ConsumeState) bool { if !state.IsComplete() { return true } @@ -60,14 +60,14 @@ func (dv *Router) advertDataFetch(nName enc.Name, bootTime uint64, seqNo uint64) go func() { fetchErr := state.Error() if fetchErr != nil { - log.Warnf("advert-data: failed to fetch advertisement %s: %+v", state.Name(), fetchErr) + log.Warn(a, "Failed to fetch advertisement", "name", state.Name(), "err", fetchErr) time.Sleep(1 * time.Second) // wait on error - dv.advertDataFetch(nName, bootTime, seqNo) + a.dataFetch(nName, bootTime, seqNo) return } // Process the advertisement - dv.advertDataHandler(nName, seqNo, state.Content()) + a.dataHandler(nName, seqNo, state.Content()) }() return true @@ -75,30 +75,30 @@ func (dv *Router) advertDataFetch(nName enc.Name, bootTime uint64, seqNo uint64) } // Received advertisement Data -func (dv *Router) advertDataHandler(nName enc.Name, seqNo uint64, data []byte) { +func (a *advertModule) dataHandler(nName enc.Name, seqNo uint64, data []byte) { // Lock DV state - dv.mutex.Lock() - defer dv.mutex.Unlock() + a.dv.mutex.Lock() + defer a.dv.mutex.Unlock() // Check if this is the latest advertisement - ns := dv.neighbors.Get(nName) + ns := a.dv.neighbors.Get(nName) if ns == nil { - log.Warnf("advert-data: unknown advertisement %s", nName) + log.Warn(a, "Unknown advertisement", "name", nName) return } if ns.AdvertSeq != seqNo { - log.Debugf("advert-data: old advertisement for %s (%d != %d)", nName, ns.AdvertSeq, seqNo) + log.Debug(a, "Old advertisement", "name", nName, "want", ns.AdvertSeq, "have", seqNo) return } // Parse the advertisement advert, err := tlv.ParseAdvertisement(enc.NewBufferReader(data), false) if err != nil { - log.Errorf("advert-data: failed to parse advertisement: %+v", err) + log.Error(a, "Failed to parse advertisement", "err", err) return } // Update the local advertisement list ns.Advert = advert - go dv.ribUpdate(ns) + go a.dv.ribUpdate(ns) } diff --git a/dv/dv/advert_sync.go b/dv/dv/advert_sync.go index d38970f3..d36b301b 100644 --- a/dv/dv/advert_sync.go +++ b/dv/dv/advert_sync.go @@ -9,27 +9,43 @@ import ( "github.com/named-data/ndnd/std/ndn" spec "github.com/named-data/ndnd/std/ndn/spec_2022" spec_svs "github.com/named-data/ndnd/std/ndn/svs/v3" + "github.com/named-data/ndnd/std/object" sec "github.com/named-data/ndnd/std/security" "github.com/named-data/ndnd/std/utils" ) -func (dv *Router) advertSyncSendInterest() (err error) { +type advertModule struct { + // parent router + dv *Router + // advertisement boot time for self + bootTime uint64 + // advertisement sequence number for self + seq uint64 + // object directory for advertisement data + objDir *object.MemoryFifoDir +} + +func (a *advertModule) String() string { + return "dv-advert" +} + +func (a *advertModule) sendSyncInterest() (err error) { // Sync Interests for our outgoing connections - err = dv.advertSyncSendInterestImpl(dv.config.AdvertisementSyncActivePrefix()) + err = a.sendSyncInterestImpl(a.dv.config.AdvertisementSyncActivePrefix()) if err != nil { - log.Warnf("advert-sync: failed to send active sync interest: %+v", err) + log.Error(a, "Failed to send active sync interest", "err", err) } // Sync Interests for incoming connections - err = dv.advertSyncSendInterestImpl(dv.config.AdvertisementSyncPassivePrefix()) + err = a.sendSyncInterestImpl(a.dv.config.AdvertisementSyncPassivePrefix()) if err != nil { - log.Warnf("advert-sync: failed to send passive sync interest: %+v", err) + log.Error(a, "Failed to send passive sync interest", "err", err) } return err } -func (dv *Router) advertSyncSendInterestImpl(prefix enc.Name) (err error) { +func (a *advertModule) sendSyncInterestImpl(prefix enc.Name) (err error) { // SVS v3 Sync Data syncName := prefix.Append(enc.NewVersionComponent(3)) @@ -37,10 +53,10 @@ func (dv *Router) advertSyncSendInterestImpl(prefix enc.Name) (err error) { sv := &spec_svs.SvsData{ StateVector: &spec_svs.StateVector{ Entries: []*spec_svs.StateVectorEntry{{ - Name: dv.config.RouterName(), + Name: a.dv.config.RouterName(), SeqNoEntries: []*spec_svs.SeqNoEntry{{ - BootstrapTime: dv.advertBootTime, - SeqNo: dv.advertSyncSeq, + BootstrapTime: a.bootTime, + SeqNo: a.seq, }}, }}, }, @@ -52,25 +68,25 @@ func (dv *Router) advertSyncSendInterestImpl(prefix enc.Name) (err error) { dataCfg := &ndn.DataConfig{ ContentType: utils.IdPtr(ndn.ContentTypeBlob), } - data, err := dv.engine.Spec().MakeData(syncName, dataCfg, sv.Encode(), signer) + data, err := a.dv.engine.Spec().MakeData(syncName, dataCfg, sv.Encode(), signer) if err != nil { - log.Errorf("advert-sync: sendSyncInterest failed make data: %+v", err) + log.Error(nil, "Failed make data", "err", err) return } // Make SVS Sync Interest intCfg := &ndn.InterestConfig{ Lifetime: utils.IdPtr(1 * time.Second), - Nonce: utils.ConvertNonce(dv.engine.Timer().Nonce()), + Nonce: utils.ConvertNonce(a.dv.engine.Timer().Nonce()), HopLimit: utils.IdPtr(uint(2)), // use localhop w/ this } - interest, err := dv.engine.Spec().MakeInterest(syncName, intCfg, data.Wire, nil) + interest, err := a.dv.engine.Spec().MakeInterest(syncName, intCfg, data.Wire, nil) if err != nil { return err } // Sync Interest has no reply - err = dv.engine.Express(interest, nil) + err = a.dv.engine.Express(interest, nil) if err != nil { return err } @@ -78,27 +94,27 @@ func (dv *Router) advertSyncSendInterestImpl(prefix enc.Name) (err error) { return nil } -func (dv *Router) advertSyncOnInterest(args ndn.InterestHandlerArgs, active bool) { +func (a *advertModule) OnSyncInterest(args ndn.InterestHandlerArgs, active bool) { // If there is no incoming face ID, we can't use this if args.IncomingFaceId == nil { - log.Warn("advert-sync: received Sync Interest with no incoming face ID, ignoring") + log.Warn(a, "Received Sync Interest with no incoming face ID, ignoring") return } // Check if app param is present if args.Interest.AppParam() == nil { - log.Warn("advert-sync: received Sync Interest with no AppParam, ignoring") + log.Warn(a, "Received Sync Interest with no AppParam, ignoring") return } // Decode Sync Data pkt, _, err := spec.ReadPacket(enc.NewWireReader(args.Interest.AppParam())) if err != nil { - log.Warnf("advert-sync: failed to parse Sync Data: %+v", err) + log.Warn(a, "Failed to parse Sync Data", "err", err) return } if pkt.Data == nil { - log.Warnf("advert-sync: no Sync Data, ignoring") + log.Warn(a, "No Sync Data, ignoring") return } @@ -108,20 +124,20 @@ func (dv *Router) advertSyncOnInterest(args ndn.InterestHandlerArgs, active bool svWire := pkt.Data.Content() params, err := spec_svs.ParseSvsData(enc.NewWireReader(svWire), false) if err != nil || params.StateVector == nil { - log.Warnf("advert-sync: failed to parse StateVec: %+v", err) + log.Warn(a, "Failed to parse StateVec", "err", err) return } // Process each entry in the state vector - dv.mutex.Lock() - defer dv.mutex.Unlock() + a.dv.mutex.Lock() + defer a.dv.mutex.Unlock() // FIB needs update if face changes for any neighbor fibDirty := false markRecvPing := func(ns *table.NeighborState) { err, faceDirty := ns.RecvPing(*args.IncomingFaceId, active) if err != nil { - log.Warnf("advert-sync: failed to update neighbor: %+v", err) + log.Warn(a, "Failed to update neighbor", "err", err) } fibDirty = fibDirty || faceDirty } @@ -129,19 +145,19 @@ func (dv *Router) advertSyncOnInterest(args ndn.InterestHandlerArgs, active bool // There should only be one entry in the StateVector, but check all anyway for _, node := range params.StateVector.Entries { if len(node.SeqNoEntries) != 1 { - log.Warnf("advert-sync: unexpected %d SeqNoEntries for %s, ignoring", len(node.SeqNoEntries), node.Name) + log.Warn(a, "Unexpected SeqNoEntries count", "count", len(node.SeqNoEntries), "router", node.Name) return } entry := node.SeqNoEntries[0] // Parse name from entry if node.Name == nil { - log.Warnf("advert-sync: failed to parse neighbor name: %+v", err) + log.Warn(a, "Failed to parse neighbor name", "err", err) continue } // Check if the entry is newer than what we know - ns := dv.neighbors.Get(node.Name) + ns := a.dv.neighbors.Get(node.Name) if ns != nil { if ns.AdvertBoot >= entry.BootstrapTime && ns.AdvertSeq >= entry.SeqNo { // Nothing has changed, skip @@ -152,18 +168,18 @@ func (dv *Router) advertSyncOnInterest(args ndn.InterestHandlerArgs, active bool // Create new neighbor entry cause none found // This is the ONLY place where neighbors are created // In all other places, quit if not found - ns = dv.neighbors.Add(node.Name) + ns = a.dv.neighbors.Add(node.Name) } markRecvPing(ns) ns.AdvertBoot = entry.BootstrapTime ns.AdvertSeq = entry.SeqNo - go dv.advertDataFetch(node.Name, entry.BootstrapTime, entry.SeqNo) + go a.dataFetch(node.Name, entry.BootstrapTime, entry.SeqNo) } // Update FIB if needed if fibDirty { - go dv.fibUpdate() + go a.dv.fibUpdate() } } diff --git a/dv/dv/prefix_sync.go b/dv/dv/prefix_sync.go index 42fd8687..a6cfcbad 100644 --- a/dv/dv/prefix_sync.go +++ b/dv/dv/prefix_sync.go @@ -57,7 +57,7 @@ func (dv *Router) prefixDataFetch(nName enc.Name) { router.Fetching = true // Fetch the prefix data object - log.Debugf("prefix-table: fetching object for %s [%d => %d]", nName, router.Known, router.Latest) + log.Debug(dv.pfx, "Fetching prefix data", "router", nName, "known", router.Known, "latest", router.Latest) name := router.GetNextDataName() dv.client.Consume(name, func(state *object.ConsumeState) bool { @@ -68,7 +68,7 @@ func (dv *Router) prefixDataFetch(nName enc.Name) { go func() { fetchErr := state.Error() if fetchErr != nil { - log.Warnf("prefix-table: failed to fetch object %s: %+v", state.Name(), fetchErr) + log.Warn(dv.pfx, "Failed to fetch prefix data", "name", state.Name(), "err", fetchErr) time.Sleep(1 * time.Second) // wait on error } diff --git a/dv/dv/readvertise.go b/dv/dv/readvertise.go index 7cdfe1b2..bf5c709a 100644 --- a/dv/dv/readvertise.go +++ b/dv/dv/readvertise.go @@ -32,7 +32,7 @@ func (dv *Router) readvertiseOnInterest(args ndn.InterestHandlerArgs) { res.Encode(), signer) if err != nil { - log.Warnf("readvertise: failed to make response Data: %+v", err) + log.Warn(dv, "Failed to make readvertise response Data", "err", err) return } args.Reply(data.Wire) @@ -42,23 +42,23 @@ func (dv *Router) readvertiseOnInterest(args ndn.InterestHandlerArgs) { // readvertise: /localhost/nlsr/rib/unregister/h%0C%07%07%08%05cathyo%01A/params-sha256=026dd595c75032c5101b321fbc11eeb96277661c66bc0564ac7ea1a281ae8210 iname := args.Interest.Name() if len(iname) != 6 { - log.Warnf("readvertise: invalid interest %s", iname) + log.Warn(dv, "Invalid readvertise Interest", "name", iname) return } module, cmd, advC := iname[2], iname[3], iname[4] if module.String() != "rib" { - log.Warnf("readvertise: unknown module %s", iname) + log.Warn(dv, "Unknown readvertise module", "name", iname) return } params, err := mgmt.ParseControlParameters(enc.NewBufferReader(advC.Val), false) if err != nil || params.Val == nil || params.Val.Name == nil { - log.Warnf("readvertise: failed to parse advertised name (%s)", err) + log.Warn(dv, "Failed to parse readvertised name", "err", err) return } - log.Debugf("readvertise: %s %s", cmd, params.Val.Name) + log.Debug(dv, "Received readvertise request", "cmd", cmd, "name", params.Val.Name) dv.mutex.Lock() defer dv.mutex.Unlock() @@ -68,7 +68,7 @@ func (dv *Router) readvertiseOnInterest(args ndn.InterestHandlerArgs) { case "unregister": dv.pfx.Withdraw(params.Val.Name) default: - log.Warnf("readvertise: unknown cmd %s", cmd) + log.Warn(dv, "Unknown readvertise cmd", "cmd", cmd) return } diff --git a/dv/dv/router.go b/dv/dv/router.go index 59bb17d9..980ba0b8 100644 --- a/dv/dv/router.go +++ b/dv/dv/router.go @@ -44,12 +44,8 @@ type Router struct { // forwarding table fib *table.Fib - // advertisement boot time for self - advertBootTime uint64 - // advertisement sequence number for self - advertSyncSeq uint64 - // object directory for advertisement data - advertDir *object.MemoryFifoDir + // advertisement module + advert advertModule // prefix table svs instance pfxSvs *ndn_sync.SvSync } @@ -71,16 +67,20 @@ func NewRouter(config *config.Config, engine ndn.Engine) (*Router, error) { mutex: sync.Mutex{}, } - // Initialize sync and dirs - dv.advertBootTime = uint64(time.Now().Unix()) - dv.advertDir = object.NewMemoryFifoDir(32) // keep last few advertisements + // Initialize advertisement module + dv.advert = advertModule{ + dv: dv, + bootTime: uint64(time.Now().Unix()), + seq: 0, + objDir: object.NewMemoryFifoDir(32), // keep last few advertisements + } // Create sync groups dv.pfxSvs = ndn_sync.NewSvSync(ndn_sync.SvSyncOpts{ Engine: engine, GroupPrefix: config.PrefixTableSyncPrefix(), OnUpdate: func(ssu ndn_sync.SvSyncUpdate) { go dv.onPfxSyncUpdate(ssu) }, - BootTime: dv.advertBootTime, + BootTime: dv.advert.bootTime, }) // Create tables @@ -92,10 +92,15 @@ func NewRouter(config *config.Config, engine ndn.Engine) (*Router, error) { return dv, nil } +// Log identifier for the DV router. +func (dv *Router) String() string { + return "dv-router" +} + // Start the DV router. Blocks until Stop() is called. func (dv *Router) Start() (err error) { - log.Infof("Starting DV router") - defer log.Infof("Stopping DV router") + log.Info(dv, "Starting router") + defer log.Info(dv, "Stopping router") // Initialize channels dv.stop = make(chan bool, 1) @@ -132,12 +137,12 @@ func (dv *Router) Start() (err error) { // Add self to the RIB and make initial advertisement dv.rib.Set(dv.config.RouterName(), dv.config.RouterName(), 0) - dv.advertGenerateNew() + dv.advert.generate() for { select { case <-dv.heartbeat.C: - dv.advertSyncSendInterest() + dv.advert.sendSyncInterest() case <-dv.deadcheck.C: dv.checkDeadNeighbors() case <-dv.stop: @@ -172,7 +177,7 @@ func (dv *Router) register() (err error) { // Advertisement Sync (active) err = dv.engine.AttachHandler(dv.config.AdvertisementSyncActivePrefix(), func(args ndn.InterestHandlerArgs) { - go dv.advertSyncOnInterest(args, true) + go dv.advert.OnSyncInterest(args, true) }) if err != nil { return err @@ -181,7 +186,7 @@ func (dv *Router) register() (err error) { // Advertisement Sync (passive) err = dv.engine.AttachHandler(dv.config.AdvertisementSyncPassivePrefix(), func(args ndn.InterestHandlerArgs) { - go dv.advertSyncOnInterest(args, false) + go dv.advert.OnSyncInterest(args, false) }) if err != nil { return err diff --git a/dv/dv/status.go b/dv/dv/status.go index 75395b52..ae9aa94f 100644 --- a/dv/dv/status.go +++ b/dv/dv/status.go @@ -26,7 +26,7 @@ func (dv *Router) statusOnInterest(args ndn.InterestHandlerArgs) { data, err := dv.engine.Spec().MakeData(name, cfg, status.Encode(), signer) if err != nil { - log.Warnf("readvertise: failed to make response Data: %+v", err) + log.Warn(dv, "Failed to make readvertise response Data", "err", err) return } diff --git a/dv/dv/table_algo.go b/dv/dv/table_algo.go index f5ca1335..a26f18e2 100644 --- a/dv/dv/table_algo.go +++ b/dv/dv/table_algo.go @@ -54,7 +54,7 @@ func (dv *Router) ribUpdate(ns *table.NeighborState) { if dirty { go func() { dv.fibUpdate() - dv.advertGenerateNew() + dv.advert.generate() dv.prefixDataFetchAll() }() } @@ -69,7 +69,7 @@ func (dv *Router) checkDeadNeighbors() { for _, ns := range dv.neighbors.GetAll() { // Check if the neighbor is entirely dead if ns.IsDead() { - log.Infof("table-algo: neighbor %s is dead", ns.Name.String()) + log.Info(dv, "Neighbor is dead", "router", ns.Name) // This is the ONLY place that can remove neighbors dv.neighbors.Remove(ns.Name) @@ -83,14 +83,14 @@ func (dv *Router) checkDeadNeighbors() { if dirty { go func() { dv.fibUpdate() - dv.advertGenerateNew() + dv.advert.generate() }() } } // Update the FIB func (dv *Router) fibUpdate() { - log.Debugf("table-algo: sychronizing updates to forwarding table") + log.Debug(dv, "Sychronizing updates to forwarding table") dv.mutex.Lock() defer dv.mutex.Unlock() diff --git a/dv/nfdc/nfdc.go b/dv/nfdc/nfdc.go index f7ac5a44..0e1d3232 100644 --- a/dv/nfdc/nfdc.go +++ b/dv/nfdc/nfdc.go @@ -32,6 +32,10 @@ func NewNfdMgmtThread(engine ndn.Engine) *NfdMgmtThread { } } +func (m *NfdMgmtThread) String() string { + return "dv-nfdc" +} + func (m *NfdMgmtThread) Start() { for { select { @@ -39,7 +43,8 @@ func (m *NfdMgmtThread) Start() { for i := 0; i < cmd.Retries || cmd.Retries < 0; i++ { _, err := m.engine.ExecMgmtCmd(cmd.Module, cmd.Cmd, cmd.Args) if err != nil { - log.Errorf("nfdc %s %s failed: %s %+v [%d]", cmd.Module, cmd.Cmd, cmd.Args.Name, err, i) + log.Error(m, "Forwarder command failed", "err", err, "attempt", i, + "module", cmd.Module, "cmd", cmd.Cmd, "args", cmd.Args) time.Sleep(100 * time.Millisecond) } else { time.Sleep(1 * time.Millisecond) diff --git a/dv/table/neighbor_table.go b/dv/table/neighbor_table.go index e45d4dbf..28684663 100644 --- a/dv/table/neighbor_table.go +++ b/dv/table/neighbor_table.go @@ -50,6 +50,10 @@ func NewNeighborTable(config *config.Config, nfdc *nfdc.NfdMgmtThread) *Neighbor } } +func (nt *NeighborTable) String() string { + return "dv-neighbors" +} + func (nt *NeighborTable) Get(name enc.Name) *NeighborState { return nt.GetH(name.Hash()) } @@ -111,7 +115,7 @@ func (ns *NeighborState) RecvPing(faceId uint64, active bool) (error, bool) { // If face ID has changed, re-register face. if ns.faceId != faceId { ns.isFaceActive = active - log.Infof("neighbor: %s face ID changed from %d to %d", ns.Name, ns.faceId, faceId) + log.Info(ns.nt, "Neighbor face change", "neighbor", ns.Name, "faceid", faceId, "old", ns.faceId) ns.routeUnregister() ns.routeRegister(faceId) return nil, true diff --git a/dv/table/prefix_table.go b/dv/table/prefix_table.go index d552392a..ae64b91d 100644 --- a/dv/table/prefix_table.go +++ b/dv/table/prefix_table.go @@ -63,6 +63,10 @@ func NewPrefixTable( return pt } +func (pt *PrefixTable) String() string { + return "dv-prefix" +} + func (pt *PrefixTable) GetRouter(name enc.Name) *PrefixTableRouter { hash := name.String() router := pt.routers[hash] @@ -77,7 +81,7 @@ func (pt *PrefixTable) GetRouter(name enc.Name) *PrefixTableRouter { } func (pt *PrefixTable) Reset() { - log.Infof("prefix-table: reset") + log.Info(pt, "Reset table") pt.me.Prefixes = make(map[string]*PrefixEntry) op := tlv.PrefixOpList{ @@ -88,7 +92,7 @@ func (pt *PrefixTable) Reset() { } func (pt *PrefixTable) Announce(name enc.Name) { - log.Infof("prefix-table: announcing %s", name) + log.Info(pt, "Announce prefix", "name", name) hash := name.String() // Skip if matching entry already exists @@ -111,7 +115,7 @@ func (pt *PrefixTable) Announce(name enc.Name) { } func (pt *PrefixTable) Withdraw(name enc.Name) { - log.Infof("prefix-table: withdrawing %s", name) + log.Info(pt, "Withdraw prefix", "name", name) hash := name.String() // Check if entry does not exist @@ -132,26 +136,26 @@ func (pt *PrefixTable) Withdraw(name enc.Name) { // Applies ops from a list. Returns if dirty. func (pt *PrefixTable) Apply(ops *tlv.PrefixOpList) (dirty bool) { if ops.ExitRouter == nil || len(ops.ExitRouter.Name) == 0 { - log.Error("prefix-table: received PrefixOpList has no ExitRouter") + log.Error(pt, "Received PrefixOpList has no ExitRouter") return false } router := pt.GetRouter(ops.ExitRouter.Name) if ops.PrefixOpReset { - log.Infof("prefix-table: reset prefix table for %s", ops.ExitRouter.Name) + log.Info(pt, "Reset prefixes for remote", "router", ops.ExitRouter.Name) router.Prefixes = make(map[string]*PrefixEntry) dirty = true } for _, add := range ops.PrefixOpAdds { - log.Infof("prefix-table: added prefix for %s: %s", ops.ExitRouter.Name, add.Name) + log.Info(pt, "Add prefix for remote", "router", ops.ExitRouter.Name, "name", add.Name) router.Prefixes[add.Name.String()] = &PrefixEntry{Name: add.Name} dirty = true } for _, remove := range ops.PrefixOpRemoves { - log.Infof("prefix-table: removed prefix for %s: %s", ops.ExitRouter.Name, remove.Name) + log.Info(pt, "Remove prefix for remote", "router", ops.ExitRouter.Name, "name", remove.Name) delete(router.Prefixes, remove.Name.String()) dirty = true } @@ -183,7 +187,7 @@ func (r *PrefixTableRouter) GetNextDataName() enc.Name { // Process the received prefix data. Returns if dirty. func (pt *PrefixTable) ApplyData(name enc.Name, data []byte, router *PrefixTableRouter) bool { if len(name) < 2 { - log.Warnf("prefix-table: unexpected name length: %d", len(name)) + log.Warn(pt, "Unexpected name length", "len", len(name)) return false } @@ -194,14 +198,14 @@ func (pt *PrefixTable) ApplyData(name enc.Name, data []byte, router *PrefixTable seqNo = name[len(name)-1] } else if seqNo.Typ != enc.TypeSequenceNumNameComponent { // version is immutable, sequence number is in name - log.Warnf("prefix-table: unexpected sequence number type: %s", seqNo.Typ) + log.Warn(pt, "Unexpected sequence number type", "type", seqNo.Typ) return false } // Parse the prefix data ops, err := tlv.ParsePrefixOpList(enc.NewBufferReader(data), true) if err != nil { - log.Warnf("prefix-table: failed to parse PrefixOpList: %+v", err) + log.Warn(pt, "Failed to parse PrefixOpList", "err", err) return false } @@ -226,7 +230,7 @@ func (pt *PrefixTable) publishOp(content enc.Wire) { Version: utils.IdPtr(uint64(0)), // immutable }) if err != nil { - log.Errorf("prefix-table: failed to produce op: %v", err) + log.Error(pt, "Failed to produce op", "err", err) return } pt.objDir.Push(name) @@ -259,7 +263,7 @@ func (pt *PrefixTable) publishSnap() { Version: utils.IdPtr(pt.me.Latest), }) if err != nil { - log.Errorf("prefix-table: failed to produce snap: %v", err) + log.Error(pt, "Failed to produce snap", "err", err) } pt.objDir.Push(name) pt.objDir.Evict(pt.client) diff --git a/dv/table/rib.go b/dv/table/rib.go index a9239fb9..0a359f05 100644 --- a/dv/table/rib.go +++ b/dv/table/rib.go @@ -46,6 +46,11 @@ func NewRib(config *config.Config) *Rib { } } +// Log identifier for the RIB. +func (r *Rib) String() string { + return "dv-rib" +} + // Print the RIB to the console (for debugging). func (r *Rib) Print() { for _, entry := range r.entries { @@ -208,9 +213,9 @@ func (e *RibEntry) refresh() bool { e.lowest2 = lowest2 e.nextHop1 = nextHop1 e.nextHop2 = nextHop2 - log.Infof("rib: update next hop %s => %s[%d], %s[%d]", e.name, - e.rib.neighbors[nextHop1], lowest1, - e.rib.neighbors[nextHop2], lowest2) + log.Info(e.rib, "Update next hop", "name", e.name, + "hop1", e.rib.neighbors[nextHop1], "cost1", lowest1, + "hop2", e.rib.neighbors[nextHop2], "cost2", lowest2) return true } diff --git a/fw/executor/main.go b/fw/executor/main.go index 2d7ed4b9..cd46dc8d 100644 --- a/fw/executor/main.go +++ b/fw/executor/main.go @@ -70,7 +70,7 @@ func Main(args []string) { sigChannel := make(chan os.Signal, 1) signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - core.Log.Info(yanfd, "received signal - exit", "signal", receivedSig) + core.Log.Info(yanfd, "Received signal - exit", "signal", receivedSig) yanfd.Stop() } diff --git a/fw/executor/profiler.go b/fw/executor/profiler.go index 89718e97..f548e471 100644 --- a/fw/executor/profiler.go +++ b/fw/executor/profiler.go @@ -19,7 +19,7 @@ func NewProfiler(config *YaNFDConfig) *Profiler { } func (p *Profiler) String() string { - return "Profiler" + return "profiler" } func (p *Profiler) Start() (err error) { diff --git a/fw/executor/yanfd.go b/fw/executor/yanfd.go index 8de354f2..96375968 100644 --- a/fw/executor/yanfd.go +++ b/fw/executor/yanfd.go @@ -49,7 +49,7 @@ type YaNFD struct { } func (y *YaNFD) String() string { - return "YaNFD" + return "yanfd" } // NewYaNFD creates a YaNFD. Don't call this function twice. diff --git a/fw/face/internal-transport.go b/fw/face/internal-transport.go index 135d09fa..b6783681 100644 --- a/fw/face/internal-transport.go +++ b/fw/face/internal-transport.go @@ -8,7 +8,7 @@ package face import ( - "strconv" + "fmt" "github.com/named-data/ndnd/fw/core" defn "github.com/named-data/ndnd/fw/defn" @@ -54,8 +54,7 @@ func RegisterInternalTransport() (LinkService, *InternalTransport) { } func (t *InternalTransport) String() string { - return "InternalTransport, FaceID=" + strconv.FormatUint(t.faceID, 10) + - ", RemoteURI=" + t.remoteURI.String() + ", LocalURI=" + t.localURI.String() + return fmt.Sprintf("internal-transport (faceid=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } // SetPersistency changes the persistency of the face. diff --git a/fw/face/link-service.go b/fw/face/link-service.go index 2264d7b3..61016f60 100644 --- a/fw/face/link-service.go +++ b/fw/face/link-service.go @@ -9,7 +9,7 @@ package face import ( "encoding/binary" - "strconv" + "fmt" "time" "github.com/named-data/ndnd/fw/core" @@ -75,10 +75,10 @@ type linkServiceBase struct { func (l *linkServiceBase) String() string { if l.transport != nil { - return "LinkService, " + l.transport.String() + return fmt.Sprintf("link-service (%s)", l.transport) } - return "LinkService, FaceID=" + strconv.FormatUint(l.faceID, 10) + return fmt.Sprintf("link-service (faceid=%d)", l.faceID) } func (l *linkServiceBase) SetFaceID(faceID uint64) { diff --git a/fw/face/multicast-udp-transport.go b/fw/face/multicast-udp-transport.go index 175387e2..4d3dbc20 100644 --- a/fw/face/multicast-udp-transport.go +++ b/fw/face/multicast-udp-transport.go @@ -105,7 +105,7 @@ func (t *MulticastUDPTransport) connectRecv() error { } func (t *MulticastUDPTransport) String() string { - return fmt.Sprintf("MulticastUDPTransport, FaceID=%d, RemoteURI=%s, LocalURI=%s", t.faceID, t.remoteURI, t.localURI) + return fmt.Sprintf("multicast-udp-transport (faceid=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } func (t *MulticastUDPTransport) SetPersistency(persistency spec_mgmt.Persistency) bool { diff --git a/fw/face/ndnlp-link-service.go b/fw/face/ndnlp-link-service.go index e8581b72..160987b6 100644 --- a/fw/face/ndnlp-link-service.go +++ b/fw/face/ndnlp-link-service.go @@ -10,7 +10,6 @@ package face import ( "math" "runtime" - "strconv" "time" "github.com/named-data/ndnd/fw/core" @@ -96,14 +95,6 @@ func MakeNDNLPLinkService(transport transport, options NDNLPLinkServiceOptions) return l } -func (l *NDNLPLinkService) String() string { - if l.transport != nil { - return "NDNLPLinkService, " + l.transport.String() - } - - return "NDNLPLinkService, FaceID=" + strconv.FormatUint(l.faceID, 10) -} - // Options gets the settings of the NDNLPLinkService. func (l *NDNLPLinkService) Options() NDNLPLinkServiceOptions { return l.options diff --git a/fw/face/null-link-service.go b/fw/face/null-link-service.go index 75251df4..c2e8b43b 100644 --- a/fw/face/null-link-service.go +++ b/fw/face/null-link-service.go @@ -8,8 +8,6 @@ package face import ( - "strconv" - "github.com/named-data/ndnd/fw/core" ) @@ -27,14 +25,6 @@ func MakeNullLinkService(transport transport) *NullLinkService { return l } -func (l *NullLinkService) String() string { - if l.transport != nil { - return "NullLinkService, " + l.transport.String() - } - - return "NullLinkService, FaceID=" + strconv.FormatUint(l.faceID, 10) -} - // Run runs the NullLinkService. func (l *NullLinkService) Run(initial []byte) { FaceTable.Add(l) diff --git a/fw/face/null-transport.go b/fw/face/null-transport.go index ca076c4a..0db4e8a1 100644 --- a/fw/face/null-transport.go +++ b/fw/face/null-transport.go @@ -8,7 +8,7 @@ package face import ( - "strconv" + "fmt" defn "github.com/named-data/ndnd/fw/defn" spec_mgmt "github.com/named-data/ndnd/std/ndn/mgmt_2022" @@ -36,7 +36,7 @@ func MakeNullTransport() *NullTransport { } func (t *NullTransport) String() string { - return "NullTransport, FaceID=" + strconv.FormatUint(t.faceID, 10) + ", RemoteURI=" + t.remoteURI.String() + ", LocalURI=" + t.localURI.String() + return fmt.Sprintf("null-transport (faceid=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } // SetPersistency changes the persistency of the face. diff --git a/fw/face/table.go b/fw/face/table.go index 82b11579..0141b1e5 100644 --- a/fw/face/table.go +++ b/fw/face/table.go @@ -34,7 +34,7 @@ func init() { } func (t *Table) String() string { - return "FaceTable" + return "face-table" } // Add adds a face to the face table. diff --git a/fw/face/tcp-listener.go b/fw/face/tcp-listener.go index 33fd9a74..e8079a92 100644 --- a/fw/face/tcp-listener.go +++ b/fw/face/tcp-listener.go @@ -40,7 +40,7 @@ func MakeTCPListener(localURI *defn.URI) (*TCPListener, error) { } func (l *TCPListener) String() string { - return fmt.Sprintf("TCPListener, %s", l.localURI) + return fmt.Sprintf("tcp-listener (%s)", l.localURI) } func (l *TCPListener) Run() { diff --git a/fw/face/udp-listener.go b/fw/face/udp-listener.go index 5dc647d7..2efce136 100644 --- a/fw/face/udp-listener.go +++ b/fw/face/udp-listener.go @@ -40,7 +40,7 @@ func MakeUDPListener(localURI *defn.URI) (*UDPListener, error) { } func (l *UDPListener) String() string { - return fmt.Sprintf("UDPListener, %s", l.localURI) + return fmt.Sprintf("udp-listener (%s)", l.localURI) } // Run starts the UDP listener. diff --git a/fw/face/unicast-tcp-transport.go b/fw/face/unicast-tcp-transport.go index e7b3df12..f7993a0f 100644 --- a/fw/face/unicast-tcp-transport.go +++ b/fw/face/unicast-tcp-transport.go @@ -132,7 +132,7 @@ func AcceptUnicastTCPTransport( } func (t *UnicastTCPTransport) String() string { - return fmt.Sprintf("UnicastTCPTransport, FaceID=%d, RemoteURI=%s, LocalURI=%s", t.faceID, t.remoteURI, t.localURI) + return fmt.Sprintf("unicast-tcp-transport (faceid=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } func (t *UnicastTCPTransport) SetPersistency(persistency spec_mgmt.Persistency) bool { diff --git a/fw/face/unicast-udp-transport.go b/fw/face/unicast-udp-transport.go index d194392a..035b3676 100644 --- a/fw/face/unicast-udp-transport.go +++ b/fw/face/unicast-udp-transport.go @@ -92,7 +92,7 @@ func MakeUnicastUDPTransport( } func (t *UnicastUDPTransport) String() string { - return fmt.Sprintf("UnicastUDPTransport, FaceID=%d, RemoteURI=%s, LocalURI=%s", t.faceID, t.remoteURI, t.localURI) + return fmt.Sprintf("unicast-udp-transport (face=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } func (t *UnicastUDPTransport) SetPersistency(persistency spec_mgmt.Persistency) bool { diff --git a/fw/face/unix-stream-listener.go b/fw/face/unix-stream-listener.go index e0f1fdd3..3cccb966 100644 --- a/fw/face/unix-stream-listener.go +++ b/fw/face/unix-stream-listener.go @@ -9,6 +9,7 @@ package face import ( "errors" + "fmt" "net" "os" "path" @@ -40,7 +41,7 @@ func MakeUnixStreamListener(localURI *defn.URI) (*UnixStreamListener, error) { } func (l *UnixStreamListener) String() string { - return "UnixStreamListener, " + l.localURI.String() + return fmt.Sprintf("unix-stream-listener (%s)", l.localURI) } func (l *UnixStreamListener) Run() { @@ -87,11 +88,11 @@ func (l *UnixStreamListener) Run() { newTransport, err := MakeUnixStreamTransport(remoteURI, l.localURI, newConn) if err != nil { - core.Log.Error(l, "Failed to create new Unix stream transport", "err", err) + core.Log.Error(l, "Failed to create new unix stream transport", "err", err) continue } - core.Log.Info(l, "Accepting new Unix stream face", "uri", remoteURI) + core.Log.Info(l, "Accepting new unix stream face", "uri", remoteURI) options := MakeNDNLPLinkServiceOptions() options.IsFragmentationEnabled = false // reliable stream MakeNDNLPLinkService(newTransport, options).Run(nil) diff --git a/fw/face/unix-stream-transport.go b/fw/face/unix-stream-transport.go index 5d59bc8e..78d818e0 100644 --- a/fw/face/unix-stream-transport.go +++ b/fw/face/unix-stream-transport.go @@ -41,7 +41,7 @@ func MakeUnixStreamTransport(remoteURI *defn.URI, localURI *defn.URI, conn net.C } func (t *UnixStreamTransport) String() string { - return fmt.Sprintf("UnixStreamTransport, FaceID=%d, RemoteURI=%s, LocalURI=%s", t.faceID, t.remoteURI, t.localURI) + return fmt.Sprintf("unix-stream-transport (faceid=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } // SetPersistency changes the persistency of the face. diff --git a/fw/face/web-socket-listener.go b/fw/face/web-socket-listener.go index 29c9dd2d..548a2139 100644 --- a/fw/face/web-socket-listener.go +++ b/fw/face/web-socket-listener.go @@ -16,7 +16,6 @@ import ( "net/http" "net/url" "strconv" - "strings" "sync" "github.com/gorilla/websocket" @@ -53,12 +52,7 @@ func (cfg WebSocketListenerConfig) URL() *url.URL { } func (cfg WebSocketListenerConfig) String() string { - var b strings.Builder - fmt.Fprintf(&b, "WebSocket listener at %s", cfg.URL()) - if cfg.TLSEnabled { - fmt.Fprintf(&b, " with TLS cert %s and key %s", cfg.TLSCert, cfg.TLSKey) - } - return b.String() + return fmt.Sprintf("web-socket-listener (url=%s tls=%s)", cfg.URL(), cfg.TLSCert) } func NewWebSocketListener(cfg WebSocketListenerConfig) (*WebSocketListener, error) { diff --git a/fw/face/web-socket-transport.go b/fw/face/web-socket-transport.go index f12bcd61..3f19c743 100644 --- a/fw/face/web-socket-transport.go +++ b/fw/face/web-socket-transport.go @@ -40,7 +40,7 @@ func NewWebSocketTransport(localURI *defn.URI, c *websocket.Conn) (t *WebSocketT } func (t *WebSocketTransport) String() string { - return fmt.Sprintf("WebSocketTransport, FaceID=%d, RemoteURI=%s, LocalURI=%s", t.faceID, t.remoteURI, t.localURI) + return fmt.Sprintf("web-socket-transport (faceid=%d remote=%s local=%s)", t.faceID, t.remoteURI, t.localURI) } func (t *WebSocketTransport) SetPersistency(persistency spec_mgmt.Persistency) bool { diff --git a/fw/fw/bestroute.go b/fw/fw/bestroute.go index 391bf286..bda00262 100644 --- a/fw/fw/bestroute.go +++ b/fw/fw/bestroute.go @@ -35,7 +35,7 @@ func init() { func (s *BestRoute) Instantiate(fwThread *Thread) { s.NewStrategyBase(fwThread, enc.Component{ Typ: enc.TypeGenericNameComponent, Val: []byte("best-route"), - }, 1, "BestRoute") + }, 1, "bestroute") } func (s *BestRoute) AfterContentStoreHit( diff --git a/fw/fw/multicast.go b/fw/fw/multicast.go index 75b2a5e5..74df07d9 100644 --- a/fw/fw/multicast.go +++ b/fw/fw/multicast.go @@ -33,7 +33,7 @@ func init() { func (s *Multicast) Instantiate(fwThread *Thread) { s.NewStrategyBase(fwThread, enc.Component{ Typ: enc.TypeGenericNameComponent, Val: []byte("multicast"), - }, 1, "Multicast") + }, 1, "multicast") } func (s *Multicast) AfterContentStoreHit( diff --git a/fw/fw/strategy.go b/fw/fw/strategy.go index c6820146..fb55f818 100644 --- a/fw/fw/strategy.go +++ b/fw/fw/strategy.go @@ -8,7 +8,7 @@ package fw import ( - "strconv" + "fmt" "github.com/named-data/ndnd/fw/defn" "github.com/named-data/ndnd/fw/table" @@ -65,7 +65,7 @@ func (s *StrategyBase) NewStrategyBase( } func (s *StrategyBase) String() string { - return s.strategyLogName + "-v" + strconv.FormatUint(s.version, 10) + "-Thread" + strconv.Itoa(s.threadID) + return fmt.Sprintf("%s (v=%d t=%d)", s.strategyLogName, s.version, s.threadID) } // GetName returns the name of strategy, including version information. diff --git a/fw/fw/thread.go b/fw/fw/thread.go index 1dc925d5..87bb083a 100644 --- a/fw/fw/thread.go +++ b/fw/fw/thread.go @@ -9,8 +9,8 @@ package fw import ( "encoding/binary" + "fmt" "runtime" - "strconv" "github.com/named-data/ndnd/fw/core" "github.com/named-data/ndnd/fw/defn" @@ -92,7 +92,7 @@ func NewThread(id int) *Thread { } func (t *Thread) String() string { - return "FwThread-" + strconv.Itoa(t.threadID) + return fmt.Sprintf("fw-thread-%d", t.threadID) } // GetID returns the ID of the forwarding thread diff --git a/fw/mgmt/cs.go b/fw/mgmt/cs.go index 33eff242..1c5a0aaf 100644 --- a/fw/mgmt/cs.go +++ b/fw/mgmt/cs.go @@ -23,7 +23,7 @@ type ContentStoreModule struct { } func (c *ContentStoreModule) String() string { - return "ContentStoreMgmt" + return "mgmt-cs" } func (c *ContentStoreModule) registerManager(manager *Thread) { diff --git a/fw/mgmt/face.go b/fw/mgmt/face.go index 2a511487..2fec27b5 100644 --- a/fw/mgmt/face.go +++ b/fw/mgmt/face.go @@ -27,7 +27,7 @@ type FaceModule struct { } func (f *FaceModule) String() string { - return "FaceMgmt" + return "mgmt-face" } func (f *FaceModule) registerManager(manager *Thread) { diff --git a/fw/mgmt/fib.go b/fw/mgmt/fib.go index b19e234b..84b81c84 100644 --- a/fw/mgmt/fib.go +++ b/fw/mgmt/fib.go @@ -22,7 +22,7 @@ type FIBModule struct { } func (f *FIBModule) String() string { - return "FIBMgmt" + return "mgmt-fib" } func (f *FIBModule) registerManager(manager *Thread) { diff --git a/fw/mgmt/forwarder-status.go b/fw/mgmt/forwarder-status.go index f9753591..bf025af1 100644 --- a/fw/mgmt/forwarder-status.go +++ b/fw/mgmt/forwarder-status.go @@ -24,7 +24,7 @@ type ForwarderStatusModule struct { } func (f *ForwarderStatusModule) String() string { - return "ForwarderStatusMgmt" + return "mgmt-status" } func (f *ForwarderStatusModule) registerManager(manager *Thread) { diff --git a/fw/mgmt/nlsr_readvertiser.go b/fw/mgmt/nlsr_readvertiser.go index 2a19b85a..06f40560 100644 --- a/fw/mgmt/nlsr_readvertiser.go +++ b/fw/mgmt/nlsr_readvertiser.go @@ -28,7 +28,7 @@ func NewNlsrReadvertiser(m *Thread) *NlsrReadvertiser { } func (r *NlsrReadvertiser) String() string { - return "NlsrReadvertiser" + return "mgmt-nlsr-readvertiser" } func (r *NlsrReadvertiser) Announce(name enc.Name, route *table.Route) { @@ -64,7 +64,7 @@ func (r *NlsrReadvertiser) Announce(name enc.Name, route *table.Route) { func (r *NlsrReadvertiser) Withdraw(name enc.Name, route *table.Route) { if route.Origin != uint64(spec_mgmt.RouteOriginClient) { - core.Log.Debug(r, "Skip withdraw", "name", name, "origin", route.Origin) + core.Log.Debug(r, "Skip withdraw (origin)", "name", name, "origin", route.Origin) return } diff --git a/fw/mgmt/rib.go b/fw/mgmt/rib.go index 6657f5be..2bd6a2bc 100644 --- a/fw/mgmt/rib.go +++ b/fw/mgmt/rib.go @@ -26,7 +26,7 @@ type RIBModule struct { } func (r *RIBModule) String() string { - return "RIBMgmt" + return "mgmt-rib" } func (r *RIBModule) registerManager(manager *Thread) { diff --git a/fw/mgmt/strategy-choice.go b/fw/mgmt/strategy-choice.go index 30d1c763..384ef34d 100644 --- a/fw/mgmt/strategy-choice.go +++ b/fw/mgmt/strategy-choice.go @@ -22,7 +22,7 @@ type StrategyChoiceModule struct { } func (s *StrategyChoiceModule) String() string { - return "StrategyChoiceMgmt" + return "mgmt-strategy" } func (s *StrategyChoiceModule) registerManager(manager *Thread) { diff --git a/fw/mgmt/thread.go b/fw/mgmt/thread.go index bf31f294..680ce936 100644 --- a/fw/mgmt/thread.go +++ b/fw/mgmt/thread.go @@ -40,7 +40,7 @@ type Thread struct { } func (m *Thread) String() string { - return "Mgmt" + return "mgmt" } // MakeMgmtThread creates a new management thread. diff --git a/std/engine/basic/engine.go b/std/engine/basic/engine.go index 7666520f..61dfa20e 100644 --- a/std/engine/basic/engine.go +++ b/std/engine/basic/engine.go @@ -5,6 +5,7 @@ package basic import ( "bytes" "crypto/sha256" + "encoding/hex" "errors" "fmt" "sync" @@ -57,6 +58,10 @@ type Engine struct { cmdChecker ndn.SigChecker } +func (e *Engine) String() string { + return "BasicEngine" +} + func (e *Engine) EngineTrait() ndn.Engine { return e } @@ -98,14 +103,14 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { var incomingFaceId *uint64 = nil var raw enc.Wire = nil - if log.HasTrace() { + if hasLogTrace() { wire := reader.Range(0, reader.Length()) - log.Trace("received packet bytes", "wire", wire.Join()) + log.Trace(e, "Received packet bytes", "wire", hex.EncodeToString(wire.Join())) } pkt, ctx, err := spec.ReadPacket(reader) if err != nil { - log.Errorf("failed to parse packet", "err", err) + log.Error(e, "Failed to parse packet", "err", err) // Recoverable error. Should continue. return nil } @@ -114,7 +119,7 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { if pkt.LpPacket != nil { lpPkt := pkt.LpPacket if lpPkt.FragIndex != nil || lpPkt.FragCount != nil { - log.Warn("fragmented LpPackets are not supported - DROP") + log.Warn(e, "Fragmented LpPackets are not supported - DROP") return nil } // Parse the inner packet. @@ -125,10 +130,10 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { pkt, ctx, err = spec.ReadPacket(enc.NewWireReader(raw)) } if err != nil || (pkt.Data == nil) == (pkt.Interest == nil) { - log.Errorf("failed to parse packet in LpPacket", "err", err) - if log.HasTrace() { + log.Error(e, "Failed to parse packet in LpPacket", "err", err) + if hasLogTrace() { wire := reader.Range(0, reader.Length()) - log.Trace("failed packet bytes", "wire", wire.Join()) + log.Trace(e, "Failed to parse packet bytes", "wire", hex.EncodeToString(wire.Join())) } // Recoverable error. Should continue. return nil @@ -145,17 +150,13 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { // Now pkt is either Data or Interest (including Nack). if nackReason != spec.NackReasonNone { if pkt.Interest == nil { - log.Error("received nack for an Data") + log.Error(e, "Nack received for non-Interest", "reason", nackReason) return nil } - if log.HasTrace() { - log.Trace("nack received", "reason", nackReason, "name", pkt.Interest.Name()) - } + log.Trace(e, "Nack received", "reason", nackReason, "name", pkt.Interest.Name()) e.onNack(pkt.Interest.NameV, nackReason) } else if pkt.Interest != nil { - if log.HasTrace() { - log.Trace("interest received", "name", pkt.Interest.Name()) - } + log.Trace(e, "Interest received", "name", pkt.Interest.Name()) e.onInterest(ndn.InterestHandlerArgs{ Interest: pkt.Interest, RawInterest: raw, @@ -164,9 +165,7 @@ func (e *Engine) onPacket(reader enc.ParseReader) error { IncomingFaceId: incomingFaceId, }) } else if pkt.Data != nil { - if log.HasTrace() { - log.Trace("data received", "name", pkt.Data.Name()) - } + log.Trace(e, "Data received", "name", pkt.Data.Name()) // PitToken is not used for now e.onData(pkt.Data, ctx.Data_context.SigCovered(), raw, pitToken) } else { @@ -205,7 +204,7 @@ func (e *Engine) onInterest(args ndn.InterestHandlerArgs) { return nil }() if handler == nil { - log.Warn("no handler for interest", "name", name) + log.Warn(e, "No handler for interest", "name", name) return } @@ -213,11 +212,11 @@ func (e *Engine) onInterest(args ndn.InterestHandlerArgs) { args.Reply = func(encodedData enc.Wire) error { now := e.timer.Now() if args.Deadline.Before(now) { - log.Warn("deadline exceeded - DROP", "name", name) + log.Warn(e, "Deadline exceeded - DROP", "name", name) return ndn.ErrDeadlineExceed } if !e.face.IsRunning() { - log.Error("cannot send through a closed face - DROP", "name", name) + log.Error(e, "Cannot send through a closed face - DROP", "name", name) return ndn.ErrFaceDown } if args.PitToken != nil { @@ -250,7 +249,7 @@ func (e *Engine) onData(pkt *spec.Data, sigCovered enc.Wire, raw enc.Wire, pitTo n := e.pit.PrefixMatch(pkt.NameV) if n == nil { - log.Warn("received data for an unknown interest - DROP", "name", pkt.Name()) + log.Warn(e, "Received data for an unknown interest - DROP", "name", pkt.Name()) return } @@ -311,7 +310,7 @@ func (e *Engine) onNack(name enc.Name, reason uint64) { defer e.pitLock.Unlock() n := e.pit.ExactMatch(name) if n == nil { - log.Warn("received Nack for an unknown interest - DROP", "name", name) + log.Warn(e, "Received Nack for an unknown interest - DROP", "name", name) return } for _, entry := range n.Value() { @@ -329,7 +328,7 @@ func (e *Engine) onNack(name enc.Name, reason uint64) { } func (e *Engine) onError(err error) error { - log.Error("error on face", "err", err) + log.Error(e, "Error on face", "err", err) // TODO: Handle Interest cancellation return err } @@ -429,11 +428,10 @@ func (e *Engine) Express(interest *ndn.EncodedInterest, callback ndn.ExpressCall // Send interest err := e.face.Send(interest.Wire) if err != nil { - log.Error("failed to send interest", "err", err) - } else if log.HasTrace() { - log.Trace("interest sent", "name", finalName) + log.Error(e, "Failed to send interest", "err", err) } + log.Trace(e, "Interest sent", "name", finalName) return err } @@ -507,10 +505,10 @@ func (e *Engine) ExecMgmtCmd(module string, cmd string, args any) (any, error) { func (e *Engine) RegisterRoute(prefix enc.Name) error { _, err := e.ExecMgmtCmd("rib", "register", &mgmt.ControlArgs{Name: prefix}) if err != nil { - log.Error("failed to register prefix", "err", err, "name", prefix) + log.Error(e, "Failed to register prefix", "err", err, "name", prefix) return err } else { - log.Info("prefix registered", "name", prefix) + log.Info(e, "Prefix registered", "name", prefix) } return nil } @@ -518,10 +516,10 @@ func (e *Engine) RegisterRoute(prefix enc.Name) error { func (e *Engine) UnregisterRoute(prefix enc.Name) error { _, err := e.ExecMgmtCmd("rib", "unregister", &mgmt.ControlArgs{Name: prefix}) if err != nil { - log.Error("failed to unregister prefix", "err", err, "name", prefix) + log.Error(e, "Failed to unregister prefix", "err", err, "name", prefix) return err } else { - log.Info("prefix unregistered", "name", prefix) + log.Info(e, "Prefix unregistered", "name", prefix) } return nil } @@ -542,3 +540,7 @@ func NewEngine(face face.Face, timer ndn.Timer, cmdSigner ndn.Signer, cmdChecker pitLock: sync.Mutex{}, } } + +func hasLogTrace() bool { + return log.Default().Level() <= log.LevelTrace +} diff --git a/std/log/default.go b/std/log/default.go index ba7e36ab..a6ba5662 100644 --- a/std/log/default.go +++ b/std/log/default.go @@ -10,66 +10,31 @@ func Default() *Logger { } // Trace level message. -func Trace(msg string, v ...any) { - defaultLogger.log(nil, msg, LevelTrace, v...) +func Trace(t Tag, msg string, v ...any) { + defaultLogger.log(t, msg, LevelTrace, v...) } // Debug level message. -func Debug(msg string, v ...any) { - defaultLogger.log(nil, msg, LevelDebug, v...) +func Debug(t Tag, msg string, v ...any) { + defaultLogger.log(t, msg, LevelDebug, v...) } // Info level message. -func Info(msg string, v ...any) { - defaultLogger.Info(nil, msg, v...) +func Info(t Tag, msg string, v ...any) { + defaultLogger.log(t, msg, LevelInfo, v...) } // Warn level message. -func Warn(msg string, v ...any) { - defaultLogger.Warn(nil, msg, v...) +func Warn(t Tag, msg string, v ...any) { + defaultLogger.log(t, msg, LevelWarn, v...) } // Error level message. -func Error(msg string, v ...any) { - defaultLogger.Error(nil, msg, v...) +func Error(t Tag, msg string, v ...any) { + defaultLogger.log(t, msg, LevelError, v...) } // Fatal level message, followed by an exit. -func Fatal(msg string, v ...any) { - defaultLogger.Fatal(nil, msg, v...) -} - -// Tracef level formatted message. -func Tracef(msg string, v ...any) { - defaultLogger.Trace(nil, msg, v...) -} - -// Debugf level formatted message. -func Debugf(msg string, v ...any) { - defaultLogger.Debug(nil, msg, v...) -} - -// Infof level formatted message. -func Infof(msg string, v ...any) { - defaultLogger.Info(nil, msg, v...) -} - -// Warnf level formatted message. -func Warnf(msg string, v ...any) { - defaultLogger.Warn(nil, msg, v...) -} - -// Errorf level formatted message. -func Errorf(msg string, v ...any) { - defaultLogger.Error(nil, msg, v...) -} - -// Fatalf level formatted message, followed by an exit. -func Fatalf(msg string, v ...any) { - defaultLogger.Fatal(nil, msg, v...) -} - -// HasTrace returns if trace level is enabled. -func HasTrace() bool { - return defaultLogger.level <= LevelTrace +func Fatal(t Tag, msg string, v ...any) { + defaultLogger.log(t, msg, LevelFatal, v...) } diff --git a/std/object/client.go b/std/object/client.go index a0e0b5ac..aef57057 100644 --- a/std/object/client.go +++ b/std/object/client.go @@ -43,6 +43,11 @@ func NewClient(engine ndn.Engine, store ndn.Store) *Client { return client } +// Instance log identifier +func (c *Client) String() string { + return "client" +} + // Start the client. The engine must be running. func (c *Client) Start() error { if !c.engine.IsRunning() { diff --git a/std/object/client_consume.go b/std/object/client_consume.go index 497fa6a1..0c1113fe 100644 --- a/std/object/client_consume.go +++ b/std/object/client_consume.go @@ -193,7 +193,7 @@ func (c *Client) fetchMetadata( name enc.Name, callback func(meta *rdr.MetaData, err error), ) { - log.Debugf("consume: fetching object metadata %s", name) + log.Debug(c, "Fetching object metadata", "name", name) args := ExpressRArgs{ Name: name.Append(rdr.METADATA), Config: &ndn.InterestConfig{ @@ -233,7 +233,7 @@ func (c *Client) fetchDataByPrefix( name enc.Name, callback func(data ndn.Data, err error), ) { - log.Debugf("consume: fetching data with prefix %s", name) + log.Debug(c, "Fetching data with prefix", "name", name) args := ExpressRArgs{ Name: name, Config: &ndn.InterestConfig{ diff --git a/std/object/client_consume_seg.go b/std/object/client_consume_seg.go index 63d3d9e2..e99a6d14 100644 --- a/std/object/client_consume_seg.go +++ b/std/object/client_consume_seg.go @@ -38,9 +38,14 @@ func newRrSegFetcher(client *Client) rrSegFetcher { } } +// log identifier +func (s *rrSegFetcher) String() string { + return "seg-fetcher" +} + // add a stream to the fetch queue func (s *rrSegFetcher) add(state *ConsumeState) { - log.Debugf("consume: adding %s to fetch queue", state.fetchName) + log.Debug(s, "Adding stream to fetch queue", "name", state.fetchName) s.streams = append(s.streams, state) s.queueCheck() } @@ -216,7 +221,7 @@ func (s *rrSegFetcher) handleData(args ndn.ExpressCallbackArgs, state *ConsumeSt } if state.wnd[1] == state.segCnt { - log.Debugf("consume: %s completed", state.args.Name) + log.Debug(s, "Stream completed successfully", "name", state.fetchName) state.complete = true s.remove(state) } diff --git a/std/object/client_expressr.go b/std/object/client_expressr.go index 74a968cd..6eb86204 100644 --- a/std/object/client_expressr.go +++ b/std/object/client_expressr.go @@ -46,7 +46,7 @@ func (c *Client) expressRImpl(args ExpressRArgs) { // TODO: reexpress faster than lifetime err = c.engine.Express(interest, func(res ndn.ExpressCallbackArgs) { if res.Result == ndn.InterestResultTimeout { - log.Debugf("client::expressr retrying %s", args.Name) + log.Debug(c, "ExpressR Interest timeout", "name", args.Name) // check if retries are exhausted if args.Retries == 0 { diff --git a/std/sync/svs.go b/std/sync/svs.go index 44220360..89f18f3d 100644 --- a/std/sync/svs.go +++ b/std/sync/svs.go @@ -2,6 +2,7 @@ package sync import ( "errors" + "fmt" "math" rand "math/rand/v2" "sort" @@ -99,6 +100,11 @@ func NewSvSync(opts SvSyncOpts) *SvSync { } } +// Instance log identifier +func (s *SvSync) String() string { + return fmt.Sprintf("svs (%s)", s.o.GroupPrefix) +} + // Start the SV Sync instance. func (s *SvSync) Start() (err error) { err = s.o.Engine.AttachHandler(s.o.GroupPrefix, func(args ndn.InterestHandlerArgs) { @@ -208,7 +214,7 @@ func (s *SvSync) onReceiveStateVector(sv *spec_svs.StateVector) { // [SPEC] If any received BootstrapTime is more than 86400s in the // future compared to current time, the entire state vector SHOULD be ignored. if entry.BootstrapTime > uint64(time.Now().Unix())+86400 { - log.Warnf("SvSync: dropping state vector with far future BootstrapTime: %d", entry.BootstrapTime) + log.Warn(s, "Dropping state vector with far future BootstrapTime: %d", entry.BootstrapTime) return } @@ -327,7 +333,7 @@ func (s *SvSync) sendSyncInterest() { } data, err := s.o.Engine.Spec().MakeData(syncName, dataCfg, svWire, signer) if err != nil { - log.Errorf("SvSync: sendSyncInterest failed make data: %+v", err) + log.Error(s, "sendSyncInterest failed make data", "err", err) return } @@ -338,14 +344,14 @@ func (s *SvSync) sendSyncInterest() { } interest, err := s.o.Engine.Spec().MakeInterest(syncName, intCfg, data.Wire, nil) if err != nil { - log.Errorf("SvSync: sendSyncInterest failed make interest: %+v", err) + log.Error(s, "sendSyncInterest failed make interest", "err", err) return } // [Spec] Sync Ack Policy - Do not acknowledge Sync Interests err = s.o.Engine.Express(interest, nil) if err != nil { - log.Errorf("SvSync: sendSyncInterest failed express: %+v", err) + log.Error(s, "sendSyncInterest failed express", "err", err) } } @@ -356,18 +362,18 @@ func (s *SvSync) onSyncInterest(interest ndn.Interest) { // Check if app param is present if interest.AppParam() == nil { - log.Debug("SvSync: onSyncInterest no AppParam, ignoring") + log.Debug(s, "onSyncInterest no AppParam, ignoring") return } // Decode Sync Data pkt, _, err := spec.ReadPacket(enc.NewWireReader(interest.AppParam())) if err != nil { - log.Warnf("SvSync: onSyncInterest failed to parse SyncData: %+v", err) + log.Warn(s, "onSyncInterest failed to parse SyncData", "err", err) return } if pkt.Data == nil { - log.Warnf("SvSync: onSyncInterest no Data, ignoring") + log.Warn(s, "onSyncInterest no Data, ignoring") return } @@ -377,7 +383,7 @@ func (s *SvSync) onSyncInterest(interest ndn.Interest) { svWire := pkt.Data.Content().Join() params, err := spec_svs.ParseSvsData(enc.NewBufferReader(svWire), false) if err != nil || params.StateVector == nil { - log.Warnf("SvSync: onSyncInterest failed to parse StateVec: %+v", err) + log.Warn(s, "onSyncInterest failed to parse StateVec", "err", err) return } diff --git a/tools/catchunks.go b/tools/catchunks.go index f8b8a085..a3dd1f3a 100644 --- a/tools/catchunks.go +++ b/tools/catchunks.go @@ -19,6 +19,10 @@ func RunCatChunks(args []string) { (&CatChunks{args: args}).run() } +func (cc *CatChunks) String() string { + return "cat" +} + func (cc *CatChunks) usage() { fmt.Fprintf(os.Stderr, "Usage: %s \n", cc.args[0]) fmt.Fprintf(os.Stderr, "\n") @@ -35,14 +39,14 @@ func (cc *CatChunks) run() { // get name from cli name, err := enc.NameFromStr(cc.args[1]) if err != nil { - log.Fatalf("Invalid name: %s", cc.args[1]) + log.Fatal(cc, "Invalid name", "name", cc.args[1]) } // start face and engine app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - log.Errorf("Unable to start engine: %+v", err) + log.Error(cc, "Unable to start engine", "err", err) return } defer app.Stop() @@ -51,7 +55,7 @@ func (cc *CatChunks) run() { cli := object.NewClient(app, object.NewMemoryStore()) err = cli.Start() if err != nil { - log.Errorf("Unable to start object client: %+v", err) + log.Error(cc, "Unable to start object client", "err", err) return } defer cli.Stop() @@ -77,7 +81,7 @@ func (cc *CatChunks) run() { } if status.Progress()%1000 == 0 { - log.Debugf("Progress: %.2f%%", float64(status.Progress())/float64(status.ProgressMax())*100) + log.Debug(cc, "Consume progress", "progress", float64(status.Progress())/float64(status.ProgressMax())*100) write(status) } @@ -86,13 +90,14 @@ func (cc *CatChunks) run() { state := <-done if state.Error() != nil { - log.Errorf("Error fetching object: %+v", state.Error()) + log.Error(cc, "Error fetching object", "err", state.Error()) return } // statistics - log.Infof("Object fetched: %s", state.Name()) - log.Infof("Content: %d bytes", byteCount) - log.Infof("Time taken: %s", t2.Sub(t1)) - log.Infof("Throughput: %f Mbit/s", float64(byteCount*8)/t2.Sub(t1).Seconds()/1e6) + fmt.Fprintf(os.Stderr, "Object fetched %s\n", state.Name()) + fmt.Fprintf(os.Stderr, "Content: %d bytes\n", byteCount) + fmt.Fprintf(os.Stderr, "Time taken: %s\n", t2.Sub(t1)) + fmt.Fprintf(os.Stderr, "Throughput: %f Mbit/s\n", float64(byteCount*8)/t2.Sub(t1).Seconds()/1e6) + } diff --git a/tools/pingclient.go b/tools/pingclient.go index fc51e131..f91a7a6c 100644 --- a/tools/pingclient.go +++ b/tools/pingclient.go @@ -47,6 +47,10 @@ func RunPingClient(args []string) { (&PingClient{args: args}).run() } +func (pc *PingClient) String() string { + return "ping" +} + func (pc *PingClient) usage() { fmt.Fprintf(os.Stderr, "Usage: %s \n", pc.args[0]) fmt.Fprintf(os.Stderr, "\n") @@ -64,7 +68,7 @@ func (pc *PingClient) send(seq uint64) { interest, err := pc.app.Spec().MakeInterest(name, cfg, nil, nil) if err != nil { - log.Errorf("Unable to make Interest: %+v", err) + log.Error(pc, "Unable to make Interest", "err", err) return } @@ -101,7 +105,7 @@ func (pc *PingClient) send(seq uint64) { } }) if err != nil { - log.Errorf("Unable to send Interest: %+v", err) + log.Error(pc, "Unable to send Interest", "err", err) } } @@ -143,7 +147,8 @@ func (pc *PingClient) run() { // parse name prefix prefixN, err := enc.NameFromStr(prefix) if err != nil { - log.Fatalf("Invalid prefix: %s", pc.args[1]) + log.Fatal(pc, "Invalid prefix", "name", pc.args[1]) + return } pc.prefix = prefixN pc.name = prefixN.Append(enc.NewStringComponent(enc.TypeGenericNameComponent, "ping")) @@ -157,7 +162,7 @@ func (pc *PingClient) run() { pc.app = engine.NewBasicEngine(engine.NewDefaultFace()) err = pc.app.Start() if err != nil { - log.Fatalf("Unable to start engine: %+v", err) + log.Fatal(pc, "Unable to start engine", "err", err) return } defer pc.app.Stop() diff --git a/tools/pingserver.go b/tools/pingserver.go index 5ae995ca..b1249b90 100644 --- a/tools/pingserver.go +++ b/tools/pingserver.go @@ -30,6 +30,10 @@ func RunPingServer(args []string) { }).run() } +func (ps *PingServer) String() string { + return "ping-server" +} + func (ps *PingServer) usage() { fmt.Fprintf(os.Stderr, "Usage: %s \n", ps.args[0]) fmt.Fprintf(os.Stderr, "\n") @@ -44,27 +48,28 @@ func (ps *PingServer) run() { prefix, err := enc.NameFromStr(ps.args[1]) if err != nil { - log.Fatalf("Invalid prefix: %s", ps.args[1]) + log.Fatal(ps, "Invalid prefix", "name", ps.args[1]) + return } ps.name = prefix.Append(enc.NewStringComponent(enc.TypeGenericNameComponent, "ping")) ps.app = engine.NewBasicEngine(engine.NewDefaultFace()) err = ps.app.Start() if err != nil { - log.Fatalf("Unable to start engine: %+v", err) + log.Fatal(ps, "Unable to start engine", "err", err) return } defer ps.app.Stop() err = ps.app.AttachHandler(ps.name, ps.onInterest) if err != nil { - log.Fatalf("Unable to register handler: %+v", err) + log.Fatal(ps, "Unable to register handler", "err", err) return } err = ps.app.RegisterRoute(ps.name) if err != nil { - log.Fatalf("Unable to register route: %+v", err) + log.Fatal(ps, "Unable to register route", "err", err) return } @@ -93,12 +98,12 @@ func (ps *PingServer) onInterest(args ndn.InterestHandlerArgs) { args.Interest.AppParam(), ps.signer) if err != nil { - log.Errorf("Unable to encode data: %+v", err) + log.Error(ps, "Unable to encode data", "err", err) return } err = args.Reply(data.Wire) if err != nil { - log.Errorf("Unable to reply with data: %+v", err) + log.Error(ps, "Unable to reply with data", "err", err) return } } diff --git a/tools/putchunks.go b/tools/putchunks.go index b7b9031d..372b0eb4 100644 --- a/tools/putchunks.go +++ b/tools/putchunks.go @@ -21,6 +21,10 @@ func RunPutChunks(args []string) { (&PutChunks{args: args}).run() } +func (pc *PutChunks) String() string { + return "put" +} + func (pc *PutChunks) usage() { fmt.Fprintf(os.Stderr, "Usage: %s \n", pc.args[0]) fmt.Fprintf(os.Stderr, "\n") @@ -37,14 +41,15 @@ func (pc *PutChunks) run() { // get name from cli name, err := enc.NameFromStr(pc.args[1]) if err != nil { - log.Fatalf("Invalid name: %s", pc.args[1]) + log.Fatal(pc, "Invalid object name", "name", pc.args[1]) + return } // start face and engine app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - log.Errorf("Unable to start engine: %+v", err) + log.Fatal(pc, "Unable to start engine", "err", err) return } defer app.Stop() @@ -53,7 +58,7 @@ func (pc *PutChunks) run() { cli := object.NewClient(app, object.NewMemoryStore()) err = cli.Start() if err != nil { - log.Errorf("Unable to start object client: %+v", err) + log.Fatal(pc, "Unable to start object client", "err", err) return } defer cli.Stop() @@ -77,17 +82,17 @@ func (pc *PutChunks) run() { Content: content, }) if err != nil { - log.Fatalf("Unable to produce object: %+v", err) + log.Fatal(pc, "Unable to produce object", "err", err) return } content = nil // gc - log.Infof("Object produced: %s", vname) + log.Info(pc, "Object produced", "name", vname) // register route to the object err = app.RegisterRoute(name) if err != nil { - log.Fatalf("Unable to register route: %+v", err) + log.Fatal(pc, "Unable to register route", "err", err) return } From a379bc574e6cc34beb400db9c8aab6d48192df7b Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 00:47:49 +0000 Subject: [PATCH 05/12] std: log adapt --- std/examples/low-level/producer/main.go | 2 +- std/examples/low-level/svs/main.go | 19 ++--- std/examples/schema-test/chat/main.go | 22 +++--- .../schema-test/encryption/consumer/main.go | 11 ++- .../schema-test/encryption/producer/main.go | 9 +-- .../schema-test/group-sig/consumer/main.go | 11 ++- .../schema-test/group-sig/producer/main.go | 9 +-- .../schema-test/rdr/catchunks/main.go | 7 +- .../schema-test/rdr/putchunks/main.go | 9 +-- .../schema-test/signed-by/consumer/main.go | 13 ++-- .../schema-test/signed-by/producer/main.go | 15 ++-- .../single-packet/consumer/main.go | 7 +- .../single-packet/producer/main.go | 11 ++- .../schema-test/storage/consumer/main.go | 11 ++- .../schema-test/storage/producer/main.go | 9 +-- std/examples/schema-test/sync/main.go | 9 +-- std/schema/base_node.go | 17 ++--- std/schema/demosec/encryption.go | 32 +++++---- std/schema/demosec/policies.go | 22 +++--- std/schema/expressing_point.go | 41 ++++++----- std/schema/interface.go | 10 --- std/schema/leaf_node.go | 10 +-- std/schema/rdr/pipelines.go | 4 +- std/schema/rdr/rdr.go | 70 +++++++++++-------- std/schema/svs/sync.go | 32 ++++----- std/schema/tree.go | 12 ++-- std/security/pib/sqlite-pib.go | 6 +- std/security/pib/tpm-file.go | 11 ++- 28 files changed, 208 insertions(+), 233 deletions(-) diff --git a/std/examples/low-level/producer/main.go b/std/examples/low-level/producer/main.go index a64c8ff4..09e3ca7e 100644 --- a/std/examples/low-level/producer/main.go +++ b/std/examples/low-level/producer/main.go @@ -54,7 +54,7 @@ func onInterest(args ndn.InterestHandlerArgs) { } func main() { - app := engine.NewBasicEngine(engine.NewDefaultFace()) + app = engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { logger.Fatal(nil, "Unable to start engine", "err", err) diff --git a/std/examples/low-level/svs/main.go b/std/examples/low-level/svs/main.go index a5826c20..c6529135 100644 --- a/std/examples/low-level/svs/main.go +++ b/std/examples/low-level/svs/main.go @@ -1,6 +1,7 @@ package main import ( + "fmt" "os" "time" @@ -17,23 +18,23 @@ func main() { // ndnd fw strategy set prefix=/ndn/svs strategy=/localhost/nfd/strategy/multicast // - logger := log.NewText(os.Stderr) - if len(os.Args) < 2 { - log.Fatalf("Usage: %s ", os.Args[0]) + fmt.Fprintf(os.Stderr, "Usage: %s ", os.Args[0]) + os.Exit(1) } // Parse command line arguments name, err := enc.NameFromStr(os.Args[1]) if err != nil { - log.Fatalf("Invalid node ID: %s", os.Args[1]) + log.Fatal(nil, "Invalid node ID", "name", os.Args[1]) + return } // Create a new engine app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatal(nil, "Unable to start engine", "err", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -44,21 +45,21 @@ func main() { Engine: app, GroupPrefix: group, OnUpdate: func(ssu sync.SvSyncUpdate) { - logger.Info(nil, "Received update", "update", ssu) + log.Info(nil, "Received update", "update", ssu) }, }) // Register group prefix route err = app.RegisterRoute(group) if err != nil { - logger.Error(nil, "Unable to register route", "err", err) + log.Error(nil, "Unable to register route", "err", err) return } defer app.UnregisterRoute(group) err = svsync.Start() if err != nil { - logger.Error(nil, "Unable to create SvSync", "err", err) + log.Error(nil, "Unable to create SvSync", "err", err) return } @@ -67,6 +68,6 @@ func main() { for range ticker.C { seq := svsync.IncrSeqNo(name) - logger.Info(nil, "Published new sequence number", "seq", seq) + log.Info(nil, "Published new sequence number", "seq", seq) } } diff --git a/std/examples/schema-test/chat/main.go b/std/examples/schema-test/chat/main.go index b11acd51..132dfeb4 100644 --- a/std/examples/schema-test/chat/main.go +++ b/std/examples/schema-test/chat/main.go @@ -6,7 +6,6 @@ import ( "fmt" "html/template" "io" - "math/rand" "net/http" "os" "os/signal" @@ -14,7 +13,6 @@ import ( "strings" "sync" "syscall" - "time" "github.com/gorilla/websocket" enc "github.com/named-data/ndnd/std/encoding" @@ -156,18 +154,16 @@ func setupRoutes() { func main() { // Note: remember to ` nfdc strategy set /example/schema /localhost/nfd/strategy/multicast ` - log.SetLevel(log.ErrorLevel) - logger := log.WithField("module", "main") - rand.Seed(time.Now().UnixMicro()) + log.Default().SetLevel(log.LevelError) // Parse port number if len(os.Args) < 2 { - logger.Fatal("Insufficient argument. Please input a port number uniquely used by this instance.") + log.Fatal(nil, "Insufficient argument. Please input a port number uniquely used by this instance.") return } port, err := strconv.Atoi(os.Args[1]) if err != nil { - logger.Fatal("Invalid argument") + log.Fatal(nil, "Invalid argument") return } nodeId = fmt.Sprintf("node-%d", port) @@ -175,16 +171,16 @@ func main() { // Load HTML UI file to serve file, err := os.Open("home.html") if err != nil { - logger.Fatalf("Failed to open home.html: %+v", err) + log.Fatal(nil, "Failed to open home.html", "err", err) } homeHtmlTmp, err = io.ReadAll(file) if err != nil { - logger.Fatalf("Failed to read home.html: %+v", err) + log.Fatal(nil, "Failed to read home.html", "err", err) } file.Close() temp, err := template.New("HTML").Parse(string(homeHtmlTmp)) if err != nil { - logger.Fatalf("Failed to create template: %+v", err) + log.Fatal(nil, "Failed to create template", "err", err) } strBuilder := strings.Builder{} temp.Execute(&strBuilder, port) @@ -200,7 +196,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -209,7 +205,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/chatApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -265,7 +261,7 @@ func main() { fmt.Printf("Start serving on http://localhost:%d/ ...\n", port) signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) cancel() server.Shutdown(context.Background()) wg.Wait() diff --git a/std/examples/schema-test/encryption/consumer/main.go b/std/examples/schema-test/encryption/consumer/main.go index 7a525016..14c5b026 100644 --- a/std/examples/schema-test/encryption/consumer/main.go +++ b/std/examples/schema-test/encryption/consumer/main.go @@ -64,16 +64,13 @@ const SchemaJson = `{ const HmacKey = "Hello, World!" func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - if len(os.Args) < 2 { - logger.Fatal("Insufficient argument. Please input the version number given by the producer.") + log.Fatal(nil, "Insufficient argument. Please input the version number given by the producer.") return } ver, err := strconv.Atoi(os.Args[1]) if err != nil { - logger.Fatal("Invalid argument") + log.Fatal(nil, "Invalid argument") return } @@ -87,7 +84,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -96,7 +93,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/encryptionApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() diff --git a/std/examples/schema-test/encryption/producer/main.go b/std/examples/schema-test/encryption/producer/main.go index 5b6a54dd..305bdb05 100644 --- a/std/examples/schema-test/encryption/producer/main.go +++ b/std/examples/schema-test/encryption/producer/main.go @@ -66,9 +66,6 @@ const SchemaJson = `{ const HmacKey = "Hello, World!" func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$isProducer": true, @@ -79,7 +76,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -88,7 +85,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/encryptionApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -114,5 +111,5 @@ func main() { fmt.Print("Start serving ...\n") signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/std/examples/schema-test/group-sig/consumer/main.go b/std/examples/schema-test/group-sig/consumer/main.go index d9733e9a..926a4fd3 100644 --- a/std/examples/schema-test/group-sig/consumer/main.go +++ b/std/examples/schema-test/group-sig/consumer/main.go @@ -69,16 +69,13 @@ const SchemaJson = `{ const HmacKey = "Hello, World!" func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - if len(os.Args) < 2 { - logger.Fatal("Insufficient argument. Please input the version number given by the producer.") + log.Fatal(nil, "Insufficient argument. Please input the version number given by the producer.") return } ver, err := strconv.Atoi(os.Args[1]) if err != nil { - logger.Fatal("Invalid argument") + log.Fatal(nil, "Invalid argument") return } @@ -92,7 +89,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -101,7 +98,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/groupSigApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() diff --git a/std/examples/schema-test/group-sig/producer/main.go b/std/examples/schema-test/group-sig/producer/main.go index 2023e045..cdee8d4b 100644 --- a/std/examples/schema-test/group-sig/producer/main.go +++ b/std/examples/schema-test/group-sig/producer/main.go @@ -77,9 +77,6 @@ occaecat cupidatat non proident, sunt in culpa qui officia deserunt mollit anim const HmacKey = "Hello, World!" func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$isProducer": true, @@ -90,7 +87,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -99,7 +96,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/groupSigApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -119,5 +116,5 @@ func main() { fmt.Print("Start serving ...\n") signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/std/examples/schema-test/rdr/catchunks/main.go b/std/examples/schema-test/rdr/catchunks/main.go index addfc3a6..5f0e5292 100644 --- a/std/examples/schema-test/rdr/catchunks/main.go +++ b/std/examples/schema-test/rdr/catchunks/main.go @@ -57,9 +57,6 @@ const SchemaJson = `{ }` func main() { - log.SetLevel(log.DebugLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$isProducer": false, @@ -69,7 +66,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -78,7 +75,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/rdr") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() diff --git a/std/examples/schema-test/rdr/putchunks/main.go b/std/examples/schema-test/rdr/putchunks/main.go index be3ed10e..f6ebcb99 100644 --- a/std/examples/schema-test/rdr/putchunks/main.go +++ b/std/examples/schema-test/rdr/putchunks/main.go @@ -66,9 +66,6 @@ occaecat cupidatat non proident, sunt in culpa qui officia deserunt mollit anim ` func main() { - log.SetLevel(log.DebugLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$isProducer": true, @@ -78,7 +75,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -87,7 +84,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/rdr") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -102,5 +99,5 @@ func main() { fmt.Print("Start serving ...\n") signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/std/examples/schema-test/signed-by/consumer/main.go b/std/examples/schema-test/signed-by/consumer/main.go index dcb0da73..ce1f9e16 100644 --- a/std/examples/schema-test/signed-by/consumer/main.go +++ b/std/examples/schema-test/signed-by/consumer/main.go @@ -106,11 +106,8 @@ const ( ) func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - if len(os.Args) < 2 { - logger.Fatal("Insufficient argument. Please input the version number given by the producer.") + log.Fatal(nil, "Insufficient argument. Please input the version number given by the producer.") return } nodeId := os.Args[1] @@ -122,12 +119,12 @@ func main() { // Enroll trust anchor trustAnchorBuf, err := base64.StdEncoding.DecodeString(TrustAnchorPktB64) if err != nil { - logger.Fatalf("Invalid trust anchor: %+v", err) + log.Fatal(nil, "Invalid trust anchor", "err", err) return } err = keyStore.AddTrustAnchor(trustAnchorBuf) if err != nil { - logger.Fatalf("Unable to add trust anchor: %+v", err) + log.Fatal(nil, "Unable to add trust anchor", "err", err) return } @@ -142,7 +139,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -150,7 +147,7 @@ func main() { // Attach schema err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() diff --git a/std/examples/schema-test/signed-by/producer/main.go b/std/examples/schema-test/signed-by/producer/main.go index ffb70ba9..05f5c85b 100644 --- a/std/examples/schema-test/signed-by/producer/main.go +++ b/std/examples/schema-test/signed-by/producer/main.go @@ -110,9 +110,6 @@ const ( ) func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - nodeId := fmt.Sprintf("node-%d", rand.Int()) prefix, _ := enc.NameFromStr("/example/schema/signedBy") @@ -122,12 +119,12 @@ func main() { // Enroll trust anchor trustAnchorBuf, err := base64.StdEncoding.DecodeString(TrustAnchorPktB64) if err != nil { - logger.Fatalf("Invalid trust anchor: %+v", err) + log.Fatal(nil, "Invalid trust anchor", "err", err) return } err = keyStore.AddTrustAnchor(trustAnchorBuf) if err != nil { - logger.Fatalf("Unable to add trust anchor: %+v", err) + log.Fatal(nil, "Unable to add trust anchor", "err", err) return } spec := spec_2022.Spec{} @@ -141,7 +138,7 @@ func main() { } err = keyStore.EnrollKey(producerKeyName, enc.Buffer(ProducerKey), trustAnchorData.Name()) if err != nil { - logger.Fatalf("Unable to enroll the producer key: %+v", err) + log.Fatal(nil, "Unable to enroll the producer key", "err", err) return } @@ -156,7 +153,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -164,7 +161,7 @@ func main() { // Attach schema err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -183,5 +180,5 @@ func main() { fmt.Print("Start serving ...\n") signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/std/examples/schema-test/single-packet/consumer/main.go b/std/examples/schema-test/single-packet/consumer/main.go index 8a0a1923..8bfb18a2 100644 --- a/std/examples/schema-test/single-packet/consumer/main.go +++ b/std/examples/schema-test/single-packet/consumer/main.go @@ -43,9 +43,6 @@ const SchemaJson = `{ }` func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$onInterest": func(event *schema.Event) any { return nil }, @@ -56,7 +53,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -65,7 +62,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/testApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() diff --git a/std/examples/schema-test/single-packet/producer/main.go b/std/examples/schema-test/single-packet/producer/main.go index e78ebbb4..7c774972 100644 --- a/std/examples/schema-test/single-packet/producer/main.go +++ b/std/examples/schema-test/single-packet/producer/main.go @@ -50,7 +50,7 @@ func onInterest(event *schema.Event) any { dataWire := mNode.Call("Provide", enc.Wire{content}).(enc.Wire) err := event.Reply(dataWire) if err != nil { - log.WithField("module", "main").Errorf("unable to reply with data: %+v", err) + log.Error(nil, "Unable to reply with Data", "err", err) return true } fmt.Printf("<< D: %s\n", mNode.Name.String()) @@ -60,9 +60,6 @@ func onInterest(event *schema.Event) any { } func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$onInterest": onInterest, @@ -73,7 +70,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -82,7 +79,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/testApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -91,5 +88,5 @@ func main() { sigChannel := make(chan os.Signal, 1) signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting\n", "signal", receivedSig) } diff --git a/std/examples/schema-test/storage/consumer/main.go b/std/examples/schema-test/storage/consumer/main.go index c4d4f695..0ffd4b76 100644 --- a/std/examples/schema-test/storage/consumer/main.go +++ b/std/examples/schema-test/storage/consumer/main.go @@ -47,16 +47,13 @@ const SchemaJson = `{ }` func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - if len(os.Args) < 2 { - logger.Fatal("Insufficient argument. Please input the version number given by the producer.") + log.Fatal(nil, "Insufficient argument. Please input the version number given by the producer.") return } ver, err := strconv.Atoi(os.Args[1]) if err != nil { - logger.Fatal("Invalid argument") + log.Fatal(nil, "Invalid argument") return } @@ -69,7 +66,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err = app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -78,7 +75,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/storageApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() diff --git a/std/examples/schema-test/storage/producer/main.go b/std/examples/schema-test/storage/producer/main.go index e5a4a707..69195eea 100644 --- a/std/examples/schema-test/storage/producer/main.go +++ b/std/examples/schema-test/storage/producer/main.go @@ -49,9 +49,6 @@ const SchemaJson = `{ }` func main() { - log.SetLevel(log.InfoLevel) - logger := log.WithField("module", "main") - // Setup schema tree tree := schema.CreateFromJson(SchemaJson, map[string]any{ "$isProducer": true, @@ -61,7 +58,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -70,7 +67,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/storageApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -90,5 +87,5 @@ func main() { fmt.Print("Start serving ...\n") signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/std/examples/schema-test/sync/main.go b/std/examples/schema-test/sync/main.go index 46231228..f4450213 100644 --- a/std/examples/schema-test/sync/main.go +++ b/std/examples/schema-test/sync/main.go @@ -72,9 +72,6 @@ const SchemaJson = `{ func main() { // Note: remember to ` nfdc strategy set /example/schema /localhost/nfd/strategy/multicast ` - log.SetLevel(log.ErrorLevel) - logger := log.WithField("module", "main") - rand.Seed(time.Now().UnixMicro()) nodeId := fmt.Sprintf("node-%d", rand.Int()) // Setup schema tree @@ -87,7 +84,7 @@ func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatalf("Unable to start engine: %+v", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -96,7 +93,7 @@ func main() { prefix, _ := enc.NameFromStr("/example/schema/syncApp") err = tree.Attach(prefix, app) if err != nil { - logger.Fatalf("Unable to attach the schema to the engine: %+v", err) + log.Fatal(nil, "Unable to attach the schema to the engine", "err", err) return } defer tree.Detach() @@ -152,7 +149,7 @@ func main() { fmt.Print("Start serving ...\n") signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Infof("Received signal %+v - exiting\n", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) cancel() wg.Wait() } diff --git a/std/schema/base_node.go b/std/schema/base_node.go index 87910895..707fca56 100644 --- a/std/schema/base_node.go +++ b/std/schema/base_node.go @@ -26,9 +26,6 @@ type Node struct { // Change when there found evidences showing this is the bottleneck. chd []*Node - // Log is the logger - log *log.Entry - dep uint par *Node edge enc.ComponentPattern @@ -40,6 +37,10 @@ type Node struct { engine ndn.Engine } +func (n *Node) String() string { + return n.path.String() +} + // Children of the node func (n *Node) Children() []*Node { return n.chd @@ -73,11 +74,6 @@ func (n *Node) Depth() uint { return n.dep } -// Log returns the log entry of this node -func (n *Node) Log() *log.Entry { - return n.log -} - // Impl returns the actual functional part of the node func (n *Node) Impl() NodeImpl { return n.impl @@ -196,7 +192,7 @@ func (n *Node) ConstructName(matching enc.Matching, ret enc.Name) error { // A base node shouldn't receive any Interest, so drops it. func (n *Node) OnInterest(args ndn.InterestHandlerArgs, matching enc.Matching) { if n.impl == nil { - n.log.WithField("name", args.Interest.Name().String()).Warn("Unexpected Interest. Drop.") + log.Warn(n, "Unexpected Interest. Drop.", "name", args.Interest.Name()) } else { n.impl.OnInterest(args, matching) } @@ -207,7 +203,6 @@ func (n *Node) OnInterest(args ndn.InterestHandlerArgs, matching enc.Matching) { func (n *Node) OnAttach(path enc.NamePattern, engine ndn.Engine) error { n.engine = engine n.dep = uint(len(path)) - n.log = log.WithField("module", "schema").WithField("path", path.String()) n.path = make(enc.NamePattern, len(path)) copy(n.path, path) @@ -346,7 +341,7 @@ func (n *BaseNodeImpl) NodeImplTrait() NodeImpl { // OnInterest is the callback function when there is an incoming Interest. func (n *BaseNodeImpl) OnInterest(args ndn.InterestHandlerArgs, matching enc.Matching) { - n.Node.Log().WithField("name", args.Interest.Name().String()).Warn("Unexpected Interest. Drop.") + log.Warn(n.Node, "Unexpected Interest. Drop.", "name", args.Interest.Name()) } // OnAttach is called when the node is attached to an engine diff --git a/std/schema/demosec/encryption.go b/std/schema/demosec/encryption.go index 43270357..4dca9e0e 100644 --- a/std/schema/demosec/encryption.go +++ b/std/schema/demosec/encryption.go @@ -8,6 +8,7 @@ import ( "fmt" enc "github.com/named-data/ndnd/std/encoding" + "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" "github.com/named-data/ndnd/std/schema" ) @@ -37,6 +38,10 @@ func (n *ContentKeyNode) CastTo(ptr any) any { } } +func (n *ContentKeyNode) String() string { + return fmt.Sprintf("ContentKeyNode (%s)", n.Node) +} + func CreateContentKeyNode(node *schema.Node) schema.NodeImpl { ret := &ContentKeyNode{ BaseNodeImpl: schema.BaseNodeImpl{ @@ -69,15 +74,14 @@ func (n *ContentKeyNode) GenKey(mNode schema.MatchedNode) ContentKey { } func (n *ContentKeyNode) Encrypt(mNode schema.MatchedNode, ck ContentKey, content enc.Wire) enc.Wire { - logger := mNode.Logger("RdrNode") if len(ck.ckid) != 8 || len(ck.keybits) != 32 { - logger.Errorf("invalid content key: %v", hex.EncodeToString(ck.ckid)) + log.Error(n, "Invalid content key", "ckid", hex.EncodeToString(ck.ckid)) return nil } aescis, err := aes.NewCipher(ck.keybits) if err != nil { - logger.Errorf("unable to create cipher: %+v", err) + log.Error(n, "Unable to create cipher", "err", err) return nil } iv := make([]byte, aescis.BlockSize()) @@ -105,11 +109,9 @@ func (n *ContentKeyNode) Encrypt(mNode schema.MatchedNode, ck ContentKey, conten func (n *ContentKeyNode) Decrypt(mNode schema.MatchedNode, encryptedContent enc.Wire) enc.Wire { // Note: In real-world implementation, a callback/channel version should be provided - logger := mNode.Logger("RdrNode") - encContent, err := ParseEncryptedContent(enc.NewWireReader(encryptedContent), true) if err != nil { - logger.Errorf("malformed encrypted packet") + log.Error(n, "Malformed encrypted packet") return nil } @@ -121,13 +123,13 @@ func (n *ContentKeyNode) Decrypt(mNode schema.MatchedNode, encryptedContent enc. ckResult := <-ckMNode.Call("NeedChan").(chan schema.NeedResult) if ckResult.Status != ndn.InterestResultData { - logger.Warnf("unable to fetch content key: %s", ckName.String()) + log.Warn(n, "Unable to fetch content key", "ck", ckName) return nil } aescis, err := aes.NewCipher(ckResult.Content.Join()) if err != nil { - logger.Errorf("unable to create AES cipher for key: %s", ckResult.Data.Name().String()) + log.Error(n, "Unable to create AES cipher for key", "name", ckResult.Data.Name()) return nil } @@ -135,7 +137,7 @@ func (n *ContentKeyNode) Decrypt(mNode schema.MatchedNode, encryptedContent enc. inbuf := encContent.CipherText.Join() cip := cipher.NewCBCDecrypter(aescis, iv) if len(inbuf)%cip.BlockSize() != 0 { - logger.Errorf("input AES buf has a wrong length") + log.Error(n, "Input AES buf has a wrong length") return nil } cip.CryptBlocks(inbuf, inbuf) @@ -162,7 +164,7 @@ func init() { "GenKey": func(mNode schema.MatchedNode, args ...any) any { if len(args) > 0 { err := fmt.Errorf("ContentKeyNode.GenKey requires 0 arguments but got %d", len(args)) - mNode.Logger("ContentKeyNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*ContentKeyNode](mNode.Node).GenKey(mNode) @@ -170,21 +172,21 @@ func init() { "Encrypt": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 2 { err := fmt.Errorf("ContentKeyNode.Encrypt requires 2 arguments but got %d", len(args)) - mNode.Logger("ContentKeyNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } ck, ok := args[0].(ContentKey) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "ck", Value: args[0]} - mNode.Logger("ContentKeyNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } content, ok := args[1].(enc.Wire) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "content", Value: args[1]} - mNode.Logger("ContentKeyNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } @@ -193,14 +195,14 @@ func init() { "Decrypt": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 1 { err := fmt.Errorf("ContentKeyNode.Decrypt requires 1 arguments but got %d", len(args)) - mNode.Logger("ContentKeyNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } encryptedContent, ok := args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "encryptedContent", Value: args[0]} - mNode.Logger("ContentKeyNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } diff --git a/std/schema/demosec/policies.go b/std/schema/demosec/policies.go index 0d486868..aee491af 100644 --- a/std/schema/demosec/policies.go +++ b/std/schema/demosec/policies.go @@ -5,6 +5,7 @@ import ( "sync" enc "github.com/named-data/ndnd/std/encoding" + "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" "github.com/named-data/ndnd/std/schema" sec "github.com/named-data/ndnd/std/security" @@ -17,6 +18,10 @@ type KeyStoragePolicy struct { KeyStore *DemoHmacKeyStore } +func (p *KeyStoragePolicy) String() string { + return "KeyStoragePolicy" +} + func (p *KeyStoragePolicy) PolicyTrait() schema.Policy { return p } @@ -25,10 +30,9 @@ func (p *KeyStoragePolicy) onSearch(event *schema.Event) any { p.lock.RLock() defer p.lock.RUnlock() - logger := event.Target.Logger("KeyStoragePolicy") // event.IntConfig is always valid for onSearch, no matter if there is an Interest. if event.IntConfig.CanBePrefix { - logger.Errorf("the Demo HMAC key storage does not support CanBePrefix Interest to fetch certificates.") + log.Error(p, "the Demo HMAC key storage does not support CanBePrefix Interest to fetch certificates.") return nil } key := p.KeyStore.GetKey(event.Target.Name) @@ -85,6 +89,10 @@ type SignedByPolicy struct { keyNode *schema.Node } +func (p *SignedByPolicy) String() string { + return "SignedByPolicy" +} + func (p *SignedByPolicy) PolicyTrait() schema.Policy { return p } @@ -108,15 +116,14 @@ func (p *SignedByPolicy) ConvertName(mNode *schema.MatchedNode) *schema.MatchedN } func (p *SignedByPolicy) onGetDataSigner(event *schema.Event) any { - logger := event.Target.Logger("SignedByPolicy") keyMNode := p.ConvertName(event.Target) if keyMNode == nil { - logger.Errorf("Cannot construct the key name to sign this data. Leave unsigned.") + log.Error(p, "Cannot construct the key name to sign this data. Leave unsigned.") return nil } key := p.KeyStore.GetKey(keyMNode.Name) if key == nil { - logger.Errorf("The key to sign this data is missing. Leave unsigned.") + log.Error(p, "The key to sign this data is missing. Leave unsigned.") return nil } return sec.NewHmacSigner(keyMNode.Name, key.KeyBits, false, 0) @@ -125,7 +132,6 @@ func (p *SignedByPolicy) onGetDataSigner(event *schema.Event) any { func (p *SignedByPolicy) onValidateData(event *schema.Event) any { sigCovered := event.SigCovered signature := event.Signature - logger := event.Target.Logger("SignedByPolicy") if sigCovered == nil || signature == nil || signature.SigType() != ndn.SignatureHmacWithSha256 { return schema.VrSilence } @@ -133,13 +139,13 @@ func (p *SignedByPolicy) onValidateData(event *schema.Event) any { //TODO: Compute the deadline result := <-keyMNode.Call("NeedChan").(chan schema.NeedResult) if result.Status != ndn.InterestResultData { - logger.Warnf("Unable to fetch the key that signed this data.") + log.Warn(p, "Unable to fetch the key that signed this data.") return schema.VrFail } if sec.CheckHmacSig(sigCovered, signature.SigValue(), result.Content.Join()) { return schema.VrPass } else { - logger.Warnf("Failed to verify the signature.") + log.Warn(p, "Failed to verify the signature.") return schema.VrFail } } diff --git a/std/schema/expressing_point.go b/std/schema/expressing_point.go index 1d9c2634..89140196 100644 --- a/std/schema/expressing_point.go +++ b/std/schema/expressing_point.go @@ -6,6 +6,7 @@ import ( "time" enc "github.com/named-data/ndnd/std/encoding" + "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" "github.com/named-data/ndnd/std/utils" ) @@ -46,6 +47,10 @@ type ExpressPoint struct { SupressInt bool } +func (n *ExpressPoint) String() string { + return "express-point" +} + func (n *ExpressPoint) NodeImplTrait() NodeImpl { return n } @@ -92,7 +97,6 @@ func (n *ExpressPoint) OnInterest(args ndn.InterestHandlerArgs, matching enc.Mat Deadline: &args.Deadline, Content: args.Interest.AppParam(), } - logger := event.Target.Logger("ExpressPoint") // Handle FullName: the implicit sha256 component should be removed from data name if event.Target.Name[len(event.Target.Name)-1].Typ == enc.TypeImplicitSha256DigestComponent { @@ -108,7 +112,7 @@ func (n *ExpressPoint) OnInterest(args ndn.InterestHandlerArgs, matching enc.Mat if len(cachedData) > 0 { err := args.Reply(cachedData) if err != nil { - logger.Errorf("Unable to reply Interest. Drop: %+v", err) + log.Error(n, "Unable to reply Interest - DROP", "err", err) } return } @@ -127,11 +131,11 @@ func (n *ExpressPoint) OnInterest(args ndn.InterestHandlerArgs, matching enc.Mat }) res, ok := ret.(ValidRes) if !ok || res < VrSilence { - logger.Warnf("Verification failed (%d) for Interest. Drop.", res) + log.Warn(n, "Verification failed for Interest - DROP", "res", res) return } if res == VrSilence { - logger.Warn("Unverified Interest. Drop.") + log.Warn(n, "Unverified Interest - DROP") return } } @@ -169,7 +173,6 @@ func (n *ExpressPoint) NeedCallback( node := n.Node engine := n.Node.engine spec := engine.Spec() - logger := mNode.Logger("ExpressPoint") if intConfig == nil { intConfig = &ndn.InterestConfig{ CanBePrefix: n.CanBePrefix, @@ -219,7 +222,7 @@ func (n *ExpressPoint) NeedCallback( // return ret return nil } else { - logger.Error("The storage returned an invalid data") + log.Error(n, "The storage returned an invalid data") } } // storageSearched = true @@ -228,7 +231,7 @@ func (n *ExpressPoint) NeedCallback( // Construct Interest interest, err := spec.MakeInterest(mNode.Name, intConfig, appParam, signer) if err != nil { - logger.Errorf("Unable to encode Interest in Need(): %+v", err) + log.Error(n, "Unable to encode Interest in Need()", "err", err) go callback(&Event{ TargetNode: node, NeedStatus: utils.IdPtr(ndn.InterestResultNone), @@ -300,14 +303,14 @@ func (n *ExpressPoint) NeedCallback( cbEvt.ValidResult = &res } if !ok || res < VrSilence { - logger.Warnf("Verification failed (%d) for Data. Drop.", res) + log.Warn(n, "Verification failed for Data - DROP", "res", res) cbEvt.NeedStatus = utils.IdPtr(ndn.InterestResultUnverified) cbEvt.Content = nil callback(cbEvt) return } if res == VrSilence { - logger.Warn("Unverified Data. Drop.") + log.Warn(n, "Unverified Data - DROP", "res", res) cbEvt.NeedStatus = utils.IdPtr(ndn.InterestResultUnverified) cbEvt.Content = nil callback(cbEvt) @@ -324,7 +327,7 @@ func (n *ExpressPoint) NeedCallback( }() }) if err != nil { - logger.Warn("Failed to express Interest.") + log.Warn(n, "Failed to express Interest") go callback(&Event{ TargetNode: node, NeedStatus: utils.IdPtr(ndn.InterestResultNone), @@ -399,13 +402,13 @@ func initExpressPointDesc() { "Need": func(mNode MatchedNode, args ...any) any { if len(args) < 1 || len(args) > 4 { err := fmt.Errorf("ExpressPoint.Need requires 1~4 arguments but got %d", len(args)) - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } callback, ok := args[0].(Callback) if !ok { err := ndn.ErrInvalidValue{Item: "callback", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var appParam enc.Wire = nil @@ -413,7 +416,7 @@ func initExpressPointDesc() { appParam, ok = args[1].(enc.Wire) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "appParam", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -422,7 +425,7 @@ func initExpressPointDesc() { intConfig, ok = args[2].(*ndn.InterestConfig) if !ok && args[2] != nil { err := ndn.ErrInvalidValue{Item: "intConfig", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -431,7 +434,7 @@ func initExpressPointDesc() { suppress, ok = args[3].(bool) if !ok { err := ndn.ErrInvalidValue{Item: "suppress", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -440,7 +443,7 @@ func initExpressPointDesc() { "NeedChan": func(mNode MatchedNode, args ...any) any { if len(args) > 3 { err := fmt.Errorf("ExpressPoint.NeedChan requires 0~3 arguments but got %d", len(args)) - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var appParam enc.Wire = nil @@ -449,7 +452,7 @@ func initExpressPointDesc() { appParam, ok = args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "appParam", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -458,7 +461,7 @@ func initExpressPointDesc() { intConfig, ok = args[1].(*ndn.InterestConfig) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "intConfig", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -467,7 +470,7 @@ func initExpressPointDesc() { suppress, ok = args[2].(bool) if !ok { err := ndn.ErrInvalidValue{Item: "suppress", Value: args[0]} - mNode.Logger("ExpressPoint").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } diff --git a/std/schema/interface.go b/std/schema/interface.go index cd253cf7..9fd1290f 100644 --- a/std/schema/interface.go +++ b/std/schema/interface.go @@ -6,7 +6,6 @@ import ( "time" enc "github.com/named-data/ndnd/std/encoding" - "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" ) @@ -387,12 +386,3 @@ func (mNode MatchedNode) Refine(name enc.Name) *MatchedNode { return nil } } - -// Logger returns the logger used in functions provided by this node. -// If module is "", the node's impl's class name will be used as a default value. -func (mNode MatchedNode) Logger(module string) *log.Entry { - if module == "" { - module = mNode.Node.desc.ClassName - } - return mNode.Node.Log().WithField("name", mNode.Name.String()).WithField("module", module) -} diff --git a/std/schema/leaf_node.go b/std/schema/leaf_node.go index bbe546a8..3419c146 100644 --- a/std/schema/leaf_node.go +++ b/std/schema/leaf_node.go @@ -5,6 +5,7 @@ import ( "time" enc "github.com/named-data/ndnd/std/encoding" + "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" "github.com/named-data/ndnd/std/utils" ) @@ -37,7 +38,6 @@ func (n *LeafNode) Provide( node := n.Node engine := n.Node.engine spec := engine.Spec() - logger := mNode.Logger("LeafNode") if dataCfg == nil { dataCfg = &ndn.DataConfig{ ContentType: utils.IdPtr(n.ContentType), @@ -63,7 +63,7 @@ func (n *LeafNode) Provide( data, err := spec.MakeData(mNode.Name, dataCfg, content, signer) if err != nil { - logger.Errorf("Unable to encode Data in Provide(): %+v", err) + log.Error(n, "Unable to encode Data in Provide()", "err", err) return nil } @@ -114,14 +114,14 @@ func initLeafNodeDesc() { LeafNodeDesc.Functions["Provide"] = func(mNode MatchedNode, args ...any) any { if len(args) < 1 || len(args) > 2 { err := fmt.Errorf("LeafNode.Provide requires 1~2 arguments but got %d", len(args)) - mNode.Logger("LeafNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } // content enc.Wire, dataCfg *ndn.DataConfig, content, ok := args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "content", Value: args[0]} - mNode.Logger("LeafNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var dataCfg *ndn.DataConfig @@ -129,7 +129,7 @@ func initLeafNodeDesc() { dataCfg, ok = args[1].(*ndn.DataConfig) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "dataCfg", Value: args[0]} - mNode.Logger("LeafNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } diff --git a/std/schema/rdr/pipelines.go b/std/schema/rdr/pipelines.go index e4be153c..6593f462 100644 --- a/std/schema/rdr/pipelines.go +++ b/std/schema/rdr/pipelines.go @@ -4,6 +4,7 @@ import ( "time" enc "github.com/named-data/ndnd/std/encoding" + "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" "github.com/named-data/ndnd/std/schema" ) @@ -40,10 +41,9 @@ type RdrPipelineCubic struct { // DataFetcher tries to get specified Data packet up to `maxRetries` times. func DataFetcher(mNode schema.MatchedNode, intConfig *ndn.InterestConfig, maxRetries int) schema.NeedResult { - logger := mNode.Logger("DataFetcher") var result schema.NeedResult for j := 0; j < maxRetries; j++ { - logger.Debugf("Fetching [the %d/%d trial]", j, maxRetries) + log.Debug(mNode.Node, "Fetching", "j", j, "retries", maxRetries) result = <-mNode.Call("NeedChan").(chan schema.NeedResult) switch result.Status { case ndn.InterestResultData: diff --git a/std/schema/rdr/rdr.go b/std/schema/rdr/rdr.go index f9fa2cae..f008106d 100644 --- a/std/schema/rdr/rdr.go +++ b/std/schema/rdr/rdr.go @@ -6,6 +6,7 @@ import ( "time" enc "github.com/named-data/ndnd/std/encoding" + "github.com/named-data/ndnd/std/log" "github.com/named-data/ndnd/std/ndn" rtlv "github.com/named-data/ndnd/std/ndn/rdr_2024" "github.com/named-data/ndnd/std/schema" @@ -51,6 +52,10 @@ func CreateSegmentedNode(node *schema.Node) schema.NodeImpl { return ret } +func (n *SegmentedNode) String() string { + return fmt.Sprintf("SegmentedNode (%s)", n.Node) +} + func (n *SegmentedNode) Provide(mNode schema.MatchedNode, content enc.Wire, needManifest bool) any { if mNode.Node != n.Node { panic("NTSchema tree compromised.") @@ -99,7 +104,7 @@ func (n *SegmentedNode) Provide(mNode schema.MatchedNode, content enc.Wire, need ret[i] = h.Sum(nil) } } - mNode.Logger("SegmentedNode").Debugf("Segmented into %d segments \n", segCnt) + log.Debug(n, "Segmented object", "segCnt", segCnt) if needManifest { return ret } else { @@ -117,7 +122,7 @@ func (n *SegmentedNode) NeedCallback( go n.SinglePacketPipeline(mNode, callback, manifest) return nil } - mNode.Logger("SegmentedNode").Errorf("unrecognized pipeline: %s", n.Pipeline) + log.Error(n, "Unrecognized pipeline", "pipeline", n.Pipeline) return fmt.Errorf("unrecognized pipeline: %s", n.Pipeline) } @@ -147,7 +152,6 @@ func (n *SegmentedNode) SinglePacketPipeline( var lastNackReason *uint64 var lastValidationRes *schema.ValidRes var lastNeedStatus ndn.InterestResult - logger := mNode.Logger("SegmentedNode") nameLen := len(mNode.Name) var newName enc.Name if len(manifest) > 0 { @@ -165,7 +169,7 @@ func (n *SegmentedNode) SinglePacketPipeline( newMNode := mNode.Refine(newName) succeeded = false for j := 0; !succeeded && j < int(n.MaxRetriesOnFailure); j++ { - logger.Debugf("Fetching the %d fragment [the %d trial]", i, j) + log.Debug(n, "Fetching packet", "trial", j, "retries") result := <-newMNode.Call("NeedChan").(chan schema.NeedResult) lastData = result.Data lastNackReason = result.NackReason @@ -225,6 +229,10 @@ type RdrNode struct { MaxRetriesForMeta uint64 } +func (n *RdrNode) String() string { + return fmt.Sprintf("RdrNode (%s)", n.Node) +} + func (n *RdrNode) NodeImplTrait() schema.NodeImpl { return n } @@ -299,7 +307,6 @@ func (n *RdrNode) NeedCallback(mNode schema.MatchedNode, callback schema.Callbac go func() { nameLen := len(mNode.Name) - logger := mNode.Logger("RdrNode") var err error = nil var fullName enc.Name var metadata *rtlv.MetaData @@ -314,14 +321,14 @@ func (n *RdrNode) NeedCallback(mNode schema.MatchedNode, callback schema.Callbac succeeded := false for j := 0; !succeeded && j < int(n.MaxRetriesForMeta); j++ { - logger.Debugf("Fetching the metadata packet [the %d trial]", j) + log.Debug(n, "Fetching the metadata", "trial", j) lastResult = <-epMNode.Call("NeedChan").(chan schema.NeedResult) switch lastResult.Status { case ndn.InterestResultData: succeeded = true metadata, err = rtlv.ParseMetaData(enc.NewWireReader(lastResult.Content), true) if err != nil { - logger.Errorf("Unable to parse and extract name from the metadata packet: %v\n", err) + log.Error(n, "Unable to parse and extract name from the metadata packet", "err", err) lastResult.Status = ndn.InterestResultError } fullName = metadata.Name @@ -433,6 +440,10 @@ func CreateGeneralObjNode(node *schema.Node) schema.NodeImpl { return ret } +func (n *GeneralObjNode) String() string { + return fmt.Sprintf("GeneralObjNode (%s)", n.Node) +} + func (n *GeneralObjNode) Provide(mNode schema.MatchedNode, content enc.Wire) uint64 { if mNode.Node != n.Node { panic("NTSchema tree compromised.") @@ -493,7 +504,6 @@ func (n *GeneralObjNode) NeedCallback(mNode schema.MatchedNode, callback schema. go func() { nameLen := len(mNode.Name) - logger := mNode.Logger("GeneralObjNode") var err error = nil var manifest *rtlv.ManifestData var lastResult schema.NeedResult @@ -506,14 +516,14 @@ func (n *GeneralObjNode) NeedCallback(mNode schema.MatchedNode, callback schema. succeeded := false for j := 0; !succeeded && j < int(n.MaxRetriesForManifest); j++ { - logger.Debugf("Fetching the manifest packet [the %d trial]", j) + log.Debug(n, "Fetching the manifest packet", "trial", j) lastResult = <-manifestMNode.Call("NeedChan").(chan schema.NeedResult) switch lastResult.Status { case ndn.InterestResultData: succeeded = true manifest, err = rtlv.ParseManifestData(enc.NewWireReader(lastResult.Content), true) if err != nil { - logger.Errorf("Unable to parse the manifest packet: %v\n", err) + log.Error(n, "Unable to parse the manifest packet", "err", err) lastResult.Status = ndn.InterestResultError } } @@ -597,13 +607,13 @@ func initRdrNodes() { "Provide": func(mNode schema.MatchedNode, args ...any) any { if len(args) < 1 || len(args) > 2 { err := fmt.Errorf("SegmentedNode.Provide requires 1~2 arguments but got %d", len(args)) - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } content, ok := args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "content", Value: args[0]} - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var needManifest bool = false @@ -611,7 +621,7 @@ func initRdrNodes() { needManifest, ok = args[1].(bool) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "needManifest", Value: args[0]} - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -620,13 +630,13 @@ func initRdrNodes() { "Need": func(mNode schema.MatchedNode, args ...any) any { if len(args) < 1 || len(args) > 2 { err := fmt.Errorf("SegmentedNode.Need requires 1~2 arguments but got %d", len(args)) - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } callback, ok := args[0].(schema.Callback) if !ok { err := ndn.ErrInvalidValue{Item: "callback", Value: args[0]} - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var manifest []enc.Buffer = nil @@ -634,7 +644,7 @@ func initRdrNodes() { manifest, ok = args[1].([]enc.Buffer) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "manifest", Value: args[0]} - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -643,7 +653,7 @@ func initRdrNodes() { "NeedChan": func(mNode schema.MatchedNode, args ...any) any { if len(args) > 1 { err := fmt.Errorf("SegmentedNode.NeedChan requires 0~1 arguments but got %d", len(args)) - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var manifest []enc.Buffer = nil @@ -652,7 +662,7 @@ func initRdrNodes() { manifest, ok = args[0].([]enc.Buffer) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "manifest", Value: args[0]} - mNode.Logger("SegmentedNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -686,13 +696,13 @@ func initRdrNodes() { "Provide": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 1 { err := fmt.Errorf("RdrNode.Provide requires 1 arguments but got %d", len(args)) - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } content, ok := args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "content", Value: args[0]} - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*RdrNode](mNode.Node).Provide(mNode, content) @@ -700,13 +710,13 @@ func initRdrNodes() { "Need": func(mNode schema.MatchedNode, args ...any) any { if len(args) < 1 || len(args) > 2 { err := fmt.Errorf("RdrNode.Need requires 1~2 arguments but got %d", len(args)) - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } callback, ok := args[0].(schema.Callback) if !ok { err := ndn.ErrInvalidValue{Item: "callback", Value: args[0]} - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var version *uint64 = nil @@ -714,7 +724,7 @@ func initRdrNodes() { version, ok = args[1].(*uint64) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "version", Value: args[0]} - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -724,7 +734,7 @@ func initRdrNodes() { "NeedChan": func(mNode schema.MatchedNode, args ...any) any { if len(args) > 1 { err := fmt.Errorf("RdrNode.NeedChan requires 0~1 arguments but got %d", len(args)) - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } var version *uint64 = nil @@ -733,7 +743,7 @@ func initRdrNodes() { version, ok = args[0].(*uint64) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "version", Value: args[0]} - mNode.Logger("RdrNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } } @@ -770,13 +780,13 @@ func initRdrNodes() { "Provide": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 1 { err := fmt.Errorf("GeneralObjNode.Provide requires 1 arguments but got %d", len(args)) - mNode.Logger("GeneralObjNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } content, ok := args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "content", Value: args[0]} - mNode.Logger("GeneralObjNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*GeneralObjNode](mNode.Node).Provide(mNode, content) @@ -784,13 +794,13 @@ func initRdrNodes() { "Need": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 1 { err := fmt.Errorf("GeneralObjNode.Need requires 1 arguments but got %d", len(args)) - mNode.Logger("GeneralObjNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } callback, ok := args[0].(schema.Callback) if !ok { err := ndn.ErrInvalidValue{Item: "callback", Value: args[0]} - mNode.Logger("GeneralObjNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } schema.QueryInterface[*GeneralObjNode](mNode.Node).NeedCallback(mNode, callback) @@ -799,7 +809,7 @@ func initRdrNodes() { "NeedChan": func(mNode schema.MatchedNode, args ...any) any { if len(args) > 0 { err := fmt.Errorf("GeneralObjNode.NeedChan requires 0 arguments but got %d", len(args)) - mNode.Logger("GeneralObjNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*GeneralObjNode](mNode.Node).NeedChan(mNode) diff --git a/std/schema/svs/sync.go b/std/schema/svs/sync.go index 1fdf3ca8..b2625026 100644 --- a/std/schema/svs/sync.go +++ b/std/schema/svs/sync.go @@ -59,6 +59,10 @@ type SvsNode struct { notifNode *schema.Node } +func (n *SvsNode) String() string { + return "svs-node" +} + func (n *SvsNode) NodeImplTrait() schema.NodeImpl { return n } @@ -109,11 +113,9 @@ func findSvsEntry(v *spec_svs.StateVector, name enc.Name) int { } func (n *SvsNode) onSyncInt(event *schema.Event) any { - mNotifNode := event.Target - logger := mNotifNode.Logger("SvsNode") // the path will be the subchild remoteSv, err := spec_svs.ParseStateVector(enc.NewWireReader(event.Content), true) if err != nil { - logger.Error("Unable to parse state vector. Drop.") + log.Error(n, "Unable to parse state vector - DROP", "err", err) } // If append() is called on localSv slice, a lock is necessary @@ -137,7 +139,7 @@ func (n *SvsNode) onSyncInt(event *schema.Event) any { EndSeq: cur.SeqNo + 1, } } else if n.localSv.Entries[li].SeqNo < cur.SeqNo { - log.Debugf("Missing data for: [%d]: %d < %d", cur.Name, n.localSv.Entries[li].SeqNo, cur.SeqNo) + log.Debug(n, "Missing data found", "name", cur.Name, "local", n.localSv.Entries[li].SeqNo, "cur", cur.SeqNo) n.missChan <- MissingData{ Name: cur.Name, StartSeq: n.localSv.Entries[li].SeqNo + 1, @@ -146,7 +148,7 @@ func (n *SvsNode) onSyncInt(event *schema.Event) any { n.localSv.Entries[li].SeqNo = cur.SeqNo // needFetch = true } else if n.localSv.Entries[li].SeqNo > cur.SeqNo { - log.Debugf("Outdated remote on: [%d]: %d < %d", cur.Name, cur.SeqNo, n.localSv.Entries[li].SeqNo) + log.Debug(n, "Outdated remote on", "name", cur.Name, "local", n.localSv.Entries[li].SeqNo, "cur", cur.SeqNo) needNotif = true } } @@ -267,8 +269,6 @@ func (n *SvsNode) NewData(mNode schema.MatchedNode, content enc.Wire) enc.Wire { n.dataLock.Lock() defer n.dataLock.Unlock() - logger := mNode.Logger("SvsNode") - n.selfSeq++ newDataName := make(enc.Name, len(n.ownPrefix)+1) copy(newDataName, n.ownPrefix) @@ -281,10 +281,10 @@ func (n *SvsNode) NewData(mNode schema.MatchedNode, content enc.Wire) enc.Wire { n.localSv.Entries[li].SeqNo = n.selfSeq } n.state = SyncSteady - logger.Debugf("NewData generated w/ seq=%d", n.selfSeq) + log.Debug(n, "NewData generated", "seq", n.selfSeq) n.expressStateVec() } else { - logger.Errorf("Failed to provide seq=%d", n.selfSeq) + log.Error(n, "Failed to provide", "seq", n.selfSeq) n.selfSeq-- } return ret @@ -388,13 +388,13 @@ func init() { "NewData": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 1 { err := fmt.Errorf("SvsNode.NewData requires 1 arguments but got %d", len(args)) - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } content, ok := args[0].(enc.Wire) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "content", Value: args[0]} - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*SvsNode](mNode.Node).NewData(mNode, content) @@ -402,7 +402,7 @@ func init() { "MissingDataChannel": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 0 { err := fmt.Errorf("SvsNode.MissingDataChannel requires 0 arguments but got %d", len(args)) - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*SvsNode](mNode.Node).MissingDataChannel() @@ -410,7 +410,7 @@ func init() { "MySequence": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 0 { err := fmt.Errorf("SvsNode.MySequence requires 0 arguments but got %d", len(args)) - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*SvsNode](mNode.Node).MySequence() @@ -418,19 +418,19 @@ func init() { "GetDataName": func(mNode schema.MatchedNode, args ...any) any { if len(args) != 2 { err := fmt.Errorf("SvsNode.GetDataName requires 2 arguments but got %d", len(args)) - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } nodeId, ok := args[0].([]byte) if !ok && args[0] != nil { err := ndn.ErrInvalidValue{Item: "nodeId", Value: args[0]} - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } seq, ok := args[1].(uint64) if !ok && args[1] != nil { err := ndn.ErrInvalidValue{Item: "seq", Value: args[1]} - mNode.Logger("SvsNode").Error(err.Error()) + log.Error(mNode.Node, err.Error()) return err } return schema.QueryInterface[*SvsNode](mNode.Node).GetDataName(mNode, nodeId, seq) diff --git a/std/schema/tree.go b/std/schema/tree.go index 5f272fd2..604f108c 100644 --- a/std/schema/tree.go +++ b/std/schema/tree.go @@ -19,6 +19,10 @@ type Tree struct { engine ndn.Engine } +func (t *Tree) String() string { + return "schema" +} + func (t *Tree) Engine() ndn.Engine { return t.engine } @@ -48,7 +52,7 @@ func (t *Tree) Attach(prefix enc.Name, engine ndn.Engine) error { if err != nil { return err } - log.WithField("module", "schema").Info("Attached to engine.") + log.Info(t, "Attached to engine") t.engine = engine return nil } @@ -61,7 +65,7 @@ func (t *Tree) Detach() { t.lock.Lock() defer t.lock.Unlock() - log.WithField("module", "schema").Info("Detached from engine") + log.Info(t, "Detached from engine") t.engine.DetachHandler(t.root.AttachedPrefix()) t.root.OnDetach() } @@ -79,9 +83,7 @@ func (t *Tree) intHandler(args ndn.InterestHandlerArgs) { matchName := args.Interest.Name() mNode := t.root.Match(matchName) if mNode == nil { - log.WithField("module", "schema"). - WithField("name", args.Interest.Name().String()). - Warn("Unexpected Interest. Drop.") + log.Warn(t, "Unexpected Interest - DROP", "name", matchName) return } mNode.Node.OnInterest(args, mNode.Matching) diff --git a/std/security/pib/sqlite-pib.go b/std/security/pib/sqlite-pib.go index 4cae9827..5077fe6e 100644 --- a/std/security/pib/sqlite-pib.go +++ b/std/security/pib/sqlite-pib.go @@ -39,6 +39,10 @@ type SqlitePib struct { tpm Tpm } +func (pib *SqlitePib) String() string { + return "sqlite-pib" +} + func (pib *SqlitePib) Tpm() Tpm { return pib.tpm } @@ -252,7 +256,7 @@ func (key *SqliteKey) FindCert(check func(Cert) bool) Cert { func NewSqlitePib(path string, tpm Tpm) *SqlitePib { db, err := sql.Open("sqlite3", path) if err != nil { - log.WithField("module", "SqlitePib").Errorf("unable to connect to sqlite PIB: %+v", err) + log.Error(nil, "Unable to connect to sqlite PIB", "err", err) return nil } return &SqlitePib{ diff --git a/std/security/pib/tpm-file.go b/std/security/pib/tpm-file.go index 29644d5f..7309f4ed 100644 --- a/std/security/pib/tpm-file.go +++ b/std/security/pib/tpm-file.go @@ -5,6 +5,7 @@ import ( "crypto/x509" "encoding/base64" "encoding/hex" + "fmt" "os" "path" @@ -18,6 +19,10 @@ type FileTpm struct { path string } +func (tpm *FileTpm) String() string { + return fmt.Sprintf("file-tpm (%s)", tpm.path) +} + func (tpm *FileTpm) ToFileName(keyNameBytes []byte) string { h := sha256.New() h.Write(keyNameBytes) @@ -30,7 +35,7 @@ func (tpm *FileTpm) GetSigner(keyName enc.Name, keyLocatorName enc.Name) ndn.Sig text, err := os.ReadFile(fileName) if err != nil { - log.WithField("module", "FileTpm").Errorf("unable to read private key file: %s, %+v", fileName, err) + log.Error(tpm, "Unable to read private key file", "file", fileName, "error", err) return nil } @@ -38,7 +43,7 @@ func (tpm *FileTpm) GetSigner(keyName enc.Name, keyLocatorName enc.Name) ndn.Sig block := make([]byte, blockLen) n, err := base64.StdEncoding.Decode(block, text) if err != nil { - log.WithField("module", "FileTpm").Errorf("unable to base64 decode private key file: %s, %+v", fileName, err) + log.Error(tpm, "Unable to base64 decode private key file", "file", fileName, "error", err) return nil } block = block[:n] @@ -58,7 +63,7 @@ func (tpm *FileTpm) GetSigner(keyName enc.Name, keyLocatorName enc.Name) ndn.Sig return sec.NewRsaSigner(false, false, 0, rsabits, keyLocatorName) } - log.WithField("module", "FileTpm").Errorf("unrecognized private key format: %s", fileName) + log.Error(tpm, "Unrecognized private key format", "file", fileName) return nil } From 5b31e6a715b7170d6f99bacf0f2ee67769f403d2 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 00:52:11 +0000 Subject: [PATCH 06/12] fw: fix darwin build --- fw/face/impl/syscalls_darwin.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/fw/face/impl/syscalls_darwin.go b/fw/face/impl/syscalls_darwin.go index 59e8eaa7..f1ffe909 100644 --- a/fw/face/impl/syscalls_darwin.go +++ b/fw/face/impl/syscalls_darwin.go @@ -23,7 +23,7 @@ func SyscallGetSocketSendQueueSize(c syscall.RawConn) uint64 { var err error val, err = unix.GetsockoptInt(int(fd), unix.SOL_SOCKET, unix.SO_NWRITE) if err != nil { - core.Log.Warn("Face-Syscall", "Unable to get size of socket send queue for fd", "fd", fd, "err", err) + core.Log.Warn(nil, "Unable to get size of socket send queue for fd", "fd", fd, "err", err) val = 0 } }) From 0c13a9f541b6006ecac720bd0ad73f302546ab35 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 01:11:30 +0000 Subject: [PATCH 07/12] dv: adjust log messsages --- dv/table/prefix_table.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/dv/table/prefix_table.go b/dv/table/prefix_table.go index ae64b91d..e1d30a93 100644 --- a/dv/table/prefix_table.go +++ b/dv/table/prefix_table.go @@ -143,19 +143,19 @@ func (pt *PrefixTable) Apply(ops *tlv.PrefixOpList) (dirty bool) { router := pt.GetRouter(ops.ExitRouter.Name) if ops.PrefixOpReset { - log.Info(pt, "Reset prefixes for remote", "router", ops.ExitRouter.Name) + log.Info(pt, "Reset remote prefixes", "router", ops.ExitRouter.Name) router.Prefixes = make(map[string]*PrefixEntry) dirty = true } for _, add := range ops.PrefixOpAdds { - log.Info(pt, "Add prefix for remote", "router", ops.ExitRouter.Name, "name", add.Name) + log.Info(pt, "Add remote prefix", "router", ops.ExitRouter.Name, "name", add.Name) router.Prefixes[add.Name.String()] = &PrefixEntry{Name: add.Name} dirty = true } for _, remove := range ops.PrefixOpRemoves { - log.Info(pt, "Remove prefix for remote", "router", ops.ExitRouter.Name, "name", remove.Name) + log.Info(pt, "Remove remote prefix", "router", ops.ExitRouter.Name, "name", remove.Name) delete(router.Prefixes, remove.Name.String()) dirty = true } From 70ab75a88f7fd0a0304e686512a9b97391d24347 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 01:25:21 +0000 Subject: [PATCH 08/12] tidy mod --- go.mod | 1 - go.sum | 2 -- 2 files changed, 3 deletions(-) diff --git a/go.mod b/go.mod index 3973b3ab..0273a75c 100644 --- a/go.mod +++ b/go.mod @@ -7,7 +7,6 @@ require ( github.com/goccy/go-yaml v1.15.13 github.com/gorilla/websocket v1.5.3 github.com/mattn/go-sqlite3 v1.14.24 - github.com/pkg/errors v0.9.1 github.com/stretchr/testify v1.10.0 go.etcd.io/bbolt v1.3.11 golang.org/x/exp v0.0.0-20241217172543-b2144cdd0a67 diff --git a/go.sum b/go.sum index aec9a630..d34a2f53 100644 --- a/go.sum +++ b/go.sum @@ -12,8 +12,6 @@ github.com/gorilla/websocket v1.5.3 h1:saDtZ6Pbx/0u+bgYQ3q96pZgCzfhKXGPqt7kZ72aN github.com/gorilla/websocket v1.5.3/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE= github.com/mattn/go-sqlite3 v1.14.24 h1:tpSp2G2KyMnnQu99ngJ47EIkWVmliIizyZBfPrBWDRM= github.com/mattn/go-sqlite3 v1.14.24/go.mod h1:Uh1q+B4BYcTPb+yiD3kU8Ct7aC0hY9fxUwlHK0RXw+Y= -github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= -github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/spaolacci/murmur3 v0.0.0-20180118202830-f09979ecbc72 h1:qLC7fQah7D6K1B0ujays3HV9gkFtllcxhzImRR7ArPQ= From 7245ddb3e14a5382d78b534338cd63391823ea44 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 01:32:41 +0000 Subject: [PATCH 09/12] refactor: client seg tag --- std/object/client_consume_seg.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/std/object/client_consume_seg.go b/std/object/client_consume_seg.go index e99a6d14..9b414f21 100644 --- a/std/object/client_consume_seg.go +++ b/std/object/client_consume_seg.go @@ -40,7 +40,7 @@ func newRrSegFetcher(client *Client) rrSegFetcher { // log identifier func (s *rrSegFetcher) String() string { - return "seg-fetcher" + return "client-seg" } // add a stream to the fetch queue From 8544937478df9409ae7f494f34d1eb5906d62f0d Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 01:39:29 +0000 Subject: [PATCH 10/12] nfdc: fix panic --- tools/nfdc/nfdc_cmd.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/tools/nfdc/nfdc_cmd.go b/tools/nfdc/nfdc_cmd.go index a12776bc..78405092 100644 --- a/tools/nfdc/nfdc_cmd.go +++ b/tools/nfdc/nfdc_cmd.go @@ -201,6 +201,9 @@ func (n *Nfdc) printCtrlResponse(res *mgmt.ControlResponse) { fmt.Printf("Status=%d (%s)\n", res.Val.StatusCode, res.Val.StatusText) // iterate over parameters in sorted order + if res.Val.Params == nil { + return + } params := res.Val.Params.ToDict() keys := make([]string, 0, len(params)) for key := range params { From 00872b2995a75df55ef0cbca68eb842dcc4f307d Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 01:43:31 +0000 Subject: [PATCH 11/12] std: fix tag --- std/engine/basic/engine.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/std/engine/basic/engine.go b/std/engine/basic/engine.go index 61dfa20e..3f53de22 100644 --- a/std/engine/basic/engine.go +++ b/std/engine/basic/engine.go @@ -59,7 +59,7 @@ type Engine struct { } func (e *Engine) String() string { - return "BasicEngine" + return "basic-engine" } func (e *Engine) EngineTrait() ndn.Engine { From b40133a3060602e2a7c769e337d3b9b855e02c82 Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 14 Jan 2025 01:54:58 +0000 Subject: [PATCH 12/12] std: logging refactor --- std/examples/low-level/consumer/main.go | 8 +++----- std/examples/low-level/producer/main.go | 13 ++++++------- tools/putchunks.go | 3 ++- 3 files changed, 11 insertions(+), 13 deletions(-) diff --git a/std/examples/low-level/consumer/main.go b/std/examples/low-level/consumer/main.go index c45f775f..a9d053e3 100644 --- a/std/examples/low-level/consumer/main.go +++ b/std/examples/low-level/consumer/main.go @@ -11,13 +11,11 @@ import ( "github.com/named-data/ndnd/std/utils" ) -var logger = log.Default() - func main() { app := engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatal(nil, "Unable to start engine", "err", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -32,7 +30,7 @@ func main() { } interest, err := app.Spec().MakeInterest(name, intCfg, nil, nil) if err != nil { - logger.Error(nil, "Unable to make Interest", "err", err) + log.Error(nil, "Unable to make Interest", "err", err) return } @@ -55,7 +53,7 @@ func main() { ch <- struct{}{} }) if err != nil { - logger.Error(nil, "Unable to send Interest", "err", err) + log.Error(nil, "Unable to send Interest", "err", err) return } diff --git a/std/examples/low-level/producer/main.go b/std/examples/low-level/producer/main.go index 09e3ca7e..44c25310 100644 --- a/std/examples/low-level/producer/main.go +++ b/std/examples/low-level/producer/main.go @@ -18,7 +18,6 @@ import ( var app ndn.Engine var pib *sec_pib.SqlitePib -var logger = log.Default() func onInterest(args ndn.InterestHandlerArgs) { interest := args.Interest @@ -40,12 +39,12 @@ func onInterest(args ndn.InterestHandlerArgs) { enc.Wire{content}, signer) if err != nil { - logger.Error(nil, "Unable to encode data", "err", err) + log.Error(nil, "Unable to encode data", "err", err) return } err = args.Reply(data.Wire) if err != nil { - logger.Error(nil, "Unable to reply with data", "err", err) + log.Error(nil, "Unable to reply with data", "err", err) return } fmt.Printf("<< D: %s\n", interest.Name().String()) @@ -57,7 +56,7 @@ func main() { app = engine.NewBasicEngine(engine.NewDefaultFace()) err := app.Start() if err != nil { - logger.Fatal(nil, "Unable to start engine", "err", err) + log.Fatal(nil, "Unable to start engine", "err", err) return } defer app.Stop() @@ -69,12 +68,12 @@ func main() { prefix, _ := enc.NameFromStr("/example/testApp") err = app.AttachHandler(prefix, onInterest) if err != nil { - logger.Error(nil, "Unable to register handler", "err", err) + log.Error(nil, "Unable to register handler", "err", err) return } err = app.RegisterRoute(prefix) if err != nil { - logger.Error(nil, "Unable to register route", "err", err) + log.Error(nil, "Unable to register route", "err", err) return } @@ -82,5 +81,5 @@ func main() { sigChannel := make(chan os.Signal, 1) signal.Notify(sigChannel, os.Interrupt, syscall.SIGTERM) receivedSig := <-sigChannel - logger.Info(nil, "Received signal - exiting", "signal", receivedSig) + log.Info(nil, "Received signal - exiting", "signal", receivedSig) } diff --git a/tools/putchunks.go b/tools/putchunks.go index 372b0eb4..558a63a3 100644 --- a/tools/putchunks.go +++ b/tools/putchunks.go @@ -99,5 +99,6 @@ func (pc *PutChunks) run() { // wait forever sigchan := make(chan os.Signal, 1) signal.Notify(sigchan, os.Interrupt, syscall.SIGTERM) - <-sigchan + receivedSig := <-sigchan + log.Info(nil, "Received signal - exiting", "signal", receivedSig) }