diff --git a/cmd/reactor/main.go b/cmd/reactor/main.go index d705a9f..ce81597 100644 --- a/cmd/reactor/main.go +++ b/cmd/reactor/main.go @@ -7,6 +7,7 @@ import ( "log" "strconv" "FRMS/internal/pkg/reactor" + "FRMS/internal/pkg/logging" ) type coordinator interface { @@ -48,6 +49,7 @@ func main() { ch := make(chan error) rlc := NewCoordinator(ip,port,ch) // host port go rlc.Start() + logging.Debug(logging.DStart, "Reactor Started") err = <-ch if err != nil { log.Fatal(err) diff --git a/cmd/reactor/reactor b/cmd/reactor/reactor index efb8b05..4f794ec 100755 Binary files a/cmd/reactor/reactor and b/cmd/reactor/reactor differ diff --git a/cmd/server/main.go b/cmd/server/main.go index e8b6433..9ca81da 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -8,6 +8,7 @@ import ( "os" "fmt" "FRMS/internal/pkg/server" + "FRMS/internal/pkg/logging" ) type listener interface { @@ -40,6 +41,7 @@ func main() { log.Fatal(err) } go l.Start() + logging.Debug(logging.DStart, "server starting") err = <-ch // blocking to wait for any errors and keep alive otherwise if err != nil { //fmt.Printf("ERROR: %v\n",err) diff --git a/cmd/server/server b/cmd/server/server index 7edb90a..9104700 100755 Binary files a/cmd/server/server and b/cmd/server/server differ diff --git a/cmd/tui/main.go b/cmd/tui/main.go index fefee53..dd5131e 100644 --- a/cmd/tui/main.go +++ b/cmd/tui/main.go @@ -7,6 +7,7 @@ import ( "os" "strconv" "FRMS/internal/pkg/tui" + "FRMS/internal/pkg/logging" ) type TUI interface { @@ -42,6 +43,7 @@ func main() { ch := make(chan error) t := NewTUI(ip,port,ifconfig,ch) go t.Start() + logging.Debug(logging.DStart, "Started TUI Client") err = <-ch if err != nil { log.Fatal(err) diff --git a/cmd/tui/tui b/cmd/tui/tui index 8c2917b..7dcb53c 100755 Binary files a/cmd/tui/tui and b/cmd/tui/tui differ diff --git a/internal/pkg/logging/dslogs b/internal/pkg/logging/dslogs new file mode 100755 index 0000000..b349e7f --- /dev/null +++ b/internal/pkg/logging/dslogs @@ -0,0 +1,111 @@ +#!/usr/bin/env python3 +import sys +import shutil +from typing import Optional, List, Tuple, Dict + +import typer +from rich import print +from rich.columns import Columns +from rich.console import Console +from rich.traceback import install + +# fmt: off +# Mapping from topics to colors +TOPICS = { + "EXIT": "#9a9a99", + "STRT": "#67a0b2", + "PING": "#d0b343", + "SCAN": "#70c43f", + #"LOG1": "#4878bc", + #"LOG2": "#398280", + #"CMIT": "#98719f", + #"PERS": "#d08341", + #"SNAP": "#FD971F", + #"DROP": "#ff615c", + "CLNT": "#00813c", + #"TEST": "#fe2c79", + #"INFO": "#ffffff", + #"WARN": "#d08341", + "ERRO": "#fe2626", +} +# fmt: on + + +def list_topics(value: Optional[str]): + if value is None: + return value + topics = value.split(",") + for topic in topics: + if topic not in TOPICS: + raise typer.BadParameter(f"topic {topic} not recognized") + return topics + + +def main( + file: typer.FileText = typer.Argument(None, help="File to read, stdin otherwise"), + colorize: bool = typer.Option(True, "--no-color"), + n_columns: Optional[int] = typer.Option(None, "--columns", "-c"), + ignore: Optional[str] = typer.Option(None, "--ignore", "-i", callback=list_topics), + just: Optional[str] = typer.Option(None, "--just", "-j", callback=list_topics), +): + topics = list(TOPICS) + + # We can take input from a stdin (pipes) or from a file + input_ = file if file else sys.stdin + # Print just some topics or exclude some topics (good for avoiding verbose ones) + if just: + topics = just + if ignore: + topics = [lvl for lvl in topics if lvl not in set(ignore)] + + topics = set(topics) + console = Console() + width = console.size.width + + panic = False + for line in input_: + try: + time, topic, *msg = line.strip().split(" ") + # To ignore some topics + if topic not in topics: + continue + + msg = " ".join(msg) + + # Debug calls from the test suite aren't associated with + # any particular peer. Otherwise we can treat second column + # as peer id + if topic != "TEST": + i = int(msg[1]) + + # Colorize output by using rich syntax when needed + if colorize and topic in TOPICS: + color = TOPICS[topic] + msg = f"[{color}]{msg}[/{color}]" + + # Single column printing. Always the case for debug stmts in tests + if n_columns is None or topic == "TEST": + print(time, msg) + # Multi column printing, timing is dropped to maximize horizontal + # space. Heavylifting is done through rich.column.Columns object + else: + cols = ["" for _ in range(n_columns)] + msg = "" + msg + cols[i] = msg + col_width = int(width / n_columns) + cols = Columns(cols, width=col_width - 1, equal=True, expand=True) + print(cols) + except: + # Code from tests or panics does not follow format + # so we print it as is + if line.startswith("panic"): + panic = True + # Output from tests is usually important so add a + # horizontal line with hashes to make it more obvious + if not panic: + print("#" * console.width) + print(line, end="") + + +if __name__ == "__main__": + typer.run(main) diff --git a/internal/pkg/logging/logging.go b/internal/pkg/logging/logging.go new file mode 100644 index 0000000..51c0f31 --- /dev/null +++ b/internal/pkg/logging/logging.go @@ -0,0 +1,63 @@ +package logging + +import ( + "log" + "fmt" + "os" + "time" + "strconv" +) + +func getVerbosity() int { + v := os.Getenv("VERBOSE") + level := 0 + if v != "" { + var err error + level, err = strconv.Atoi(v) + if err != nil { + log.Fatalf("Invalid Vverboity %v", v) + } + } + return level +} + +type logTopic string +const ( + // define 4 character topic abbreviations for coloring + DError logTopic = "ERRO" + DClient logTopic = "CLNT" + DStart logTopic = "STRT" + DExit logTopic = "EXIT" + DPing logTopic = "PING" + DScan logTopic = "SCAN" +) +// the list can grow + +var debugStart time.Time +var debugVerbosity int + +func init() { + filename := time.Now().Format("01-02T15:04:05") + filename += ".log" + f, err := os.OpenFile(filename, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664) + if err != nil { + log.Fatal(err) + } + log.SetOutput(f) + debugVerbosity = getVerbosity() + debugStart = time.Now() + + log.SetFlags(log.Flags() &^ (log.Ldate | log.Ltime)) // turns off date and time so we can set manually +} + +// example call Debug(dClient, "R%d connecting to client %d", r.Id, c.Id) +func Debug(topic logTopic, format string, a ...interface{}) { + if debugVerbosity >= 1 { + time := time.Since(debugStart).Microseconds() + time /= 100 + prefix := fmt.Sprintf("%06d %v ", time, string(topic)) + format = prefix + format + log.Printf(format, a...) + } +} + diff --git a/internal/pkg/reactor/monitoring.go b/internal/pkg/reactor/monitoring.go index f8f9612..d82005f 100644 --- a/internal/pkg/reactor/monitoring.go +++ b/internal/pkg/reactor/monitoring.go @@ -6,6 +6,7 @@ import ( "log" "fmt" "net" + "FRMS/internal/pkg/logging" "google.golang.org/grpc" pb "FRMS/internal/pkg/grpc" ) @@ -67,7 +68,7 @@ func (c *Coordinator) Register() { pb.RegisterMonitoringServer(grpcServer,c) go grpcServer.Serve(lis) } - log.Printf("Listening for pings on %v:%v\n",ip,c.hwinfo.Port) + logging.Debug(logging.DStart, "Listening for pings on %v:%v\n",ip,c.hwinfo.Port) } func (c *Coordinator) GetReactorStatus(ctx context.Context, ping *pb.ReactorStatusRequest) (*pb.ReactorStatusResponse, error) { diff --git a/internal/pkg/reactor/rlcoordinator.go b/internal/pkg/reactor/rlcoordinator.go index 5fe2e41..eb7bf0e 100644 --- a/internal/pkg/reactor/rlcoordinator.go +++ b/internal/pkg/reactor/rlcoordinator.go @@ -10,6 +10,7 @@ import ( "FRMS/internal/pkg/system" "FRMS/internal/pkg/I2C" "FRMS/internal/pkg/sensor" + "FRMS/internal/pkg/logging" "errors" "context" "google.golang.org/grpc" @@ -121,6 +122,7 @@ func (c *Coordinator) Start() { c.Register() go c.Monitor() go c.Connect() + logging.Debug(logging.DStart, "%v RLC Starting", c.Id) } func (c *Coordinator) Monitor() { @@ -164,7 +166,7 @@ func (c *Coordinator) Connect() { err = errors.New("Failed to connect to central server") c.Err <-err } - fmt.Printf("Server currently unavailable, retrying in %v ms", to) + logging.Debug(logging.DClient,"Server currently unavailable, retrying in %v ms", to) time.Sleep(time.Duration(to) * time.Millisecond) } else { c.Err <-err @@ -180,7 +182,7 @@ func (c *Coordinator) Connect() { c.Err <-err } if resp.GetSuccess() { - fmt.Println("Central server reached") + logging.Debug(logging.DClient,"Central server reached") } else { c.Err <-errors.New("Failed to reach central server!") } diff --git a/internal/pkg/server/coordinator.go b/internal/pkg/server/coordinator.go index e069862..00cfef3 100644 --- a/internal/pkg/server/coordinator.go +++ b/internal/pkg/server/coordinator.go @@ -2,7 +2,8 @@ package server import ( "sync" - "fmt" + //"fmt" + "FRMS/internal/pkg/logging" ) // this package creates coordinators responsible for keeping track of active clients and invoking managers @@ -45,6 +46,7 @@ func (c *Coordinator) ClientHandler(cl *Client) int { // (creates and) notifies manager of client connection m := c.GetManager(cl) go m.Start(cl) + logging.Debug(logging.DClient, "Coordinator starting manager for %v client %v",cl.Type,cl.Id) return m.GetPort() } @@ -53,7 +55,6 @@ func (c *Coordinator) GetManager(cl *Client) GeneralManager { defer c.Managers.Unlock() var exists bool var m GeneralManager - fmt.Printf("client %v\n",cl) if m, exists = c.Managers.Directory[cl.Id]; !exists { // manager in memory m = c.NewManager(cl, c.Err) diff --git a/internal/pkg/server/listener.go b/internal/pkg/server/listener.go index 1ee7352..83f489f 100644 --- a/internal/pkg/server/listener.go +++ b/internal/pkg/server/listener.go @@ -1,11 +1,12 @@ package server import ( - "log" + //"log" "fmt" "net" "context" "FRMS/internal/pkg/system" + "FRMS/internal/pkg/logging" "google.golang.org/grpc" pb "FRMS/internal/pkg/grpc" ) @@ -58,7 +59,7 @@ func (l *Listener) Start() { } go l.Sys.Start() // listener started and grpc handler registered - log.Printf("Started listener on %v:%v\n",l.Ip,l.Port) + logging.Debug(logging.DStart,"Started listener on %v:%v\n",l.Ip,l.Port) fmt.Printf("=========================\n PORT: %v\n=========================\n",l.Port) } @@ -78,9 +79,10 @@ func (l *Listener) Register() error { func (l *Listener) ReactorClientDiscoveryHandler(ctx context.Context, ping *pb.ReactorClientRequest) (*pb.ReactorClientResponse, error) { // incoming reactor ping need to spawn coord c := &Client{Ip:ping.GetClientIp(),Model:ping.GetClientModel(),Type:"reactor",Port:int(ping.GetClientPort()),Id:ping.GetClientId()} - log.Printf("%v %v has connected from %v:%v\n",c.Type,c.Id,c.Ip,c.Port) + logging.Debug(logging.DClient, "%v %v has connected from %v:%v\n",c.Type,c.Id,c.Ip,c.Port) coord, ok := l.Coordinators["reactor"] if !ok { + logging.Debug(logging.DStart, "Stating Reactor Coordinator") coord = NewReactorCoordinator(l.Sys, l.Err) l.Coordinators["reactor"] = coord coord.Start() @@ -96,12 +98,13 @@ func (l *Listener) TUIClientDiscoveryHandler(ctx context.Context, ping *pb.TUICl var ok bool coord, ok = l.Coordinators["tui"] if !ok { + logging.Debug(logging.DStart, "Stating TUI Coordinator") coord = NewTUICoordinator(l.Ip, l.Sys, l.Err) l.Coordinators["tui"] = coord coord.Start() } port := coord.ClientHandler(t) - log.Printf("%v %v has connected from %v:%v\n",t.Type,t.Id,l.Ip,port) + logging.Debug(logging.DClient,"%v %v has connected from %v:%v\n",t.Type,t.Id,l.Ip,port) r := &pb.TUIClientResponse{ClientId:t.Id,ServerIp:l.Ip,ServerPort:int32(port)} return r, nil } diff --git a/internal/pkg/server/manager.go b/internal/pkg/server/manager.go index 1432ea4..a3066da 100644 --- a/internal/pkg/server/manager.go +++ b/internal/pkg/server/manager.go @@ -1,11 +1,12 @@ package server import ( - "log" + //"log" "time" "math" "sync" "errors" + "FRMS/internal/pkg/logging" ) // this package will implement a boilerplate manager @@ -38,7 +39,7 @@ func (m *Manager) Start(cl *Client) { // manager already running m.Err <-errors.New("Manager already running!") } // if we get here, manager is atomically activated and we can ensure start wont run again - log.Printf("%v Manager (%v) starting!\n",m.Type,m.Id) + logging.Debug(logging.DStart, "%v Manager (%v) starting!\n",m.Type,m.Id) } func (m *Manager) Exit() { @@ -46,7 +47,7 @@ func (m *Manager) Exit() { if !m.Deactivate() { m.Err <-errors.New("Manager already disabled!") } - log.Printf("%v Manager (%v) exiting!\n",m.Type,m.Id) + logging.Debug(logging.DExit, "%v Manager (%v) exiting!\n",m.Type,m.Id) } // reactor manager atomic operations diff --git a/internal/pkg/server/reactormanager.go b/internal/pkg/server/reactormanager.go index 6cbee2a..387d995 100644 --- a/internal/pkg/server/reactormanager.go +++ b/internal/pkg/server/reactormanager.go @@ -6,6 +6,7 @@ import ( "log" "context" "sync" + "FRMS/internal/pkg/logging" "google.golang.org/grpc" "google.golang.org/grpc/status" "google.golang.org/grpc/credentials/insecure" @@ -65,7 +66,7 @@ func (r *ReactorManager) Connect() *grpc.ClientConn { for { if !r.IsActive() { - log.Fatal("No longer active, aborting connection attempt\n") + logging.Debug(logging.DClient,"No longer active, aborting connection attempt\n") return &grpc.ClientConn{} } var err error @@ -76,10 +77,10 @@ func (r *ReactorManager) Connect() *grpc.ClientConn { if code == (5 | 14) { // unavailable or not found to := r.Timeout() if to == 0 { - log.Printf("Client not responding\n") + logging.Debug(logging.DClient,"Client not responding\n") return &grpc.ClientConn{} } - log.Printf("Client currently down, retrying in %v ms\n",to) + logging.Debug(logging.DClient,"Client currently down, retrying in %v ms\n",to) time.Sleep(time.Duration(to) * time.Millisecond) } else { @@ -100,7 +101,7 @@ func (r *ReactorManager) Monitor(conn *grpc.ClientConn) { resp, err := client.GetReactorStatus(context.Background(),req) code := status.Code(err) if code != 0 { // if != OK - fmt.Printf("Reactor %v down! Code: %v\n", r.Id,code) + logging.Debug(logging.DClient,"Reactor %v down! Code: %v\n", r.Id,code) r.devstatus.Lock() for _, d := range r.Devs { newd := d @@ -118,6 +119,7 @@ func (r *ReactorManager) Monitor(conn *grpc.ClientConn) { r.Devs[d.Id] = d } r.devstatus.Unlock() + logging.Debug(logging.DPing, "Devices Updated for reactor %v", r.Id) time.Sleep(r.Hb) // time between sensor pings } } diff --git a/internal/pkg/server/tuimanager.go b/internal/pkg/server/tuimanager.go index b367199..bc14ff1 100644 --- a/internal/pkg/server/tuimanager.go +++ b/internal/pkg/server/tuimanager.go @@ -7,6 +7,7 @@ import ( "net" "log" "context" + "FRMS/internal/pkg/logging" "google.golang.org/grpc" pb "FRMS/internal/pkg/grpc" ) @@ -66,6 +67,7 @@ func (t *TUIManager) Timeoutd() { for t.IsActive() { if sleep, elapsed := t.Elapsed(); elapsed { // timeout elapsed + logging.Debug(logging.DExit,"Client %v no longer responding", t.Id) t.Exit() } else { time.Sleep(sleep) @@ -99,6 +101,7 @@ func (t *TUIManager) Register() { go func(ch chan int,p int) { ch <-p }(t.Port.Chan, t.Port.int) + logging.Debug(logging.DStart, "TUI Manager %v ready for client", t.Id) // up and running } @@ -124,6 +127,7 @@ func (t *TUIManager) GetDevices(ctx context.Context, req *pb.GetDevicesRequest) resp.Devices = append(resp.Devices, &pb.Dev{Id:v.Id,Type:v.Type,Status:v.Status,Data:v.Data,Index:v.Index}) } } + logging.Debug(logging.DClient,"Got devices for TUI %v" ,t.Id) return resp, nil } diff --git a/internal/pkg/tui/tui.go b/internal/pkg/tui/tui.go index 420beb7..7fc4c4b 100644 --- a/internal/pkg/tui/tui.go +++ b/internal/pkg/tui/tui.go @@ -7,6 +7,7 @@ import ( "strconv" "strings" "time" + "FRMS/internal/pkg/logging" "github.com/rivo/tview" _ "github.com/gdamore/tcell/v2" "os" @@ -46,6 +47,7 @@ func (t *TUI) Start() { if err := t.TUIClient.Start(); err != nil { t.Err <- err } + logging.Debug(logging.DStart, "TUI %v starting", t.Id) go t.Monitor() t.CreateDisplay() t.Display.Start() @@ -79,10 +81,12 @@ func (t *TUI) Monitor() { t.App.QueueUpdateDraw(func() { t.UpdateDevices(reactor) }) + logging.Debug(logging.DClient, "%v getting reactor devices", t.Id) case <-t.SelectedDevice: // TODO case <-timer: // time to ping for status + logging.Debug(logging.DClient, "%v getting reactor status", t.Id) t.App.QueueUpdateDraw(func() { t.UpdateDevices() })