Skip to content

Commit

Permalink
Cleanup logging. Resolved FD-600.
Browse files Browse the repository at this point in the history
  • Loading branch information
@factom-clay
factom-clay committed Aug 13, 2018
1 parent 8e8ec19 commit d84451e
Show file tree
Hide file tree
Showing 4 changed files with 96 additions and 54 deletions.
1 change: 1 addition & 0 deletions common/globals/globals.go
View file
Expand Up @@ -5,6 +5,7 @@ import "time"
var FnodeNames map[string]string = make(map[string]string) /// use by MessageTrace debug code
var Params FactomParams
var StartTime time.Time
var LastDebugLogRegEx string // used to detect if FactomParams.DebugLogRegEx was changed by the control panel

type FactomParams struct {
AckbalanceHash bool
Expand Down
71 changes: 43 additions & 28 deletions common/messages/messageTrace.go
View file
Expand Up @@ -4,6 +4,7 @@ import (
"fmt"
"os"
"regexp"
"strings"
"sync"
"time"

Expand All @@ -12,13 +13,15 @@ import (
"github.com/FactomProject/factomd/common/interfaces"
)

//TODO: Cache message hash to message string with age out...
var (
traceMutex sync.Mutex
files map[string]*os.File
enabled map[string]bool
TestRegex *regexp.Regexp
sequence int
history *([16384][32]byte) // Last 16k messages logged
h int // head of history
msgmap map[[32]byte]string
)

// Check a filename and see if logging is on for that filename
Expand All @@ -33,17 +36,25 @@ func checkFileName(name string) bool {
if globals.Params.DebugLogRegEx == "" {
return false
}
if TestRegex == nil {
// if the regex string has changed ...
if globals.Params.DebugLogRegEx != globals.LastDebugLogRegEx {

TestRegex = nil // throw away the old regex
globals.LastDebugLogRegEx = globals.Params.DebugLogRegEx
}
//strip quotes if they are included in the string
if globals.Params.DebugLogRegEx[0] == '"' || globals.Params.DebugLogRegEx[0] == '\'' {
globals.Params.DebugLogRegEx = globals.Params.DebugLogRegEx[1 : len(globals.Params.DebugLogRegEx)-1] // Trim the leading "
globals.Params.DebugLogRegEx = globals.Params.DebugLogRegEx[1 : len(globals.Params.DebugLogRegEx)-1] // Trim the "'s
}
theRegex, err := regexp.Compile(globals.Params.DebugLogRegEx)
// if we haven't compiled the regex ...
if TestRegex == nil {
theRegex, err := regexp.Compile("(?i)" + globals.Params.DebugLogRegEx) // force case insensitive
if err != nil {
panic(err)
}
files = make(map[string]*os.File)
enabled = make(map[string]bool)
enabled = make(map[string]bool) // create a clean cache of enabled files
TestRegex = theRegex
globals.LastDebugLogRegEx = globals.Params.DebugLogRegEx
}

flag, old := enabled[name]
Expand All @@ -57,6 +68,7 @@ func checkFileName(name string) bool {
// assumes traceMutex is locked already
func getTraceFile(name string) (f *os.File) {
//traceMutex.Lock() defer traceMutex.Unlock()
name = strings.ToLower(name)
if !checkFileName(name) {
return nil
}
Expand All @@ -76,9 +88,6 @@ func getTraceFile(name string) (f *os.File) {
return f
}

var history *([16384][32]byte) // Last 16k messages logged
var h int // head of history
var msgmap map[[32]byte]string

func addmsg(hash [32]byte, msg string) {
if history == nil {
Expand Down Expand Up @@ -114,16 +123,14 @@ func LogMessage(name string, note string, msg interfaces.IMsg) {
}
sequence++
seq := sequence
var t byte
var rhash, hash, mhash, msgString string
embeddedHash := ""
hash = "??????"
mhash = "??????"
rhash = "??????"
if msg == nil {
t = 0
msgString = "-nil-"
} else {
to := ""
hash := "??????"
mhash := "??????"
rhash := "??????"
t := byte(0)
msgString := "-nil-"
if msg != nil {
t = msg.Type()
msgString = msg.String()
// work around message that don't have hashes yet ...
Expand All @@ -145,26 +152,34 @@ func LogMessage(name string, note string, msg interfaces.IMsg) {
ack := msg.(*Ack)
byte := ack.GetHash().Fixed
embeddedHash = fmt.Sprintf(" EmbeddedMsg: %s", getmsg(byte()))
case constants.MISSING_MSG_RESPONSE:
mm := msg.(*MissingMsgResponse)
embeddedHash = fmt.Sprintf(" EmbeddedMsg: %s | %s", mm.MsgResponse.String(), mm.AckResponse.String())
case constants.MISSING_DATA:
md := msg.(*MissingData)
embeddedHash = fmt.Sprintf(" EmbeddedMsg: %s", getmsg(md.RequestHash.Fixed()))
//case constants.MISSING_MSG_RESPONSE:
// mm := msg.(*MissingMsgResponse)
// embeddedHash = fmt.Sprintf(" EmbeddedMsg: %s | %s", mm.MsgResponse.String(), mm.AckResponse.String())

default:
if msg.GetMsgHash() != nil {
bytes := msg.GetMsgHash().Fixed()
addmsg(bytes, msgString) // Keep message we have seen for a while
}
}

if msg.IsPeer2Peer() {
if 0 == msg.GetOrigin() {
to = "RandomPeer"
} else {
// right for sim... what about network ?
to = fmt.Sprintf("FNode%02d", msg.GetOrigin()-1)
}
} else {
//to = "broadcast"
}
}

now := time.Now().Local()

s := fmt.Sprintf("%7v %02d:%02d:%02d %-25s M-%v|R-%v|H-%v %26s[%2v]:%v%v\n", seq, now.Hour()%24, now.Minute()%60, now.Second()%60,
note, mhash, rhash, hash, constants.MessageName(byte(t)), t,
msgString, embeddedHash)
s := fmt.Sprintf("%7v %02d:%02d:%02d.%03d %-25s M-%v|R-%v|H-%v|%p %26s[%2v]:%v%v %v\n", seq, now.Hour()%24, now.Minute()%60, now.Second()%60, (now.Nanosecond()/1e6)%1000,
note, mhash, rhash, hash, msg, constants.MessageName(byte(t)), t,
msgString, embeddedHash, to)
s = addNodeNames(s)

myfile.WriteString(s)
Expand Down Expand Up @@ -223,7 +238,7 @@ func LogPrintf(name string, format string, more ...interface{}) {
}
seq := sequence
now := time.Now().Local()
s := fmt.Sprintf("%7v %02d:%02d:%02d %s\n", seq, now.Hour()%24, now.Minute()%60, now.Second()%60, fmt.Sprintf(format, more...))
s := fmt.Sprintf("%7v %02d:%02d:%02d.%03d %s\n", seq, now.Hour()%24, now.Minute()%60, now.Second()%60, (now.Nanosecond()/1e6)%1000, fmt.Sprintf(format, more...))
s = addNodeNames(s)
myfile.WriteString(s)
}
Expand Down
37 changes: 26 additions & 11 deletions engine/factomd_test.go
View file
Expand Up @@ -108,12 +108,6 @@ func TestSetupANetwork(t *testing.T) {

ranSimTest = true

runCmd := func(cmd string) {
os.Stderr.WriteString("Executing: " + cmd + "\n")
InputChan <- cmd
return
}

args := append([]string{},
"--db=Map",
"--network=LOCAL",
Expand All @@ -128,7 +122,7 @@ func TestSetupANetwork(t *testing.T) {
"--controlpanelport=37002",
"--networkport=37003",
"--startdelay=1",
//"--debuglog=.*",
"--debuglog=.*",
"--stdoutlog=out.txt",
"--stderrlog=err.txt",
"--checkheads=false",
Expand All @@ -139,6 +133,14 @@ func TestSetupANetwork(t *testing.T) {
state0.MessageTally = true
time.Sleep(3 * time.Second)

runCmd := func(cmd string) {
TimeNow(state0)
os.Stderr.WriteString("Executing: " + cmd + "\n")
os.Stdout.WriteString("Executing: " + cmd + "\n")
InputChan <- cmd
return
}

t.Log("Allocated 10 nodes")
if len(GetFnodes()) != 10 {
t.Fatal("Should have allocated 10 nodes")
Expand All @@ -154,7 +156,20 @@ func TestSetupANetwork(t *testing.T) {
runCmd("w")
WaitBlocks(state0, 1)
runCmd("g10")
WaitBlocks(state0, 1)

for {
pendingCommits := 0
for _, s := range fnodes {
pendingCommits += s.State.Commits.Len()
}
if pendingCommits == 0 {
break
}
fmt.Printf("Waiting for G10 to complete\n")
WaitMinutes(state0, 1)

}
WaitBlocks(state0, 2)
// Allocate 4 leaders
WaitForMinute(state0, 3)

Expand Down Expand Up @@ -765,9 +780,6 @@ func Test5up(t *testing.T) {
WaitMinutes(state0, 2)

runCmd("g6")
WaitBlocks(state0, 1)
WaitMinutes(state0, 1)

for {
pendingCommits := 0
for _, s := range fnodes {
Expand All @@ -780,6 +792,9 @@ func Test5up(t *testing.T) {
WaitMinutes(state0, 1)

}
WaitBlocks(state0, 1)
WaitMinutes(state0, 1)

// Allocate leaders
runCmd("1")
for i := 0; i < leaders-1; i++ {
Expand Down
41 changes: 26 additions & 15 deletions state/stateConsensus.go
View file
Expand Up @@ -8,7 +8,7 @@ import (
"errors"
"fmt"
"hash"
"sync"
"reflect"
"time"

"github.com/FactomProject/factomd/common/constants"
Expand Down Expand Up @@ -38,42 +38,51 @@ var _ = (*hash.Hash32)(nil)
// Returns true if some message was processed.
//***************************************************************

var once sync.Once
var debugExec_flag bool
func (s *State) CheckFileName(name string) bool {
return messages.CheckFileName(name)
}

func (s *State) DebugExec() (ret bool) {
once.Do(func() { debugExec_flag = globals.Params.DebugLogRegEx != "" })

//return s.FactomNodeName == "FNode0"
return debugExec_flag
return globals.Params.DebugLogRegEx != ""
}

func (s *State) LogMessage(logName string, comment string, msg interfaces.IMsg) {
if s.DebugExec() {
var dbh int
if s.LeaderPL != nil {
dbh = int(s.LeaderPL.DBHeight)
nodeName := "unknown"
minute := 0
if s != nil {
if s.LeaderPL != nil {
dbh = int(s.LeaderPL.DBHeight)
}
nodeName = s.FactomNodeName
minute = int(s.CurrentMinute)
}
messages.StateLogMessage(s.FactomNodeName, dbh, int(s.CurrentMinute), logName, comment, msg)
messages.StateLogMessage(nodeName, dbh, minute, logName, comment, msg)
}
}

func (s *State) LogPrintf(logName string, format string, more ...interface{}) {
if s.DebugExec() {
var dbh int
if s.LeaderPL != nil {
dbh = int(s.LeaderPL.DBHeight)
nodeName := "unknown"
minute := 0
if s != nil {
if s.LeaderPL != nil {
dbh = int(s.LeaderPL.DBHeight)
}
nodeName = s.FactomNodeName
minute = int(s.CurrentMinute)
}
messages.StateLogPrintf(s.FactomNodeName, dbh, int(s.CurrentMinute), logName, format, more...)
messages.StateLogPrintf(nodeName, dbh, minute, logName, format, more...)
}
}
func (s *State) executeMsg(vm *VM, msg interfaces.IMsg) (ret bool) {

if msg.GetHash() == nil {
if msg.GetHash() == nil || reflect.ValueOf(msg.GetHash()).IsNil() {
s.LogMessage("badMsgs", "Nil hash in executeMsg", msg)
return false
}

preExecuteMsgTime := time.Now()
_, ok := s.Replay.Valid(constants.INTERNAL_REPLAY, msg.GetRepeatHash().Fixed(), msg.GetTimestamp(), s.GetTimestamp())
if !ok {
Expand Down Expand Up @@ -1295,6 +1304,8 @@ func (s *State) LeaderExecuteRevealEntry(m interfaces.IMsg) {
func (s *State) ProcessAddServer(dbheight uint32, addServerMsg interfaces.IMsg) bool {
as, ok := addServerMsg.(*messages.AddServerMsg)
if ok && !ProcessIdentityToAdminBlock(s, as.ServerChainID, as.ServerType) {
s.LogMessage("executeMsg", "Failed to process", addServerMsg)

//s.AddStatus(fmt.Sprintf("Failed to add %x as server type %d", as.ServerChainID.Bytes()[2:5], as.ServerType))
return false
}
Expand Down

0 comments on commit d84451e

Please sign in to comment.