func (s *RelayTestSuite) TestLogLevel(t *C) {
r := s.relay
l := s.logger
r.LogLevelChan() <- proto.LOG_DEBUG
l.Debug("debug")
l.Info("info")
l.Warn("warning")
l.Error("error")
l.Fatal("fatal")
got := test.WaitLog(s.recvChan, 5)
expect := []proto.LogEntry{
{Ts: test.Ts, Level: proto.LOG_DEBUG, Service: "test", Msg: "debug"},
{Ts: test.Ts, Level: proto.LOG_INFO, Service: "test", Msg: "info"},
{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "test", Msg: "warning"},
{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: "error"},
{Ts: test.Ts, Level: proto.LOG_CRITICAL, Service: "test", Msg: "fatal"},
}
t.Check(got, DeepEquals, expect)
r.LogLevelChan() <- proto.LOG_WARNING
l.Debug("debug")
l.Info("info")
l.Warn("warning")
l.Error("error")
l.Fatal("fatal")
got = test.WaitLog(s.recvChan, 3)
expect = []proto.LogEntry{
{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "test", Msg: "warning"},
{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: "error"},
{Ts: test.Ts, Level: proto.LOG_CRITICAL, Service: "test", Msg: "fatal"},
}
t.Check(got, DeepEquals, expect)
}
func (s *RelayTestSuite) TestOfflineBuffering(t *C) {
l := s.logger
// We're going to cause the relay's client Recv() to get an error
// which will cause the relay to connect again. We block this 2nd
// connect by blocking this chan. End result: relay remains offline.
s.client.SetConnectChan(s.connectChan)
doneChan := make(chan bool, 1)
go func() {
s.client.RecvError <- io.EOF
doneChan <- true
}()
// Wait for the relay to recv the recv error.
<-doneChan
// Wait for the relay to call client.Connect().
<-s.connectChan
// Double-check that relay is offline.
if !test.WaitStatus(1, s.relay, "ws", "Disconnected") {
t.Fatal("Relay connects")
}
// Relay is offline and trying to connect again in another goroutine.
// These entries should therefore not be sent. There's a minor race
// condition: when relay goes offline, it sends an internal log entry.
// Sometimes we get that here (Service="log") and sometimes not
// (len(got)==0). Either condition is correct for this test.
l.Error("err1")
l.Error("err2")
got := test.WaitLog(s.recvChan, 0)
if len(got) > 0 && got[0].Service != "log" {
t.Errorf("Log entries are not sent while offline: %+v", got)
}
// Unblock the relay's connect attempt.
s.connectChan <- true
if !test.WaitStatus(1, s.relay, "ws", "Connected") {
t.Fatal("Relay connects")
}
// Wait for the relay resend what it had ^ buffered.
got = test.WaitLog(s.recvChan, 3)
expect := []proto.LogEntry{
{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: "connected: false"},
{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: "err1"},
{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: "err2"},
{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: "connected: true"},
}
if same, diff := test.IsDeeply(got, expect); !same {
t.Error(diff)
}
}
func (s *RelayTestSuite) TearDownTest(t *C) {
// Drain the log so one test doesn't affect another.
_ = test.WaitLog(s.recvChan, 0)
s.client.SetConnectChan(nil)
}
func (s *RelayTestSuite) SetUpTest(t *C) {
s.relay.LogLevelChan() <- proto.LOG_INFO
// Drain the log so one test doesn't affect another.
_ = test.WaitLog(s.recvChan, 0)
}
func (s *ManagerTestSuite) TestLogService(t *C) {
config := &log.Config{
File: s.logFile,
Level: "info",
}
pct.Basedir.WriteConfig("log", config)
m := log.NewManager(s.client, s.logChan)
err := m.Start()
t.Assert(err, IsNil)
relay := m.Relay()
t.Assert(relay, NotNil)
logger := pct.NewLogger(relay.LogChan(), "log-svc-test")
logger.Info("i'm a log entry")
// Log entry should be sent to API.
got := test.WaitLog(s.recvChan, 3)
if len(got) == 0 {
t.Fatal("No log entries")
}
var gotLog proto.LogEntry
for _, l := range got {
if l.Service == "log-svc-test" {
gotLog = l
break
}
}
t.Assert(gotLog, NotNil)
expectLog := proto.LogEntry{Ts: test.Ts, Level: proto.LOG_INFO, Service: "log-svc-test", Msg: "i'm a log entry"}
if same, diff := test.IsDeeply(gotLog, expectLog); !same {
t.Logf("%+v", got)
t.Error(diff)
}
// Since there's a log file, entry should be written to it too.
size, _ := test.FileSize(s.logFile)
test.WaitFileSize(s.logFile, size)
var content []byte
content, err = ioutil.ReadFile(s.logFile)
t.Assert(err, IsNil)
if !strings.Contains(string(content), "i'm a log entry") {
t.Error("Writes log entry to log file, got\n", string(content))
}
// Can't stop log service, but Stop() should work and not return error.
err = m.Stop()
t.Assert(err, IsNil)
/**
* Change log level and file
*/
newLogFile := s.logFile + "-2"
defer os.Remove(newLogFile)
config = &log.Config{
File: newLogFile,
Level: "warning",
}
configData, err := json.Marshal(config)
t.Assert(err, IsNil)
cmd := &proto.Cmd{
User: "******",
Service: "log",
Cmd: "SetConfig",
Data: configData,
}
gotReply := m.Handle(cmd)
expectReply := cmd.Reply(config)
if same, diff := test.IsDeeply(gotReply, expectReply); !same {
t.Logf("%+v", gotReply)
t.Error(diff)
}
// Log entry should NOT be sent to API if log level was really changed.
logger.Info("i'm lost")
got = test.WaitLog(s.recvChan, 3)
if len(got) != 0 {
t.Logf("%+v", got)
t.Error("Log level changed dynamically")
}
logger.Warn("blah")
got = test.WaitLog(s.recvChan, 3)
gotLog = proto.LogEntry{}
for _, l := range got {
if l.Service == "log-svc-test" {
gotLog = l
break
}
}
expectLog = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log-svc-test", Msg: "blah"}
if same, diff := test.IsDeeply(gotLog, expectLog); !same {
t.Logf("%+v", got)
t.Error(diff)
}
// Entry should be written to new log file if it was really changed.
size, _ = test.FileSize(newLogFile)
test.WaitFileSize(newLogFile, size)
content, err = ioutil.ReadFile(newLogFile)
t.Assert(err, IsNil)
if !strings.Contains(string(content), "blah") {
t.Error("Log file changed dynamically, got\n", string(content))
}
// Verify new log config on disk.
data, err := ioutil.ReadFile(pct.Basedir.ConfigFile("log"))
t.Assert(err, IsNil)
gotConfig := &log.Config{}
if err := json.Unmarshal(data, gotConfig); err != nil {
t.Fatal(err)
}
if same, diff := test.IsDeeply(gotConfig, config); !same {
test.Dump(gotConfig)
t.Error(diff)
}
/**
* GetConfig
*/
cmd = &proto.Cmd{
User: "******",
Service: "log",
Cmd: "GetConfig",
}
reply := m.Handle(cmd)
t.Assert(reply.Error, Equals, "")
t.Assert(reply.Data, NotNil)
gotConfigRes := []proto.AgentConfig{}
if err := json.Unmarshal(reply.Data, &gotConfigRes); err != nil {
t.Fatal(err)
}
expectConfigRes := []proto.AgentConfig{
{
InternalService: "log",
Config: string(configData),
Running: true,
},
}
if same, diff := test.IsDeeply(gotConfigRes, expectConfigRes); !same {
test.Dump(gotConfigRes)
t.Error(diff)
}
/**
* Status (internal status of log and relay)
*/
status := m.Status()
t.Check(status["ws"], Equals, "Connected")
t.Check(status["log-file"], Equals, newLogFile)
t.Check(status["log-level"], Equals, "warning")
}
func (s *RelayTestSuite) TestOfflineBufferOverflow(t *C) {
// Same magic as in TestOfflineBuffering to force relay offline.
l := s.logger
s.client.SetConnectChan(s.connectChan)
doneChan := make(chan bool, 1)
go func() {
s.client.RecvError <- io.EOF
doneChan <- true
}()
<-doneChan
<-s.connectChan
// Relay is offline, trying to connect.
// Overflow the first buffer but not the second. We should get all
// log entries back.
for i := 0; i < log.BUFFER_SIZE+1; i++ {
l.Error(fmt.Sprintf("a:%d", i))
}
if !test.WaitStatus(3, s.relay, "log-buf1", fmt.Sprintf("%d", log.BUFFER_SIZE)) {
t.Error("First buffer full")
}
// Unblock the relay's connect attempt.
s.connectChan <- true
if !test.WaitStatus(1, s.relay, "ws", "Connected") {
t.Fatal("Relay connects")
}
// Wait for the relay resend what it had ^ buffered.
// +2 for "connected: false" and "connected: true".
got := test.WaitLog(s.recvChan, log.BUFFER_SIZE+1+2)
expect := make([]proto.LogEntry, log.BUFFER_SIZE+1+2)
expect[0] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: "connected: false"}
for i, n := 0, 1; i < log.BUFFER_SIZE+1; i, n = i+1, n+1 {
expect[n] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: fmt.Sprintf("a:%d", i)}
}
expect[log.BUFFER_SIZE+1+1] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: "connected: true"}
if same, diff := test.IsDeeply(got, expect); !same {
t.Error(diff)
}
if !test.WaitStatus(3, s.relay, "log-buf2", "0") {
status := s.relay.Status()
t.Log(status)
t.Fatal("1st buf empty")
}
expect = []proto.LogEntry{}
// Force the relay offline again, then overflow both buffers. We should get
// the first buffer, an entry about lost entries (from the second buffer),
// then the second buffer with the very latest.
go func() {
s.client.RecvError <- io.EOF
doneChan <- true
}()
<-doneChan
<-s.connectChan
// Relay is offline, trying to connect.
overflow := 3
for i := 0; i < (log.BUFFER_SIZE*2)+overflow; i++ {
l.Error(fmt.Sprintf("b:%d", i))
}
if !test.WaitStatus(3, s.relay, "log-buf2", fmt.Sprintf("%d", overflow+1)) {
status := s.relay.Status()
t.Log(status)
t.Fatal("2nd buf full")
}
// Unblock the relay's connect attempt.
s.connectChan <- true
if !test.WaitStatus(1, s.relay, "ws", "Connected") {
t.Fatal("Relay connects")
}
// +3 for "connected: false", "Lost N entries", and "connected: true".
got = test.WaitLog(s.recvChan, log.BUFFER_SIZE+overflow+3)
expect = make([]proto.LogEntry, log.BUFFER_SIZE+overflow+3)
expect[0] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: "connected: false"}
n := 1
// If buf size is 10, then we should "Lost connection", get 0-8, a "Lost 10" message for 9-18, then 19-22.
/**
* /10, first buffer
* 1 Lost connection
* 2 entry 0
* 3 entry 1
* 4 entry 2
* 5 entry 3
* 6 entry 4
* 7 entry 5
* 8 entry 6
* 9 entry 7
* 10 entry 8
* Entry 9-18 into second buffer, entry 19 causes the overflow and reset:
* /10, second buffer
* 1 entry 19
* 2 entry 20
* 3 entry 21
* 4 entry 22
*/
for i := 0; i < log.BUFFER_SIZE-1; i++ {
expect[n] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: fmt.Sprintf("b:%d", i)}
n++
}
expect[n] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: fmt.Sprintf("Lost %d log entries", log.BUFFER_SIZE)}
n++
for i, j := log.BUFFER_SIZE, log.BUFFER_SIZE*2-1; i < log.BUFFER_SIZE+overflow+1; i, j = i+1, j+1 {
expect[n] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_ERROR, Service: "test", Msg: fmt.Sprintf("b:%d", j)}
n++
}
expect[log.BUFFER_SIZE+overflow+2] = proto.LogEntry{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "log", Msg: "connected: true"}
if same, diff := test.IsDeeply(got, expect); !same {
// @todo: this test may still be unstable
n := len(got)
if len(expect) > n {
n = len(expect)
}
for i := 0; i < n; i++ {
var gotL proto.LogEntry
var expectL proto.LogEntry
if i < len(got) {
gotL = got[i]
}
if i < len(expect) {
expectL = expect[i]
}
t.Logf("%+v %+v\n", gotL, expectL)
}
t.Error(diff)
}
}
func (s *RelayTestSuite) TestLogFile(t *C) {
/**
* This test is going to be a real pain in the ass because it writes/reads
* disk and the disk can be surprisingly slow on a test box. On top of that,
* there's concurrency so we also have to wait for the CPU to run goroutines.
*/
r := s.relay
l := s.logger
// Online log should work without file log.
l.Warn("It's a trap!")
got := test.WaitLog(s.recvChan, 1)
expect := []proto.LogEntry{
{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "test", Msg: "It's a trap!"},
}
t.Check(got, DeepEquals, expect)
log, err := ioutil.ReadFile(s.logFile)
if !os.IsNotExist(err) {
t.Error("We haven't enabled the log file yet, so it shouldn't exist yet")
}
// Enable the log file.
r.LogFileChan() <- s.logFile
// Online log should work with the file log.
l.Warn("It's another trap!")
got = test.WaitLog(s.recvChan, 1)
expect = []proto.LogEntry{
{Ts: test.Ts, Level: proto.LOG_WARNING, Service: "test", Msg: "It's another trap!"},
}
t.Check(got, DeepEquals, expect)
// Log file should exist.
size, _ := test.FileSize(s.logFile)
test.WaitFileSize(s.logFile, size)
log, err = ioutil.ReadFile(s.logFile)
if err != nil {
t.Fatalf("Log file should exist: %s", err)
}
if !strings.Contains(string(log), "It's another trap!") {
t.Error("Log file contains entry after being enabled, got\n", string(log))
}
if strings.Contains(string(log), "It's a trap!") {
t.Error("Log file does not contain entry before being enabled, got\n", string(log))
}
l.Debug("Hello")
if strings.Contains(string(log), "Hello") {
t.Error("Log file should respect the log level")
}
// We should be able to change the log file.
newLogFile := s.logFile + "-new"
defer func() { os.Remove(newLogFile) }()
r.LogFileChan() <- newLogFile
l.Warn("Foo")
size, _ = test.FileSize(newLogFile)
test.WaitFileSize(newLogFile, size)
log, err = ioutil.ReadFile(newLogFile)
if err != nil {
t.Errorf("New log file should exist: %s", err)
return
}
if !strings.Contains(string(log), "Foo") {
t.Error("New log file contains only the new log entry, got\n", string(log))
}
if strings.Contains(string(log), "It's another trap!") {
t.Error("New log file should contain only the new log entry")
}
log, err = ioutil.ReadFile(s.logFile)
if err != nil {
t.Errorf("Old log file should still exist: %s", err)
return
}
if strings.Contains(string(log), "Foo") {
t.Error("Old log file should not contain the new log entry")
}
}