예제 #1
0
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)
}
예제 #2
0
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)
	}
}
예제 #3
0
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)
}
예제 #4
0
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)
}
예제 #5
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")
}
예제 #6
0
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)
	}
}
예제 #7
0
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")
	}
}