func (s *LogsSuite) TestPruneLogsByTime(c *gc.C) {
dbLogger := state.NewDbLogger(s.State, names.NewMachineTag("22"))
defer dbLogger.Close()
log := func(t time.Time, msg string) {
err := dbLogger.Log(t, "module", "loc", loggo.INFO, msg)
c.Assert(err, jc.ErrorIsNil)
}
now := time.Now()
maxLogTime := now.Add(-time.Minute)
log(now, "keep")
log(maxLogTime.Add(time.Second), "keep")
log(maxLogTime, "keep")
log(maxLogTime.Add(-time.Second), "prune")
log(maxLogTime.Add(-(2 * time.Second)), "prune")
noPruneMB := 100
err := state.PruneLogs(s.State, maxLogTime, noPruneMB)
c.Assert(err, jc.ErrorIsNil)
// After pruning there should just be 3 "keep" messages left.
var docs []bson.M
err = s.logsColl.Find(nil).All(&docs)
c.Assert(err, jc.ErrorIsNil)
c.Assert(docs, gc.HasLen, 3)
for _, doc := range docs {
c.Assert(doc["x"], gc.Equals, "keep")
}
}
func (s *LogsSuite) TestDbLogger(c *gc.C) {
logger := state.NewDbLogger(s.State, names.NewMachineTag("22"))
defer logger.Close()
t0 := time.Now().Truncate(time.Millisecond) // MongoDB only stores timestamps with ms precision.
logger.Log(t0, "some.where", "foo.go:99", loggo.INFO, "all is well")
t1 := t0.Add(time.Second)
logger.Log(t1, "else.where", "bar.go:42", loggo.ERROR, "oh noes")
var docs []bson.M
err := s.logsColl.Find(nil).Sort("t").All(&docs)
c.Assert(err, jc.ErrorIsNil)
c.Assert(docs, gc.HasLen, 2)
c.Assert(docs[0]["t"], gc.Equals, t0)
c.Assert(docs[0]["e"], gc.Equals, s.State.EnvironUUID())
c.Assert(docs[0]["n"], gc.Equals, "machine-22")
c.Assert(docs[0]["m"], gc.Equals, "some.where")
c.Assert(docs[0]["l"], gc.Equals, "foo.go:99")
c.Assert(docs[0]["v"], gc.Equals, int(loggo.INFO))
c.Assert(docs[0]["x"], gc.Equals, "all is well")
c.Assert(docs[1]["t"], gc.Equals, t1)
c.Assert(docs[1]["e"], gc.Equals, s.State.EnvironUUID())
c.Assert(docs[1]["n"], gc.Equals, "machine-22")
c.Assert(docs[1]["m"], gc.Equals, "else.where")
c.Assert(docs[1]["l"], gc.Equals, "bar.go:42")
c.Assert(docs[1]["v"], gc.Equals, int(loggo.ERROR))
c.Assert(docs[1]["x"], gc.Equals, "oh noes")
}
// ServeHTTP implements the http.Handler interface.
func (h *logSinkHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
server := websocket.Server{
Handler: func(socket *websocket.Conn) {
defer socket.Close()
st, entity, err := h.ctxt.stateForRequestAuthenticatedAgent(req)
if err != nil {
h.sendError(socket, req, err)
return
}
tag := entity.Tag()
// Note that this endpoint is agent-only. Thus the only
// callers will necessarily provide their Juju version.
//
// This would be a problem if non-Juju clients (e.g. the
// GUI) could use this endpoint since we require that the
// *Juju* version be provided as part of the request. Any
// attempt to open this endpoint to broader access must
// address this caveat appropriately.
ver, err := jujuClientVersionFromReq(req)
if err != nil {
h.sendError(socket, req, err)
return
}
filePrefix := st.ModelUUID() + " " + tag.String() + ":"
dbLogger := state.NewDbLogger(st, tag, ver)
defer dbLogger.Close()
// If we get to here, no more errors to report, so we report a nil
// error. This way the first line of the socket is always a json
// formatted simple error.
h.sendError(socket, req, nil)
logCh := h.receiveLogs(socket)
for {
select {
case <-h.ctxt.stop():
return
case m := <-logCh:
fileErr := h.logToFile(filePrefix, m)
if fileErr != nil {
logger.Errorf("logging to logsink.log failed: %v", fileErr)
}
level, _ := loggo.ParseLevel(m.Level)
dbErr := dbLogger.Log(m.Time, m.Module, m.Location, level, m.Message)
if dbErr != nil {
logger.Errorf("logging to DB failed: %v", err)
}
if fileErr != nil || dbErr != nil {
return
}
}
}
},
}
server.ServeHTTP(w, req)
}
func (s *suite) addLogs(c *gc.C, t0 time.Time, text string, count int) {
dbLogger := state.NewDbLogger(s.State, names.NewMachineTag("0"), version.Current)
defer dbLogger.Close()
for offset := 0; offset < count; offset++ {
t := t0.Add(-time.Duration(offset) * time.Second)
dbLogger.Log(t, "some.module", "foo.go:42", loggo.INFO, text)
}
}
func (s *LogsSuite) generateLogs(c *gc.C, st *state.State, now time.Time, count int) {
dbLogger := state.NewDbLogger(st, names.NewMachineTag("0"))
defer dbLogger.Close()
for i := 0; i < count; i++ {
ts := now.Add(-time.Duration(i) * time.Second)
err := dbLogger.Log(ts, "module", "loc", loggo.INFO, "message")
c.Assert(err, jc.ErrorIsNil)
}
}
// ServeHTTP implements the http.Handler interface.
func (h *logSinkHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
server := websocket.Server{
Handler: func(socket *websocket.Conn) {
defer socket.Close()
// Validate before authenticate because the authentication is
// dependent on the state connection that is determined during the
// validation.
stateWrapper, err := h.validateEnvironUUID(req)
if err != nil {
if errErr := h.sendError(socket, err); errErr != nil {
// Log at DEBUG so that in a standard environment
// logs cant't fill up with auth errors for
// unauthenticated connections.
logger.Debugf("error sending logsink error: %v", errErr)
}
return
}
defer stateWrapper.cleanup()
tag, err := stateWrapper.authenticateAgent(req)
if err != nil {
if errErr := h.sendError(socket, errors.Errorf("auth failed: %v", err)); errErr != nil {
// DEBUG used as above.
logger.Debugf("error sending logsink error: %v", errErr)
}
return
}
// If we get to here, no more errors to report, so we report a nil
// error. This way the first line of the socket is always a json
// formatted simple error.
if err := h.sendError(socket, nil); err != nil {
logger.Errorf("failed to send nil error at start of connection")
return
}
dbLogger := state.NewDbLogger(stateWrapper.state, tag)
defer dbLogger.Close()
var m LogMessage
for {
if err := websocket.JSON.Receive(socket, &m); err != nil {
if err != io.EOF {
logger.Errorf("error while receiving logs: %v", err)
}
break
}
if err := dbLogger.Log(m.Time, m.Module, m.Location, m.Level, m.Message); err != nil {
logger.Errorf("logging to DB failed: %v", err)
break
}
}
}}
server.ServeHTTP(w, req)
}
func (s *dumpLogsCommandSuite) TestRun(c *gc.C) {
// Create a controller machine and an agent for it.
m, password := s.Factory.MakeMachineReturningPassword(c, &factory.MachineParams{
Jobs: []state.MachineJob{state.JobManageModel},
Nonce: agent.BootstrapNonce,
})
err := m.SetMongoPassword(password)
c.Assert(err, jc.ErrorIsNil)
s.PrimeStateAgent(c, m.Tag(), password)
// Create multiple environments and add some logs for each.
st1 := s.Factory.MakeModel(c, nil)
defer st1.Close()
st2 := s.Factory.MakeModel(c, nil)
defer st2.Close()
states := []*state.State{s.State, st1, st2}
t := time.Date(2015, 11, 4, 3, 2, 1, 0, time.UTC)
for _, st := range states {
w := state.NewDbLogger(st, names.NewMachineTag("42"))
defer w.Close()
for i := 0; i < 3; i++ {
err := w.Log(t, "module", "location", loggo.INFO, fmt.Sprintf("%d", i))
c.Assert(err, jc.ErrorIsNil)
}
}
// Run the juju-dumplogs command
command := dumplogs.NewCommand()
context, err := testing.RunCommand(c, command, "--data-dir", s.DataDir())
c.Assert(err, jc.ErrorIsNil)
// Check the log file for each environment
expectedLog := "machine-42: 2015-11-04 03:02:01 INFO module %d"
for _, st := range states {
logName := context.AbsPath(fmt.Sprintf("%s.log", st.ModelUUID()))
logFile, err := os.Open(logName)
c.Assert(err, jc.ErrorIsNil)
scanner := bufio.NewScanner(logFile)
for i := 0; scanner.Scan(); i++ {
c.Assert(scanner.Text(), gc.Equals, fmt.Sprintf(expectedLog, i))
}
c.Assert(scanner.Err(), jc.ErrorIsNil)
}
}
// ServeHTTP implements the http.Handler interface.
func (h *logSinkHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
server := websocket.Server{
Handler: func(socket *websocket.Conn) {
defer socket.Close()
st, entity, err := h.ctxt.stateForRequestAuthenticatedAgent(req)
if err != nil {
h.sendError(socket, req, err)
return
}
tag := entity.Tag()
// If we get to here, no more errors to report, so we report a nil
// error. This way the first line of the socket is always a json
// formatted simple error.
h.sendError(socket, req, nil)
filePrefix := st.EnvironUUID() + " " + tag.String() + ":"
dbLogger := state.NewDbLogger(st, tag)
defer dbLogger.Close()
m := new(params.LogRecord)
for {
if err := websocket.JSON.Receive(socket, m); err != nil {
if err != io.EOF {
logger.Errorf("error while receiving logs: %v", err)
}
break
}
fileErr := h.logToFile(filePrefix, m)
if fileErr != nil {
logger.Errorf("logging to logsink.log failed: %v", fileErr)
}
dbErr := dbLogger.Log(m.Time, m.Module, m.Location, m.Level, m.Message)
if dbErr != nil {
logger.Errorf("logging to DB failed: %v", err)
}
if fileErr != nil || dbErr != nil {
break
}
}
}}
server.ServeHTTP(w, req)
}
// ServeHTTP implements the http.Handler interface.
func (h *logSinkHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
server := websocket.Server{
Handler: func(socket *websocket.Conn) {
defer socket.Close()
st, entity, err := h.ctxt.stateForRequestAuthenticatedAgent(req)
if err != nil {
h.sendError(socket, req, err)
return
}
tag := entity.Tag()
filePrefix := st.ModelUUID() + " " + tag.String() + ":"
dbLogger := state.NewDbLogger(st, tag)
defer dbLogger.Close()
// If we get to here, no more errors to report, so we report a nil
// error. This way the first line of the socket is always a json
// formatted simple error.
h.sendError(socket, req, nil)
logCh := h.receiveLogs(socket)
for {
select {
case <-h.ctxt.stop():
return
case m := <-logCh:
fileErr := h.logToFile(filePrefix, m)
if fileErr != nil {
logger.Errorf("logging to logsink.log failed: %v", fileErr)
}
dbErr := dbLogger.Log(m.Time, m.Module, m.Location, m.Level, m.Message)
if dbErr != nil {
logger.Errorf("logging to DB failed: %v", err)
}
if fileErr != nil || dbErr != nil {
return
}
}
}
},
}
server.ServeHTTP(w, req)
}
func (s *debugLogDbSuite) TestLogsAPI(c *gc.C) {
dbLogger := state.NewDbLogger(s.State, names.NewMachineTag("99"))
defer dbLogger.Close()
t := time.Date(2015, 6, 23, 13, 8, 49, 0, time.UTC)
dbLogger.Log(t, "juju.foo", "code.go:42", loggo.INFO, "all is well")
dbLogger.Log(t.Add(time.Second), "juju.bar", "go.go:99", loggo.ERROR, "no it isn't")
lines := make(chan string)
go func(numLines int) {
client := s.APIState.Client()
reader, err := client.WatchDebugLog(api.DebugLogParams{})
c.Assert(err, jc.ErrorIsNil)
defer reader.Close()
bufReader := bufio.NewReader(reader)
for n := 0; n < numLines; n++ {
line, err := bufReader.ReadString('\n')
c.Assert(err, jc.ErrorIsNil)
lines <- line
}
}(3)
assertLine := func(expected string) {
select {
case actual := <-lines:
c.Assert(actual, gc.Equals, expected)
case <-time.After(coretesting.LongWait):
c.Fatal("timed out waiting for log line")
}
}
// Read the 2 lines that are in the logs collection.
assertLine("machine-99: 2015-06-23 13:08:49 INFO juju.foo code.go:42 all is well\n")
assertLine("machine-99: 2015-06-23 13:08:50 ERROR juju.bar go.go:99 no it isn't\n")
// Now write and observe another log. This should be read from the oplog.
dbLogger.Log(t.Add(2*time.Second), "ju.jitsu", "no.go:3", loggo.WARNING, "beep beep")
assertLine("machine-99: 2015-06-23 13:08:51 WARNING ju.jitsu no.go:3 beep beep\n")
}