diff --git a/bba/bba.go b/bba/bba.go index 5ab1e94..42b19fd 100644 --- a/bba/bba.go +++ b/bba/bba.go @@ -3,10 +3,11 @@ package bba import ( "encoding/json" "errors" - "strconv" "sync" "sync/atomic" + "github.com/DE-labtory/cleisthenes/log" + "github.com/golang/protobuf/ptypes" "github.com/DE-labtory/cleisthenes/pb" @@ -23,7 +24,6 @@ type request struct { type BBA struct { *sync.RWMutex - cleisthenes.Tracer owner cleisthenes.Member // number of network nodes @@ -86,8 +86,6 @@ func New(n int, f int, owner cleisthenes.Member, broadcaster cleisthenes.Broadca broadcaster: broadcaster, coinGenerator: coinGenerator, - - Tracer: cleisthenes.NewMemCacheTracer(), } go instance.run() return instance @@ -140,10 +138,6 @@ func (bba *BBA) Close() { close(bba.reqChan) } -func (bba *BBA) Trace() { - bba.Tracer.Trace() -} - func (bba *BBA) muxMessage(sender cleisthenes.Member, round uint64, req cleisthenes.Request) error { if round < bba.round { return nil @@ -169,16 +163,19 @@ func (bba *BBA) handleBvalRequest(sender cleisthenes.Member, bval *BvalRequest) } count := bba.countBvalByValue(bval.Value) - bba.Log("action", "handleBval", "count", strconv.Itoa(count)) + log.Debug("comp", "bba", "action", "handleBvalRequest", "owner", bba.owner.Address.String(), "round", bba.round, + "sender", sender.Address.String(), "count", count) if count == bba.binValueSetThreshold() { - bba.Log("action", "binValueSet", "count", strconv.Itoa(count)) + log.Debug("comp", "bba", "action", "binValueSet", "owner", bba.owner.Address.String(), "round", bba.round, + "sender", sender.Address.String(), "count", count) bba.binValueSet.union(bval.Value) bba.binValueChan <- struct{}{} return nil } if count == bba.bvalBroadcastThreshold() && !bba.broadcastedBvalSet.exist(bval.Value) { bba.broadcastedBvalSet.union(bval.Value) - bba.Log("action", "broadcastBval", "count", strconv.Itoa(count)) + log.Debug("comp", "bba", "action", "broadcastBval", "owner", bba.owner.Address.String(), "round", bba.round, + "sender", sender.Address.String(), "count", count) return bba.broadcast(bval) } return nil @@ -189,7 +186,8 @@ func (bba *BBA) handleAuxRequest(sender cleisthenes.Member, aux *AuxRequest) err return err } count := bba.countAuxByValue(aux.Value) - bba.Log("action", "handleAux", "from", sender.Address.String(), "count", strconv.Itoa(count)) + log.Debug("comp", "bba", "action", "handleAuxRequest", "owner", bba.owner.Address.String(), "round", bba.round, + "sender", sender.Address.String(), "count", count) if count < bba.tryoutAgreementThreshold() { return nil } @@ -198,7 +196,7 @@ func (bba *BBA) handleAuxRequest(sender cleisthenes.Member, aux *AuxRequest) err } func (bba *BBA) tryoutAgreement() { - bba.Log("action", "tryoutAgreement", "from", bba.owner.Address.String()) + log.Debug("comp", "bba", "action", "tryoutAgreement", "owner", bba.owner.Address.String(), "round", bba.round) if bba.done.Value() { return } @@ -206,18 +204,21 @@ func (bba *BBA) tryoutAgreement() { binList := bba.binValueSet.toList() if len(binList) == 0 { - bba.Log("binary set is empty, but tried agreement") + log.Debug("comp", "bba", "action", "tryoutAgreement", "owner", bba.owner.Address.String(), "round", bba.round, + "msg", "binary set is empty, but tried agreement") return } if len(binList) > 1 { - bba.Log("bin value set size is larger than one") + log.Debug("comp", "bba", "action", "tryoutAgreement", "owner", bba.owner.Address.String(), "round", bba.round, + "msg", "bin value set size is larger than one") bba.est.Set(cleisthenes.Binary(coin)) bba.advanceRoundChan <- struct{}{} return } if binList[0] != cleisthenes.Binary(coin) { - bba.Log("bin value set value is different with coin value") + log.Debug("comp", "bba", "action", "tryoutAgreement", "owner", bba.owner.Address.String(), "round", bba.round, + "msg", "bin value set value is different with coin value") bba.est.Set(binList[0]) bba.advanceRoundChan <- struct{}{} return @@ -228,7 +229,8 @@ func (bba *BBA) tryoutAgreement() { } func (bba *BBA) advanceRound() { - bba.Log("action", "advanceRound", "from", bba.owner.Address.String()) + log.Debug("comp", "bba", "action", "advanceRound", "owner", bba.owner.Address.String(), "round", bba.round, + "msg", "bin value set value is different with coin value") bba.bvalRepo = newBvalReqRepository() bba.auxRepo = newAuxReqRepository() @@ -242,7 +244,8 @@ func (bba *BBA) advanceRound() { if err := bba.HandleInput(&BvalRequest{ Value: bba.est.Value(), }); err != nil { - bba.Log("failed to handle input") + log.Error("comp", "bba", "action", "advanceRound", "owner", bba.owner.Address.String(), "round", bba.round, + "msg", "failed to handle input", "error", err.Error()) } } @@ -258,23 +261,25 @@ func (bba *BBA) handleDelayedRequest(round uint64) { } bba.reqChan <- r if err := <-r.err; err != nil { - bba.Log("action", "handleDelayedRequest", "err", err.Error()) + log.Error("comp", "bba", "action", "handleDelayedRequest", "owner", bba.owner.Address.String(), "round", bba.round, + "error", err.Error()) } } } - bba.Log("action", "handleDelayedRequest") + log.Error("comp", "bba", "action", "handleDelayedRequest", "owner", bba.owner.Address.String(), "round", bba.round) } func (bba *BBA) broadcastAuxOnceForRound() { if bba.auxBroadcasted.Value() == true { return } - bba.Log("action", "broadcastAux", "from", bba.owner.Address.String()) + log.Debug("comp", "bba", "action", "broadcastAux", "owner", bba.owner.Address.String(), "round", bba.round) for _, bin := range bba.binValueSet.toList() { if err := bba.broadcast(&AuxRequest{ Value: bin, }); err != nil { - bba.Log("action", "broadcastAux", "err", err.Error()) + log.Error("comp", "bba", "action", "broadcastAux", "owner", bba.owner.Address.String(), "round", bba.round, + "error", err.Error()) } } bba.auxBroadcasted.Set(true) diff --git a/bba/bba_internal_test.go b/bba/bba_internal_test.go index b968f87..0efe4b0 100644 --- a/bba/bba_internal_test.go +++ b/bba/bba_internal_test.go @@ -101,7 +101,6 @@ func setupHandleBvalRequestTest(t *testing.T, bvalList []*BvalRequest) (*BBA, *m broadcastedBvalSet: newBinarySet(), binValueChan: make(chan struct{}, 10), - Tracer: cleisthenes.NewMemCacheTracer(), coinGenerator: mock.NewCoinGenerator(cleisthenes.Coin(cleisthenes.One)), } return bbaInstance, broadcaster, tester, func() { @@ -298,7 +297,6 @@ func setupHandleAuxRequestTest(t *testing.T, auxList []*AuxRequest) (*BBA, *mock auxRepo: newAuxReqRepository(), broadcaster: broadcaster, tryoutAgreementChan: make(chan struct{}, 10), - Tracer: cleisthenes.NewMemCacheTracer(), coinGenerator: mock.NewCoinGenerator(cleisthenes.Coin(cleisthenes.One)), } @@ -443,7 +441,6 @@ func tryoutAgreementTestSetup() (*BBA, *bbaTester, func()) { dec: cleisthenes.NewBinaryState(), tryoutAgreementChan: make(chan struct{}, 10), advanceRoundChan: make(chan struct{}, 10), - Tracer: cleisthenes.NewMemCacheTracer(), coinGenerator: mock.NewCoinGenerator(cleisthenes.Coin(cleisthenes.One)), } return bbaInstance, newBBATester(), func() { diff --git a/log/log_wrapper.go b/log/log_wrapper.go new file mode 100644 index 0000000..4726c4f --- /dev/null +++ b/log/log_wrapper.go @@ -0,0 +1,108 @@ +package log + +import ( + "io" + "os" + "path/filepath" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" +) + +var ( + logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) +) + +func init() { + initlogger() +} + +func EnableFileLogger(enable bool, savePath string) error { + if enable { + logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) + err := initFileLogger(savePath) + if err != nil { + logger = nil + } + return err + } else { + logger = nil + return nil + } +} + +func Debug(keyvals ...interface{}) { + if logger != nil { + level.Debug(logger).Log(keyvals) + } +} + +func Info(keyvals ...interface{}) { + if logger != nil { + level.Info(logger).Log(keyvals) + } +} + +func Warn(keyvals ...interface{}) { + if logger != nil { + level.Warn(logger).Log(keyvals) + } +} + +func Error(keyvals ...interface{}) { + if logger != nil { + level.Error(logger).Log(keyvals) + } +} + +func SetToDebug() { + if logger != nil { + logger = level.NewFilter(logger, level.AllowDebug()) + } +} + +func SetToInfo() { + if logger != nil { + logger = level.NewFilter(logger, level.AllowInfo()) + } +} + +func SetToWarn() { + if logger != nil { + logger = level.NewFilter(logger, level.AllowWarn()) + } +} + +func SetToError() { + if logger != nil { + logger = level.NewFilter(logger, level.AllowError()) + } +} + +func initlogger() { + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) +} + +func initFileLogger(savePath string) error { + + if _, err := os.Stat(savePath); err != nil { + err = os.MkdirAll(filepath.Dir(savePath), 0777) + if err != nil { + return err + } + _, err = os.Create(savePath) + if err != nil { + return err + } + } + + file, err := os.OpenFile(savePath, os.O_APPEND|os.O_WRONLY, 0777) + if err == nil { + logger = log.NewLogfmtLogger(log.NewSyncWriter(io.MultiWriter(os.Stdout, file))) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) + } else { + return err + } + + return nil +} diff --git a/log/log_wrapper_test.go b/log/log_wrapper_test.go new file mode 100644 index 0000000..7b33516 --- /dev/null +++ b/log/log_wrapper_test.go @@ -0,0 +1,31 @@ +package log_test + +import ( + "os" + "path/filepath" + "testing" + + "github.com/DE-labtory/cleisthenes/log" +) + +func TestDebug(t *testing.T) { + log.SetToDebug() + log.Debug("level", "debug") +} + +func TestInfo(t *testing.T) { + log.SetToInfo() + log.Debug("level", "debug") // not printed + log.Info("level", "info") +} + +func TestEnableFileLogger(t *testing.T) { + os.RemoveAll("./test") + absPath, _ := filepath.Abs("./test/cleisthenes.log") + //defer os.RemoveAll("./test") + err := log.EnableFileLogger(true, absPath) + if err != nil { + t.Fatal(err) + } + log.Info("level", "error", "filepath", absPath) +} diff --git a/log/test/cleisthenes.log b/log/test/cleisthenes.log new file mode 100644 index 0000000..6cdde15 --- /dev/null +++ b/log/test/cleisthenes.log @@ -0,0 +1 @@ +ts=2019-06-16T14:16:42.83398Z caller=log.go:124 level=info diff --git a/rbc/rbc.go b/rbc/rbc.go index 9988956..aab291b 100644 --- a/rbc/rbc.go +++ b/rbc/rbc.go @@ -7,6 +7,8 @@ import ( "fmt" "sync" + "github.com/DE-labtory/cleisthenes/log" + "github.com/DE-labtory/cleisthenes" "github.com/DE-labtory/cleisthenes/pb" "github.com/DE-labtory/cleisthenes/rbc/merkletree" @@ -204,6 +206,9 @@ func (rbc *RBC) HandleInput(data []byte) error { rbc.contentLength.set(uint64(len(data))) + log.Info("comp", "rbc", "action", "HandleInput", "owner", rbc.owner.Address.String(), "proposer", rbc.proposer.Address.String(), + "requests", len(reqs), "content length", len(data)) + // send to me if err := rbc.handleValueRequest(rbc.proposer, reqs[0].(*ValRequest)); err != nil { return err @@ -277,6 +282,8 @@ func (rbc *RBC) handleValueRequest(sender cleisthenes.Member, req *ValRequest) e rbc.echoSent.Set(true) rbc.shareMessage(rbc.proposer, &EchoRequest{*req}) + log.Info("comp", "rbc", "action", "handleValueRequest", "owner", rbc.owner.Address.String(), "proposer", rbc.proposer.Address.String(), + "sender", sender.Address.String()) return nil } @@ -307,6 +314,8 @@ func (rbc *RBC) handleEchoRequest(sender cleisthenes.Member, req *EchoRequest) e rbc.output.set(value) } + log.Info("comp", "rbc", "action", "handleEchoRequest", "owner", rbc.owner.Address.String(), "proposer", rbc.proposer.Address.String(), + "sender", sender.Address.String()) return nil } @@ -331,7 +340,8 @@ func (rbc *RBC) handleReadyRequest(sender cleisthenes.Member, req *ReadyRequest) } rbc.output.set(value) } - + log.Info("comp", "rbc", "action", "handleReadyRequest", "owner", rbc.owner.Address.String(), "proposer", rbc.proposer.Address.String(), + "sender", sender.Address.String()) return nil } @@ -412,6 +422,8 @@ func (rbc *RBC) interpolate(rootHash []byte) ([]byte, error) { value = append(value, data...) } + log.Info("comp", "rbc", "action", "interpolate", "owner", rbc.owner.Address.String(), "proposer", rbc.proposer.Address.String(), + "shards count", len(shards)) return value[:rbc.contentLength.value()], nil } diff --git a/test/bba/node.go b/test/bba/node.go index 11a0a4a..5ab7edc 100644 --- a/test/bba/node.go +++ b/test/bba/node.go @@ -3,8 +3,8 @@ package bba import ( "github.com/DE-labtory/cleisthenes" engine "github.com/DE-labtory/cleisthenes/bba" + "github.com/DE-labtory/cleisthenes/log" "github.com/DE-labtory/cleisthenes/pb" - "github.com/DE-labtory/iLogger" ) type handler struct { @@ -49,17 +49,17 @@ func (n *Node) Run() { handler := newHandler(func(msg cleisthenes.Message) { bbaMessage, ok := msg.Message.Payload.(*pb.Message_Bba) if !ok { - iLogger.Fatalf(nil, "[handler] received message is not Message_Bba type") + log.Error("action", "handler", "msg", "received message is not Message_Bba type") } addr, err := cleisthenes.ToAddress(msg.Sender) if err != nil { - iLogger.Fatalf(nil, "[handler] failed to parse sender address: addr=%s", addr) + log.Error("action", "handler", "sender", addr, "msg", "failed to parse sender address") } n.bba.HandleMessage(n.memberMap.Member(addr), bbaMessage) }) n.server.OnConn(func(conn cleisthenes.Connection) { - iLogger.Infof(nil, "server: on connection, from: %s", n.Info()) + log.Info("action", "server", "from", n.Info(), "msg", "on connection") conn.Handle(handler) if err := conn.Start(); err != nil { @@ -109,7 +109,3 @@ func (n *Node) Info() cleisthenes.Address { func (n *Node) Result() (cleisthenes.Binary, bool) { return n.bba.Result() } - -func (n *Node) Trace() { - n.bba.Trace() -} diff --git a/test/bba/simulation_test.go b/test/bba/simulation_test.go index bd702bb..990392b 100644 --- a/test/bba/simulation_test.go +++ b/test/bba/simulation_test.go @@ -5,9 +5,9 @@ import ( "testing" "time" - "github.com/DE-labtory/cleisthenes/test/mock" + "github.com/DE-labtory/cleisthenes/log" - "github.com/DE-labtory/iLogger" + "github.com/DE-labtory/cleisthenes/test/mock" "github.com/DE-labtory/cleisthenes" "github.com/DE-labtory/cleisthenes/test/bba" @@ -43,7 +43,7 @@ func (r *simulationResult) append(out output) { func (r *simulationResult) print() { for _, out := range r.outputList { - iLogger.Infof(nil, "addr: %s, value: %v", out.addr, out.value) + log.Info("action", "result", "addr", out.addr, "value", out.value) } } @@ -174,23 +174,11 @@ func watchResult(nodeList []*bba.Node) *simulationResult { addr: node.Info(), value: result}) } } - - time.Sleep(1 * time.Second) - iLogger.Info(nil, "sleep ...") - iLogger.Info(nil, "========================trace====================") - for _, node := range nodeList { - iLogger.Info(nil, "------------------------") - iLogger.Info(nil, node.Info().String()) - iLogger.Info(nil, "------------------------") - node.Trace() - } - if len(simulationResult.outputList) == len(nodeList) { break } } - iLogger.Info(nil, "========================result====================") simulationResult.print() return simulationResult diff --git a/test/rbc/rbc_test.go b/test/rbc/rbc_test.go index 1602a0b..b931ec2 100644 --- a/test/rbc/rbc_test.go +++ b/test/rbc/rbc_test.go @@ -8,6 +8,10 @@ import ( "testing" "time" + "github.com/DE-labtory/cleisthenes/log" + + "github.com/DE-labtory/iLogger" + "github.com/DE-labtory/cleisthenes/test/util" "github.com/DE-labtory/cleisthenes" @@ -72,6 +76,8 @@ func RBCTest(proposer *Node, nodeList []*Node, data []byte) error { if value := node.Value(proposer.address); value != nil { if !bytes.Equal(value, data) { return errors.New(fmt.Sprintf("node : %s fail to reach an agreement - expected : %s, got : %s\n", node.address.String(), data, value)) + } else { + log.Info("action", "start", "owner", node.address.String()) } doneCnt++ break @@ -90,6 +96,7 @@ func Test_RBC_4NODEs(t *testing.T) { n := 4 f := 1 + iLogger.SetToDebug() nodeType := []NodeType{Normal, Normal, Normal, Normal} nodeList := setNodeList(n, f, nodeType) wg := sync.WaitGroup{}