// Test that a disabled slow log rotation in Percona Server (or MySQL) does not change analizer config
func (s *AnalyzerTestSuite) TestNoSlowLogTakeOver(t *C) {
/*
PS can be configured to rotate slow log, making qan break.
Since qan cannot handle the situation where a slow log is rotated by a third party we take over Percona Server
rotation and disable it on DB.
*/
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
s.config,
s.iter,
s.nullmysql,
s.restartChan,
s.worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Idle")
// Disable DB rotation by setting max_slowlog_size to a value < 4096
s.nullmysql.SetGlobalVarNumber("max_slowlog_size", 1000)
// Trigger our PS slow log rotation take-over, everything should stay the same since max_slowlog_size is < 4096
a.TakeOverPerconaServerRotation()
t.Check(a.Config().MaxSlowLogSize, Equals, MAX_SLOW_LOG_SIZE)
err = a.Stop()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Stopped")
t.Check(a.String(), Equals, "qan-analyzer")
}
func (s *AnalyzerTestSuite) TestRunMockWorker(t *C) {
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
s.config,
s.iter,
s.nullmysql,
s.restartChan,
s.worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Idle")
// No interval yet, so work should not have one.
t.Check(s.worker.Interval, IsNil)
// Send an interval. The analyzer runs the worker with it.
now := time.Now()
i := &qan.Interval{
Number: 1,
StartTime: now,
StopTime: now.Add(1 * time.Minute),
Filename: "slow.log",
StartOffset: 0,
EndOffset: 999,
}
s.intervalChan <- i
if !test.WaitState(s.worker.SetupChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
t.Check(s.worker.Interval, DeepEquals, i)
if !test.WaitState(s.worker.RunChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
if !test.WaitState(s.worker.CleanupChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
err = a.Stop()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Stopped")
t.Check(a.String(), Equals, "qan-analyzer")
}
func (s *ManagerTestSuite) TestGetConfig(t *C) {
// Make a qan.Manager with mock factories.
mockConnFactory := &mock.ConnectionFactory{Conn: s.nullmysql}
a := mock.NewQanAnalyzer()
f := mock.NewQanAnalyzerFactory(a)
m := qan.NewManager(s.logger, s.clock, s.im, s.mrmsMonitor, mockConnFactory, f)
t.Assert(m, NotNil)
// Write a realistic qan.conf config to disk.
config := qan.Config{
ServiceInstance: s.mysqlInstance,
CollectFrom: "slowlog",
Interval: 300,
MaxWorkers: 1,
WorkerRunTime: 600,
Start: []mysql.Query{
mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"},
mysql.Query{Set: "SET GLOBAL long_query_time=0.456"},
mysql.Query{Set: "SET GLOBAL slow_query_log=ON"},
},
Stop: []mysql.Query{
mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"},
mysql.Query{Set: "SET GLOBAL long_query_time=10"},
},
}
err := pct.Basedir.WriteConfig("qan", &config)
t.Assert(err, IsNil)
qanConfig, err := json.Marshal(config)
t.Assert(err, IsNil)
// Start the manager and analyzer.
err = m.Start()
t.Check(err, IsNil)
test.WaitStatus(1, m, "qan", "Running")
// Get the manager config which should be just the analyzer config.
got, errs := m.GetConfig()
t.Assert(errs, HasLen, 0)
t.Assert(got, HasLen, 1)
expect := []proto.AgentConfig{
{
InternalService: "qan",
Config: string(qanConfig),
Running: true,
},
}
if same, diff := IsDeeply(got, expect); !same {
Dump(got)
t.Error(diff)
}
// Stop the manager.
err = m.Stop()
t.Assert(err, IsNil)
}
// Test slow log rotation take over from Percona Server
func (s *AnalyzerTestSuite) TestSlowLogTakeOver(t *C) {
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
s.config,
s.iter,
s.nullmysql,
s.restartChan,
s.worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Idle")
s.nullmysql.Reset()
// Increase our max_slowlog_size in mocked DB
s.nullmysql.SetGlobalVarNumber("max_slowlog_size", 5000)
// Trigger slowlog rotation, takeover should succeed since max_slowlog_size >= 4096
a.TakeOverPerconaServerRotation()
expectedQueries := []mysql.Query{
mysql.Query{
Set: "SET GLOBAL max_slowlog_size = 0",
Verify: "",
Expect: "",
},
}
t.Check(s.nullmysql.GetSet(), DeepEquals, expectedQueries)
// Config should now have the configured Percona Server slow log rotation file size
t.Check(a.Config().MaxSlowLogSize, Equals, int64(5000))
err = a.Stop()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Stopped")
t.Check(a.String(), Equals, "qan-analyzer")
}
func (s *AnalyzerTestSuite) TestStartServiceFast(t *C) {
// Simulate the next tick being 3m away (mock.clock.Eta = 180) so that
// run() sends the first tick on the tick chan, causing the first
// interval to start immediately.
s.clock.Eta = 180
defer func() { s.clock.Eta = 0 }()
config := s.config
config.Interval = 300 // 5m
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
config,
s.iter,
s.nullmysql,
s.restartChan,
s.worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Idle")
// run() should prime the tickChan with the 1st tick immediately. This makes
// the interval iter start the interval immediately. Then run() continues
// waiting for the iter to send an interval which happens when the real ticker
// (the clock) sends the 2nd tick which is synced to the interval, thus ending
// the first interval started by run() and starting the 2nd interval as normal.
select {
case tick := <-s.iter.TickChan():
t.Check(tick.IsZero(), Not(Equals), true)
case <-time.After(1 * time.Second):
t.Error("Timeout waiting for primer tick")
}
// Status indicates that next interval is 3m away as we faked.
status := a.Status()
t.Check(status["qan-analyzer-next-interval"], Equals, "180.0s")
err = a.Stop()
t.Assert(err, IsNil)
}
func (s *ManagerTestSuite) TestBadCmd(t *C) {
mockConnFactory := &mock.ConnectionFactory{Conn: s.nullmysql}
a := mock.NewQanAnalyzer()
f := mock.NewQanAnalyzerFactory(a)
m := qan.NewManager(s.logger, s.clock, s.im, s.mrmsMonitor, mockConnFactory, f)
t.Assert(m, NotNil)
err := m.Start()
t.Check(err, IsNil)
defer m.Stop()
test.WaitStatus(1, m, "qan", "Running")
cmd := &proto.Cmd{
User: "******",
Ts: time.Now(),
AgentUuid: "123",
Service: "qan",
Cmd: "foo", // bad cmd
}
reply := m.Handle(cmd)
t.Assert(reply.Error, Equals, "Unknown command: foo")
}
func (s *ManagerTestSuite) TestStarNoConfig(t *C) {
// Make a qan.Manager with mock factories.
mockConnFactory := &mock.ConnectionFactory{Conn: s.nullmysql}
a := mock.NewQanAnalyzer()
f := mock.NewQanAnalyzerFactory(a)
m := qan.NewManager(s.logger, s.clock, s.im, s.mrmsMonitor, mockConnFactory, f)
t.Assert(m, NotNil)
// qan.Manager should be able to start without a qan.conf, i.e. no analyzer.
err := m.Start()
t.Check(err, IsNil)
// Wait for qan.Manager.Start() to finish.
test.WaitStatus(1, m, "qan", "Running")
// No analyzer is configured, so the mock analyzer should not be started.
select {
case <-a.StartChan:
t.Error("Analyzer.Start() called")
default:
}
// And the mock analyzer's status should not be reported.
status := m.Status()
t.Check(status["qan"], Equals, "Running")
// Stop the manager.
err = m.Stop()
t.Assert(err, IsNil)
// No analyzer is configured, so the mock analyzer should not be stop.
select {
case <-a.StartChan:
t.Error("Analyzer.Stop() called")
default:
}
}
func (s *ManagerTestSuite) TestStartService(t *C) {
// Make and start a qan.Manager with mock factories, no analyzer yet.
mockConnFactory := &mock.ConnectionFactory{Conn: s.nullmysql}
a := mock.NewQanAnalyzer()
f := mock.NewQanAnalyzerFactory(a)
m := qan.NewManager(s.logger, s.clock, s.im, s.mrmsMonitor, mockConnFactory, f)
t.Assert(m, NotNil)
err := m.Start()
t.Check(err, IsNil)
test.WaitStatus(1, m, "qan", "Running")
// Create the qan config.
config := &qan.Config{
ServiceInstance: s.mysqlInstance,
Start: []mysql.Query{
mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"},
mysql.Query{Set: "SET GLOBAL long_query_time=0.123"},
mysql.Query{Set: "SET GLOBAL slow_query_log=ON"},
},
Stop: []mysql.Query{
mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"},
mysql.Query{Set: "SET GLOBAL long_query_time=10"},
},
Interval: 300, // 5 min
MaxSlowLogSize: 1073741824, // 1 GiB
RemoveOldSlowLogs: true,
ExampleQueries: true,
MaxWorkers: 2,
WorkerRunTime: 600, // 10 min
CollectFrom: "slowlog",
}
// Send a StartService cmd with the qan config to start an analyzer.
now := time.Now()
qanConfig, _ := json.Marshal(config)
cmd := &proto.Cmd{
User: "******",
Ts: now,
AgentUuid: "123",
Service: "agent",
Cmd: "StartService",
Data: qanConfig,
}
reply := m.Handle(cmd)
t.Assert(reply.Error, Equals, "")
// The manager writes the qan config to disk.
data, err := ioutil.ReadFile(pct.Basedir.ConfigFile("qan"))
t.Check(err, IsNil)
gotConfig := &qan.Config{}
err = json.Unmarshal(data, gotConfig)
t.Check(err, IsNil)
if same, diff := IsDeeply(gotConfig, config); !same {
Dump(gotConfig)
t.Error(diff)
}
// Now the manager and analyzer should be running.
status := m.Status()
t.Check(status["qan"], Equals, "Running")
t.Check(status["qan-analyzer"], Equals, "ok")
// Try to start the same analyzer again. It results in an error because
// double tooling is not allowed.
reply = m.Handle(cmd)
t.Check(reply.Error, Equals, "qan-analyzer service is running")
// Send a StopService cmd to stop the analyzer.
// todo-1.1: send Data with analyzer instance to stop.
now = time.Now()
cmd = &proto.Cmd{
User: "******",
Ts: now,
AgentUuid: "123",
Service: "qan",
Cmd: "StopService",
}
reply = m.Handle(cmd)
t.Assert(reply.Error, Equals, "")
// Now the manager is still running, but the analyzer is not.
status = m.Status()
t.Check(status["qan"], Equals, "Running")
// And the manager has removed the qan config from disk so next time
// the agent starts the analyzer is not started.
t.Check(test.FileExists(pct.Basedir.ConfigFile("qan")), Equals, false)
// StopService should be idempotent, so send it again and expect no error.
reply = m.Handle(cmd)
t.Assert(reply.Error, Equals, "")
// Stop the manager.
err = m.Stop()
t.Assert(err, IsNil)
}
func (s *AnalyzerTestSuite) TestRecoverWorkerPanic(t *C) {
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
s.config,
s.iter,
s.nullmysql,
s.restartChan,
s.worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Idle")
// This will cause the worker to panic when it's ran by the analyzer.
s.worker.SetupCrashChan <- true
// Send an interval. The analyzer runs the worker with it.
now := time.Now()
i := &qan.Interval{
Number: 1,
StartTime: now,
StopTime: now.Add(1 * time.Minute),
Filename: "slow.log",
StartOffset: 0,
EndOffset: 999,
}
s.intervalChan <- i
if !test.WaitState(s.worker.SetupChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
// Wait for that ^ run of the worker to fully stop and return.
test.WaitStatus(1, a, "qan-analyzer", "Idle")
i = &qan.Interval{
Number: 2,
StartTime: now,
StopTime: now.Add(1 * time.Minute),
Filename: "slow.log",
StartOffset: 1000,
EndOffset: 2000,
}
s.intervalChan <- i
if !test.WaitState(s.worker.SetupChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
t.Check(s.worker.Interval, DeepEquals, i)
if !test.WaitState(s.worker.RunChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
if !test.WaitState(s.worker.CleanupChan) {
t.Fatal("Timeout waiting for <-s.worker.SetupChan")
}
err = a.Stop()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Stopped")
t.Check(a.String(), Equals, "qan-analyzer")
}
func (s *AnalyzerTestSuite) TestRealSlowLogWorker(t *C) {
dsn := os.Getenv("PCT_TEST_MYSQL_DSN")
if dsn == "" {
t.Fatal("PCT_TEST_MYSQL_DSN is not set")
}
realmysql := mysql.NewConnection(dsn)
if err := realmysql.Connect(1); err != nil {
t.Fatal(err)
}
// Don't release all resources immediately because the worker needs the connection
defer realmysql.Close()
defer test.DrainRecvData(s.dataChan)
config := s.config
config.Start = []mysql.Query{
mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"},
mysql.Query{Set: "SET GLOBAL long_query_time=0"},
mysql.Query{Set: "SET GLOBAL slow_query_log=ON"},
}
config.Stop = []mysql.Query{
mysql.Query{Set: "SET GLOBAL slow_query_log=OFF"},
mysql.Query{Set: "SET GLOBAL long_query_time=10"},
}
worker := slowlog.NewWorker(pct.NewLogger(s.logChan, "qan-worker"), config, realmysql)
//intervalChan := make(chan *qan.Interval, 1)
//iter := mock.NewIter(intervalChan)
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
config,
s.iter,
realmysql,
s.restartChan,
worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
if !test.WaitStatus(3, a, "qan-analyzer", "Idle") {
t.Fatal("Timeout waiting for qan-analyzer=Idle")
}
now := time.Now().UTC()
i := &qan.Interval{
Number: 1,
StartTime: now,
StopTime: now.Add(1 * time.Minute),
Filename: inputDir + "slow001.log",
StartOffset: 0,
EndOffset: 524,
}
s.intervalChan <- i
data := test.WaitData(s.dataChan)
t.Assert(data, HasLen, 1)
res := data[0].(*qan.Report)
t.Check(res.Global.TotalQueries, Equals, uint64(2))
err = a.Stop()
t.Assert(err, IsNil)
}
func (s *AnalyzerTestSuite) TestMySQLRestart(t *C) {
a := qan.NewRealAnalyzer(
pct.NewLogger(s.logChan, "qan-analyzer"),
s.config,
s.iter,
s.nullmysql,
s.restartChan,
s.worker,
s.clock,
s.spool,
)
err := a.Start()
t.Assert(err, IsNil)
test.WaitStatus(1, a, "qan-analyzer", "Idle")
// When analyzer starts, it configures MySQL using the Start set of queries.
got := s.nullmysql.GetSet()
expect := s.config.Start
if same, diff := IsDeeply(got, expect); !same {
Dump(got)
t.Error(diff)
}
// Analyzer starts its iter when MySQL is ready.
t.Check(s.iter.Calls(), DeepEquals, []string{"Start"})
s.iter.Reset()
// Simulate a MySQL restart. This causes the analyzer to re-configure MySQL
// using the same Start queries.
s.nullmysql.Reset()
s.restartChan <- true
if !test.WaitState(s.nullmysql.SetChan) {
t.Error("Timeout waiting for <-s.nullmysql.SetChan")
}
test.WaitStatus(1, a, "qan-analyzer", "Idle")
got = s.nullmysql.GetSet()
if same, diff := IsDeeply(got, expect); !same {
Dump(got)
t.Error(diff)
}
// Analyzer stops and re-starts its iter on MySQL restart.
t.Check(s.iter.Calls(), DeepEquals, []string{"Stop", "Start"})
s.nullmysql.Reset()
// Enable slowlog DB rotation by setting max_slowlog_size to a value > 4096 and simulate MySQL restart
s.nullmysql.SetGlobalVarNumber("max_slowlog_size", 100000)
s.restartChan <- true
if !test.WaitState(s.nullmysql.SetChan) {
t.Error("Timeout waiting for <-s.nullmysql.SetChan")
}
test.WaitStatus(1, a, "qan-analyzer", "Idle")
expectedQueries := []mysql.Query{
mysql.Query{
Set: "SET GLOBAL max_slowlog_size = 0",
Verify: "",
Expect: "",
},
mysql.Query{
Set: "-- start",
Verify: "",
Expect: "",
},
}
t.Check(s.nullmysql.GetSet(), DeepEquals, expectedQueries)
t.Check(a.Config().MaxSlowLogSize, Equals, int64(100000))
err = a.Stop()
t.Assert(err, IsNil)
}