github.com/mattyw/juju@v0.0.0-20140610034352-732aecd63861/state/apiserver/debuglog_test.go (about)

     1  // Copyright 2014 Canonical Ltd.
     2  // Licensed under the AGPLv3, see LICENCE file for details.
     3  
     4  package apiserver_test
     5  
     6  import (
     7  	"bufio"
     8  	"crypto/tls"
     9  	"crypto/x509"
    10  	"encoding/json"
    11  	"fmt"
    12  	"io"
    13  	"net/http"
    14  	"net/url"
    15  	"os"
    16  	"path/filepath"
    17  	"strings"
    18  
    19  	"code.google.com/p/go.net/websocket"
    20  	jc "github.com/juju/testing/checkers"
    21  	"github.com/juju/utils"
    22  	gc "launchpad.net/gocheck"
    23  
    24  	"github.com/juju/juju/state/api/params"
    25  	"github.com/juju/juju/testing"
    26  )
    27  
    28  type debugLogSuite struct {
    29  	authHttpSuite
    30  	logFile *os.File
    31  	last    int
    32  }
    33  
    34  var _ = gc.Suite(&debugLogSuite{})
    35  
    36  func (s *debugLogSuite) TestWithHTTP(c *gc.C) {
    37  	uri := s.logURL(c, "http", nil).String()
    38  	_, err := s.sendRequest(c, "", "", "GET", uri, "", nil)
    39  	c.Assert(err, gc.ErrorMatches, `.*malformed HTTP response.*`)
    40  }
    41  
    42  func (s *debugLogSuite) TestWithHTTPS(c *gc.C) {
    43  	uri := s.logURL(c, "https", nil).String()
    44  	response, err := s.sendRequest(c, "", "", "GET", uri, "", nil)
    45  	c.Assert(err, gc.IsNil)
    46  	c.Assert(response.StatusCode, gc.Equals, http.StatusBadRequest)
    47  }
    48  
    49  func (s *debugLogSuite) TestNoAuth(c *gc.C) {
    50  	conn, err := s.dialWebsocketInternal(c, nil, nil)
    51  	c.Assert(err, gc.IsNil)
    52  	defer conn.Close()
    53  	reader := bufio.NewReader(conn)
    54  
    55  	s.assertErrorResponse(c, reader, "auth failed: invalid request format")
    56  	s.assertWebsocketClosed(c, reader)
    57  }
    58  
    59  func (s *debugLogSuite) TestNoLogfile(c *gc.C) {
    60  	reader := s.openWebsocket(c, nil)
    61  	s.assertErrorResponse(c, reader, "cannot open log file: .*: no such file or directory")
    62  	s.assertWebsocketClosed(c, reader)
    63  }
    64  
    65  func (s *debugLogSuite) TestBadParams(c *gc.C) {
    66  	reader := s.openWebsocket(c, url.Values{"maxLines": {"foo"}})
    67  	s.assertErrorResponse(c, reader, `maxLines value "foo" is not a valid unsigned number`)
    68  	s.assertWebsocketClosed(c, reader)
    69  }
    70  
    71  func (s *debugLogSuite) assertLogReader(c *gc.C, reader *bufio.Reader) {
    72  	s.assertLogFollowing(c, reader)
    73  	s.writeLogLines(c, logLineCount)
    74  
    75  	linesRead := s.readLogLines(c, reader, logLineCount)
    76  	c.Assert(linesRead, jc.DeepEquals, logLines)
    77  }
    78  
    79  func (s *debugLogSuite) TestServesLog(c *gc.C) {
    80  	s.ensureLogFile(c)
    81  	reader := s.openWebsocket(c, nil)
    82  	s.assertLogReader(c, reader)
    83  }
    84  
    85  func (s *debugLogSuite) TestReadFromTopLevelPath(c *gc.C) {
    86  	// Backwards compatibility check, that we can read the log file at
    87  	// https://host:port/log
    88  	s.ensureLogFile(c)
    89  	reader := s.openWebsocketCustomPath(c, "/log")
    90  	s.assertLogReader(c, reader)
    91  }
    92  
    93  func (s *debugLogSuite) TestReadFromEnvUUIDPath(c *gc.C) {
    94  	// Check that we can read the log at https://host:port/ENVUUID/log
    95  	environ, err := s.State.Environment()
    96  	c.Assert(err, gc.IsNil)
    97  	s.ensureLogFile(c)
    98  	reader := s.openWebsocketCustomPath(c, fmt.Sprintf("/environment/%s/log", environ.UUID()))
    99  	s.assertLogReader(c, reader)
   100  }
   101  
   102  func (s *debugLogSuite) TestReadRejectsWrongEnvUUIDPath(c *gc.C) {
   103  	// Check that we cannot upload charms to https://host:port/BADENVUUID/charms
   104  	s.ensureLogFile(c)
   105  	reader := s.openWebsocketCustomPath(c, "/environment/dead-beef-123456/log")
   106  	s.assertErrorResponse(c, reader, `unknown environment: "dead-beef-123456"`)
   107  	s.assertWebsocketClosed(c, reader)
   108  }
   109  
   110  func (s *debugLogSuite) TestReadsFromEnd(c *gc.C) {
   111  	s.writeLogLines(c, 10)
   112  
   113  	reader := s.openWebsocket(c, nil)
   114  	s.assertLogFollowing(c, reader)
   115  	s.writeLogLines(c, logLineCount)
   116  
   117  	linesRead := s.readLogLines(c, reader, logLineCount-10)
   118  	c.Assert(linesRead, jc.DeepEquals, logLines[10:])
   119  }
   120  
   121  func (s *debugLogSuite) TestReplayFromStart(c *gc.C) {
   122  	s.writeLogLines(c, 10)
   123  
   124  	reader := s.openWebsocket(c, url.Values{"replay": {"true"}})
   125  	s.assertLogFollowing(c, reader)
   126  	s.writeLogLines(c, logLineCount)
   127  
   128  	linesRead := s.readLogLines(c, reader, logLineCount)
   129  	c.Assert(linesRead, jc.DeepEquals, logLines)
   130  }
   131  
   132  func (s *debugLogSuite) TestBacklog(c *gc.C) {
   133  	s.writeLogLines(c, 10)
   134  
   135  	reader := s.openWebsocket(c, url.Values{"backlog": {"5"}})
   136  	s.assertLogFollowing(c, reader)
   137  	s.writeLogLines(c, logLineCount)
   138  
   139  	linesRead := s.readLogLines(c, reader, logLineCount-5)
   140  	c.Assert(linesRead, jc.DeepEquals, logLines[5:])
   141  }
   142  
   143  func (s *debugLogSuite) TestMaxLines(c *gc.C) {
   144  	s.writeLogLines(c, 10)
   145  
   146  	reader := s.openWebsocket(c, url.Values{"maxLines": {"10"}})
   147  	s.assertLogFollowing(c, reader)
   148  	s.writeLogLines(c, logLineCount)
   149  
   150  	linesRead := s.readLogLines(c, reader, 10)
   151  	c.Assert(linesRead, jc.DeepEquals, logLines[10:20])
   152  	s.assertWebsocketClosed(c, reader)
   153  }
   154  
   155  func (s *debugLogSuite) TestBacklogWithMaxLines(c *gc.C) {
   156  	s.writeLogLines(c, 10)
   157  
   158  	reader := s.openWebsocket(c, url.Values{"backlog": {"5"}, "maxLines": {"10"}})
   159  	s.assertLogFollowing(c, reader)
   160  	s.writeLogLines(c, logLineCount)
   161  
   162  	linesRead := s.readLogLines(c, reader, 10)
   163  	c.Assert(linesRead, jc.DeepEquals, logLines[5:15])
   164  	s.assertWebsocketClosed(c, reader)
   165  }
   166  
   167  func (s *debugLogSuite) TestFilter(c *gc.C) {
   168  	s.ensureLogFile(c)
   169  
   170  	reader := s.openWebsocket(c, url.Values{
   171  		"includeEntity": {"machine-0", "unit-ubuntu-0"},
   172  		"includeModule": {"juju.cmd"},
   173  		"excludeModule": {"juju.cmd.jujud"},
   174  	})
   175  	s.assertLogFollowing(c, reader)
   176  	s.writeLogLines(c, logLineCount)
   177  
   178  	expected := []string{logLines[0], logLines[40]}
   179  	linesRead := s.readLogLines(c, reader, len(expected))
   180  	c.Assert(linesRead, jc.DeepEquals, expected)
   181  }
   182  
   183  func (s *debugLogSuite) readLogLines(c *gc.C, reader *bufio.Reader, count int) (linesRead []string) {
   184  	for len(linesRead) < count {
   185  		line, err := reader.ReadString('\n')
   186  		c.Assert(err, gc.IsNil)
   187  		// Trim off the trailing \n
   188  		linesRead = append(linesRead, line[:len(line)-1])
   189  	}
   190  	return linesRead
   191  }
   192  
   193  func (s *debugLogSuite) openWebsocket(c *gc.C, values url.Values) *bufio.Reader {
   194  	conn, err := s.dialWebsocket(c, values)
   195  	c.Assert(err, gc.IsNil)
   196  	s.AddCleanup(func(_ *gc.C) { conn.Close() })
   197  	return bufio.NewReader(conn)
   198  }
   199  
   200  func (s *debugLogSuite) openWebsocketCustomPath(c *gc.C, path string) *bufio.Reader {
   201  	server := s.logURL(c, "wss", nil)
   202  	server.Path = path
   203  	header := utils.BasicAuthHeader(s.userTag, s.password)
   204  	conn, err := s.dialWebsocketFromURL(c, server.String(), header)
   205  	c.Assert(err, gc.IsNil)
   206  	s.AddCleanup(func(_ *gc.C) { conn.Close() })
   207  	return bufio.NewReader(conn)
   208  }
   209  
   210  func (s *debugLogSuite) ensureLogFile(c *gc.C) {
   211  	if s.logFile != nil {
   212  		return
   213  	}
   214  	path := filepath.Join(s.LogDir, "all-machines.log")
   215  	var err error
   216  	s.logFile, err = os.Create(path)
   217  	c.Assert(err, gc.IsNil)
   218  	s.AddCleanup(func(c *gc.C) {
   219  		s.logFile.Close()
   220  		s.logFile = nil
   221  		s.last = 0
   222  	})
   223  }
   224  
   225  func (s *debugLogSuite) writeLogLines(c *gc.C, count int) {
   226  	s.ensureLogFile(c)
   227  	for i := 0; i < count && s.last < logLineCount; i++ {
   228  		s.logFile.WriteString(logLines[s.last] + "\n")
   229  		s.last++
   230  	}
   231  }
   232  
   233  func (s *debugLogSuite) dialWebsocketInternal(c *gc.C, queryParams url.Values, header http.Header) (*websocket.Conn, error) {
   234  	server := s.logURL(c, "wss", queryParams).String()
   235  	return s.dialWebsocketFromURL(c, server, header)
   236  }
   237  
   238  func (s *debugLogSuite) dialWebsocketFromURL(c *gc.C, server string, header http.Header) (*websocket.Conn, error) {
   239  	c.Logf("dialing %v", server)
   240  	config, err := websocket.NewConfig(server, "http://localhost/")
   241  	c.Assert(err, gc.IsNil)
   242  	config.Header = header
   243  	caCerts := x509.NewCertPool()
   244  	c.Assert(caCerts.AppendCertsFromPEM([]byte(testing.CACert)), jc.IsTrue)
   245  	config.TlsConfig = &tls.Config{RootCAs: caCerts, ServerName: "anything"}
   246  	return websocket.DialConfig(config)
   247  }
   248  
   249  func (s *debugLogSuite) dialWebsocket(c *gc.C, queryParams url.Values) (*websocket.Conn, error) {
   250  	header := utils.BasicAuthHeader(s.userTag, s.password)
   251  	return s.dialWebsocketInternal(c, queryParams, header)
   252  }
   253  
   254  func (s *debugLogSuite) logURL(c *gc.C, scheme string, queryParams url.Values) *url.URL {
   255  	logURL := s.baseURL(c)
   256  	query := ""
   257  	if queryParams != nil {
   258  		query = queryParams.Encode()
   259  	}
   260  	logURL.Scheme = scheme
   261  	logURL.Path += "/log"
   262  	logURL.RawQuery = query
   263  	return logURL
   264  }
   265  
   266  func (s *debugLogSuite) assertWebsocketClosed(c *gc.C, reader *bufio.Reader) {
   267  	_, err := reader.ReadByte()
   268  	c.Assert(err, gc.Equals, io.EOF)
   269  }
   270  
   271  func (s *debugLogSuite) assertLogFollowing(c *gc.C, reader *bufio.Reader) {
   272  	errResult := s.getErrorResult(c, reader)
   273  	c.Assert(errResult.Error, gc.IsNil)
   274  }
   275  
   276  func (s *debugLogSuite) assertErrorResponse(c *gc.C, reader *bufio.Reader, expected string) {
   277  	errResult := s.getErrorResult(c, reader)
   278  	c.Assert(errResult.Error, gc.NotNil)
   279  	c.Assert(errResult.Error.Message, gc.Matches, expected)
   280  }
   281  
   282  func (s *debugLogSuite) getErrorResult(c *gc.C, reader *bufio.Reader) params.ErrorResult {
   283  	line, err := reader.ReadSlice('\n')
   284  	c.Assert(err, gc.IsNil)
   285  	var errResult params.ErrorResult
   286  	err = json.Unmarshal(line, &errResult)
   287  	c.Assert(err, gc.IsNil)
   288  	return errResult
   289  }
   290  
   291  var (
   292  	logLines = strings.Split(`
   293  machine-0: 2014-03-24 22:34:25 INFO juju.cmd supercommand.go:297 running juju-1.17.7.1-trusty-amd64 [gc]
   294  machine-0: 2014-03-24 22:34:25 INFO juju.cmd.jujud machine.go:127 machine agent machine-0 start (1.17.7.1-trusty-amd64 [gc])
   295  machine-0: 2014-03-24 22:34:25 DEBUG juju.agent agent.go:384 read agent config, format "1.18"
   296  machine-0: 2014-03-24 22:34:25 INFO juju.cmd.jujud machine.go:155 Starting StateWorker for machine-0
   297  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "state"
   298  machine-0: 2014-03-24 22:34:25 INFO juju.state open.go:80 opening state; mongo addresses: ["localhost:37017"]; entity "machine-0"
   299  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "api"
   300  machine-0: 2014-03-24 22:34:25 INFO juju apiclient.go:114 state/api: dialing "wss://localhost:17070/"
   301  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "termination"
   302  machine-0: 2014-03-24 22:34:25 ERROR juju apiclient.go:119 state/api: websocket.Dial wss://localhost:17070/: dial tcp 127.0.0.1:17070: connection refused
   303  machine-0: 2014-03-24 22:34:25 ERROR juju runner.go:220 worker: exited "api": websocket.Dial wss://localhost:17070/: dial tcp 127.0.0.1:17070: connection refused
   304  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:254 worker: restarting "api" in 3s
   305  machine-0: 2014-03-24 22:34:25 INFO juju.state open.go:118 connection established
   306  machine-0: 2014-03-24 22:34:25 DEBUG juju.utils gomaxprocs.go:24 setting GOMAXPROCS to 8
   307  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "local-storage"
   308  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "instancepoller"
   309  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "apiserver"
   310  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "resumer"
   311  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "cleaner"
   312  machine-0: 2014-03-24 22:34:25 INFO juju.state.apiserver apiserver.go:43 listening on "[::]:17070"
   313  machine-0: 2014-03-24 22:34:25 INFO juju runner.go:262 worker: start "minunitsworker"
   314  machine-0: 2014-03-24 22:34:28 INFO juju runner.go:262 worker: start "api"
   315  machine-0: 2014-03-24 22:34:28 INFO juju apiclient.go:114 state/api: dialing "wss://localhost:17070/"
   316  machine-0: 2014-03-24 22:34:28 INFO juju.state.apiserver apiserver.go:131 [1] API connection from 127.0.0.1:36491
   317  machine-0: 2014-03-24 22:34:28 INFO juju apiclient.go:124 state/api: connection established
   318  machine-0: 2014-03-24 22:34:28 DEBUG juju.state.apiserver apiserver.go:120 <- [1] <unknown> {"RequestId":1,"Type":"Admin","Request":"Login","Params":{"AuthTag":"machine-0","Password":"ARbW7iCV4LuMugFEG+Y4e0yr","Nonce":"user-admin:bootstrap"}}
   319  machine-0: 2014-03-24 22:34:28 DEBUG juju.state.apiserver apiserver.go:127 -> [1] machine-0 10.305679ms {"RequestId":1,"Response":{}} Admin[""].Login
   320  machine-1: 2014-03-24 22:36:28 INFO juju.cmd supercommand.go:297 running juju-1.17.7.1-precise-amd64 [gc]
   321  machine-1: 2014-03-24 22:36:28 INFO juju.cmd.jujud machine.go:127 machine agent machine-1 start (1.17.7.1-precise-amd64 [gc])
   322  machine-1: 2014-03-24 22:36:28 DEBUG juju.agent agent.go:384 read agent config, format "1.18"
   323  machine-1: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "api"
   324  machine-1: 2014-03-24 22:36:28 INFO juju apiclient.go:114 state/api: dialing "wss://10.0.3.1:17070/"
   325  machine-1: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "termination"
   326  machine-1: 2014-03-24 22:36:28 INFO juju apiclient.go:124 state/api: connection established
   327  machine-1: 2014-03-24 22:36:28 DEBUG juju.agent agent.go:523 writing configuration file
   328  machine-1: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "upgrader"
   329  machine-1: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "upgrade-steps"
   330  machine-1: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "machiner"
   331  machine-1: 2014-03-24 22:36:28 INFO juju.cmd.jujud machine.go:458 upgrade to 1.17.7.1-precise-amd64 already completed.
   332  machine-1: 2014-03-24 22:36:28 INFO juju.cmd.jujud machine.go:445 upgrade to 1.17.7.1-precise-amd64 completed.
   333  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju.cmd supercommand.go:297 running juju-1.17.7.1-precise-amd64 [gc]
   334  unit-ubuntu-0: 2014-03-24 22:36:28 DEBUG juju.agent agent.go:384 read agent config, format "1.18"
   335  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju.jujud unit.go:76 unit agent unit-ubuntu-0 start (1.17.7.1-precise-amd64 [gc])
   336  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "api"
   337  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju apiclient.go:114 state/api: dialing "wss://10.0.3.1:17070/"
   338  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju apiclient.go:124 state/api: connection established
   339  unit-ubuntu-0: 2014-03-24 22:36:28 DEBUG juju.agent agent.go:523 writing configuration file
   340  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "upgrader"
   341  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "logger"
   342  unit-ubuntu-0: 2014-03-24 22:36:28 DEBUG juju.worker.logger logger.go:35 initial log config: "<root>=DEBUG"
   343  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "uniter"
   344  unit-ubuntu-0: 2014-03-24 22:36:28 DEBUG juju.worker.logger logger.go:60 logger setup
   345  unit-ubuntu-0: 2014-03-24 22:36:28 INFO juju runner.go:262 worker: start "rsyslog"
   346  unit-ubuntu-0: 2014-03-24 22:36:28 DEBUG juju.worker.rsyslog worker.go:76 starting rsyslog worker mode 1 for "unit-ubuntu-0" "tim-local"
   347  `[1:], "\n")
   348  	logLineCount = len(logLines)
   349  )