migrations = []migration.Migration{fakeMigration102, fakeMigration}
})
Describe("reporting", func() {
var sender *fake.FakeMetricSender
BeforeEach(func() {
sender = fake.NewFakeMetricSender()
metrics.Initialize(sender, nil)
})
It("reports the duration that it took to migrate", func() {
Eventually(migrationProcess.Ready()).Should(BeClosed())
Expect(migrationsDone).To(BeClosed())
reportedDuration := sender.GetValue("MigrationDuration")
Expect(reportedDuration.Value).NotTo(BeZero())
Expect(reportedDuration.Unit).To(Equal("nanos"))
})
})
It("it sorts the migrations and runs them sequentially", func() {
Eventually(migrationProcess.Ready()).Should(BeClosed())
Expect(migrationsDone).To(BeClosed())
Consistently(fakeETCDDB.SetVersionCallCount).Should(Equal(2))
_, version := fakeETCDDB.SetVersionArgsForCall(0)
Expect(version).To(Equal(&models.Version{CurrentVersion: 99, TargetVersion: 102}))
_, version = fakeETCDDB.SetVersionArgsForCall(1)
Expect(version).To(Equal(&models.Version{CurrentVersion: 102, TargetVersion: 102}))
Expect(recorder.Code).To(Equal(http.StatusOK))
})
Context("metrices", func() {
var fakeMetricSender *fake.FakeMetricSender
BeforeEach(func() {
fakeMetricSender = fake.NewFakeMetricSender()
metricBatcher := metricbatcher.New(fakeMetricSender, time.Millisecond)
metrics.Initialize(fakeMetricSender, metricBatcher)
})
requestAndAssert := func(req *http.Request, metricName string) {
requestStart := time.Now()
proxy.ServeHTTP(recorder, req)
metric := fakeMetricSender.GetValue(metricName)
elapsed := float64(time.Since(requestStart)) / float64(time.Millisecond)
Expect(metric.Unit).To(Equal("ms"))
Expect(metric.Value).To(BeNumerically("<", elapsed))
}
It("Should emit value metric for recentlogs request", func() {
close(channelGroupConnector.messages)
req, _ := http.NewRequest("GET", "/apps/appID123/recentlogs", nil)
requestAndAssert(req, "dopplerProxy.recentlogsLatency")
})
It("Should emit value metric for containermetrics request", func() {
close(channelGroupConnector.messages)
req, _ := http.NewRequest("GET", "/apps/appID123/containermetrics", nil)
"recvAppendRequestCnt": 1234,
"recvPkgRate": 2.0,
"recvBandwidthRate": 0.8,
"sendAppendRequestCnt": 4321
}
`))
etcd3.RouteToHandler("GET", "/v2/stats/leader", func(w http.ResponseWriter, r *http.Request) {
http.Redirect(w, r, etcd2.URL(), 302)
})
})
It("should emit them", func() {
Eventually(func() fake.Metric {
return sender.GetValue("ETCDLeader")
}).Should(Equal(fake.Metric{
Value: 1,
Unit: "Metric",
}))
Eventually(func() fake.Metric {
return sender.GetValue("ETCDReceivedBandwidthRate")
}).Should(Equal(fake.Metric{
Value: 2,
Unit: "B/s",
}))
Eventually(func() fake.Metric {
return sender.GetValue("ETCDSentBandwidthRate")
}).Should(Equal(fake.Metric{
sender *fake.FakeMetricSender
)
BeforeEach(func() {
sender = fake.NewFakeMetricSender()
metrics.Initialize(sender, nil)
})
Context("when a connection is received", func() {
It("emit a metric for the total number of connections", func() {
_, err := ssh.Dial("tcp", proxyAddress, clientConfig)
Expect(err).NotTo(HaveOccurred())
Eventually(
func() float64 {
return sender.GetValue("ssh-connections").Value
},
).Should(Equal(float64(1)))
_, err = ssh.Dial("tcp", proxyAddress, clientConfig)
Expect(err).NotTo(HaveOccurred())
Eventually(
func() float64 {
return sender.GetValue("ssh-connections").Value
},
).Should(Equal(float64(2)))
})
})
Context("when a connection is closed", func() {
metricsReporter.CaptureRoutingResponse(endpoint, &response2xx, time.Now(), time.Millisecond)
Eventually(func() uint64 { return sender.GetCounter("responses") }).Should(BeEquivalentTo(1))
metricsReporter.CaptureRoutingResponse(endpoint, &response4xx, time.Now(), time.Millisecond)
Eventually(func() uint64 { return sender.GetCounter("responses") }).Should(BeEquivalentTo(2))
})
It("sends the latency", func() {
response := http.Response{
StatusCode: 401,
}
metricsReporter.CaptureRoutingResponse(endpoint, &response, time.Now(), 2*time.Second)
Eventually(func() fake.Metric { return sender.GetValue("latency") }).Should(Equal(
fake.Metric{
Value: 2000,
Unit: "ms",
}))
})
It("sends the latency for the given component", func() {
response := http.Response{
StatusCode: 200,
}
endpoint.Tags["component"] = "CloudController"
metricsReporter.CaptureRoutingResponse(endpoint, &response, time.Now(), 2*time.Second)
Eventually(func() fake.Metric { return sender.GetValue("latency.CloudController") }).Should(Equal(
fake.Metric{
. "github.com/onsi/ginkgo"
. "github.com/onsi/gomega"
)
var _ = Describe("Metrics", func() {
var fakeMetricSender *fake.FakeMetricSender
BeforeEach(func() {
fakeMetricSender = fake.NewFakeMetricSender()
metrics.Initialize(fakeMetricSender)
})
It("delegates SendValue", func() {
metrics.SendValue("metric", 42.42, "answers")
Expect(fakeMetricSender.GetValue("metric").Value).To(Equal(42.42))
Expect(fakeMetricSender.GetValue("metric").Unit).To(Equal("answers"))
})
It("delegates IncrementCounter", func() {
metrics.IncrementCounter("count")
Expect(fakeMetricSender.GetCounter("count")).To(BeEquivalentTo(1))
metrics.IncrementCounter("count")
Expect(fakeMetricSender.GetCounter("count")).To(BeEquivalentTo(2))
})
It("delegates AddToCounter", func() {
metrics.AddToCounter("count", 5)
})
It("responds with 202", func() {
Expect(responseRecorder.Code).To(Equal(http.StatusAccepted))
})
It("logs with the correct session nesting", func() {
Expect(logger.TestSink.LogMessages()).To(Equal([]string{
"test.request.serving",
"test.request.task-auction-handler.create.submitted",
"test.request.done",
}))
})
It("sends the correct metrics", func() {
Expect(sender.GetValue("RequestLatency").Value).To(BeNumerically(">", 0))
Expect(sender.GetCounter("RequestCount")).To(BeEquivalentTo(1))
})
})
})
Describe("LRP Handler", func() {
Context("with a valid LRPStart", func() {
BeforeEach(func() {
starts := []auctioneer.LRPStartRequest{{
Indices: []int{2},
Domain: "tests",
ProcessGuid: "some-guid",
Resource: rep.Resource{
Context("When consul is running", func() {
Context("an error occurs while acquiring the lock", func() {
BeforeEach(func() {
lockKey = ""
})
It("continues to retry", func() {
lockProcess = ifrit.Background(lockRunner)
shouldEventuallyHaveNumSessions(1)
Consistently(lockProcess.Ready()).ShouldNot(BeClosed())
Consistently(lockProcess.Wait()).ShouldNot(Receive())
clock.Increment(retryInterval)
Eventually(logger).Should(Say("acquire-lock-failed"))
Eventually(logger).Should(Say("retrying-acquiring-lock"))
Expect(sender.GetValue(lockHeldMetricName).Value).To(Equal(float64(0)))
})
})
Context("and the lock is available", func() {
It("acquires the lock", func() {
lockProcess = ifrit.Background(lockRunner)
Eventually(lockProcess.Ready()).Should(BeClosed())
Expect(sender.GetValue(lockUptimeMetricName).Value).Should(Equal(float64(0)))
Expect(getLockValue()).To(Equal(lockValue))
Expect(sender.GetValue(lockHeldMetricName).Value).To(Equal(float64(1)))
})
Context("and we have acquired the lock", func() {
JustBeforeEach(func() {
lockProcess = ifrit.Background(lockRunner)
})
It("posts the response builder's result to CC", func() {
Expect(fakeCCClient.StagingCompleteCallCount()).To(Equal(1))
guid, payload, _ := fakeCCClient.StagingCompleteArgsForCall(0)
Expect(guid).To(Equal("the-task-guid"))
Expect(payload).To(Equal(backendResponseJson))
})
Context("when the CC request succeeds", func() {
It("increments the staging success counter", func() {
Expect(metricSender.GetCounter("StagingRequestsSucceeded")).To(BeEquivalentTo(1))
})
It("emits the time it took to stage succesfully", func() {
Expect(metricSender.GetValue("StagingRequestSucceededDuration")).To(Equal(fake.Metric{
Value: float64(stagingDurationNano),
Unit: "nanos",
}))
})
It("returns a 200", func() {
Expect(responseRecorder.Code).To(Equal(200))
})
})
Context("when the CC request fails", func() {
BeforeEach(func() {
fakeCCClient.StagingCompleteReturns(&cc_client.BadResponseError{504})
})
defer newTaskConnection.Close()
case <-time.After(1 * time.Second):
Fail("Should have been able to open the socket listener")
}
newTaskConnection.Write([]byte(SOCKET_PREFIX + expectedMessage + "\n"))
Eventually(fakeLogSender.GetLogs, 3).Should(HaveLen(1))
logs := fakeLogSender.GetLogs()
Expect(logs[0].AppId).To(Equal("5678"))
})
Context("metrics", func() {
It("updates totalApps", func() {
Eventually(func() float64 {
return fakeMetricSender.GetValue("totalApps").Value
}).Should(BeEquivalentTo(3))
deleteFile()
Eventually(func() float64 {
return fakeMetricSender.GetValue("totalApps").Value
}, 3).Should(BeEquivalentTo(0))
})
})
})
})
It("creates the correct structure on forwarded messages and does not contain drain URLs", func() {
agent.Start()
reportInterval,
fakeClock,
)
pmn.Start()
})
AfterEach(func() {
pmn.Stop()
})
Context("when the report interval elapses", func() {
It("emits metrics", func() {
fakeClock.Increment(reportInterval)
Eventually(func() fake.Metric {
return sender.GetValue("LoopDevices")
}).Should(Equal(fake.Metric{
Value: 33,
Unit: "Metric",
}))
Eventually(func() fake.Metric {
return sender.GetValue("BackingStores")
}).Should(Equal(fake.Metric{
Value: 12,
Unit: "Metric",
}))
Eventually(func() fake.Metric {
return sender.GetValue("DepotDirs")
}).Should(Equal(fake.Metric{
It("does not update the domain", func() {
Consistently(bbsClient.UpsertDomainCallCount).Should(Equal(0))
})
It("sends the creates and updates for the apps it got but not the deletes", func() {
Eventually(bbsClient.DesireLRPCallCount).Should(Equal(1))
Eventually(bbsClient.UpdateDesiredLRPCallCount).Should(Equal(2))
Consistently(bbsClient.RemoveDesiredLRPCallCount).Should(Equal(0))
})
})
Context("when fetching fingerprints succeeds", func() {
It("emits the total time taken to talk to CC and then update desired state", func() {
Eventually(bbsClient.UpsertDomainCallCount, 5).Should(Equal(1))
Eventually(func() fake.Metric { return metricSender.GetValue("DesiredLRPSyncDuration") }).Should(Equal(fake.Metric{
Value: float64(syncDuration),
Unit: "nanos",
}))
})
Context("and the differ discovers desired LRPs to delete", func() {
It("the processor deletes them", func() {
Eventually(bbsClient.RemoveDesiredLRPCallCount).Should(Equal(1))
Consistently(bbsClient.RemoveDesiredLRPCallCount).Should(Equal(1))
Expect(bbsClient.RemoveDesiredLRPArgsForCall(0)).To(Equal("excess-process-guid"))
})
})
Context("and the differ discovers missing apps", func() {
Context("Emit", func() {
JustBeforeEach(func() {
table.MessagesToEmitReturns(dummyMessagesToEmit)
table.RouteCountReturns(123)
syncEvents.Emit <- struct{}{}
})
It("emits", func() {
Eventually(emitter.EmitCallCount).Should(Equal(1))
Expect(emitter.EmitArgsForCall(0)).To(Equal(dummyMessagesToEmit))
})
It("sends a 'routes total' metric", func() {
Eventually(func() float64 {
return fakeMetricSender.GetValue("RoutesTotal").Value
}, 2).Should(BeEquivalentTo(123))
})
It("sends a 'synced routes' metric", func() {
Eventually(func() uint64 {
return fakeMetricSender.GetCounter("RoutesSynced")
}, 2).Should(BeEquivalentTo(2))
})
})
Context("Begin & End events", func() {
currentTag := &models.ModificationTag{Epoch: "abc", Index: 1}
hostname1 := "foo.example.com"
hostname2 := "bar.example.com"
endpoint1 := routing_table.Endpoint{InstanceGuid: "ig-1", Host: "1.1.1.1", Port: 11, ContainerPort: 8080, Evacuating: false, ModificationTag: currentTag}
case "sentMessageCount":
Expect(metric.Value).To(Equal(uint64(1)))
case "sentByteCount":
Expect(metric.Value).To(Equal(uint64(21)))
case "receivedMessageCount":
Expect(metric.Value).To(Equal(uint64(1)))
case "receivedByteCount":
Expect(metric.Value).To(Equal(uint64(21)))
default:
Fail("Got an invalid metric name: " + metric.Name)
}
}
})
It("sends metrics using dropsonde", func() {
Expect(fakeMetricSender.GetValue("currentBufferCount")).To(Equal(fake.Metric{Value: 0, Unit: "Msg"}))
Expect(fakeMetricSender.GetCounter("sentMessageCount")).To(BeEquivalentTo(1))
Expect(fakeMetricSender.GetCounter("sentByteCount")).To(BeEquivalentTo(21))
Expect(fakeMetricSender.GetCounter("receivedMessageCount")).To(BeEquivalentTo(1))
Expect(fakeMetricSender.GetCounter("receivedByteCount")).To(BeEquivalentTo(21))
})
})
It("doesn't send empty data", func() {
bufferSize := 4096
firstMessage := []byte("")
secondMessage := []byte("hi")
loggregatorClient.Send(firstMessage)
loggregatorClient.Send(secondMessage)
})
Context("with metrics", func() {
var sender *fake.FakeMetricSender
BeforeEach(func() {
sender = fake.NewFakeMetricSender()
metrics.Initialize(sender, nil)
})
It("should emit mount time on successful mount", func() {
volumeId := "fake-volume"
client.Mount(logger, "fakedriver", volumeId, map[string]interface{}{"volume_id": volumeId})
reportedDuration := sender.GetValue("VolmanMountDuration")
Expect(reportedDuration.Unit).To(Equal("nanos"))
Expect(reportedDuration.Value).NotTo(BeZero())
reportedDuration = sender.GetValue("VolmanMountDurationForfakedriver")
Expect(reportedDuration.Unit).To(Equal("nanos"))
Expect(reportedDuration.Value).NotTo(BeZero())
})
It("should increment error count on mount failure", func() {
mountResponse := voldriver.MountResponse{Err: "an error"}
fakeDriver.MountReturns(mountResponse)
volumeId := "fake-volume"
client.Mount(logger, "fakedriver", volumeId, map[string]interface{}{"volume_id": volumeId})
Expect(sender.GetCounter("VolmanMountErrors")).To(Equal(uint64(1)))
})
handler http.HandlerFunc
)
BeforeEach(func() {
sender = fake.NewFakeMetricSender()
dropsonde_metrics.Initialize(sender, nil)
logger := lager.NewLogger("test-session")
handler = func(w http.ResponseWriter, r *http.Request) { time.Sleep(10) }
handler = middleware.NewLatencyEmitter(logger).EmitLatency(handler)
})
It("reports latency", func() {
handler.ServeHTTP(nil, nil)
latency := sender.GetValue("RequestLatency")
Expect(latency.Value).NotTo(BeZero())
Expect(latency.Unit).To(Equal("nanos"))
})
})
Describe("RequestCountWrap", func() {
var (
sender *fake.FakeMetricSender
handler http.HandlerFunc
)
BeforeEach(func() {
sender = fake.NewFakeMetricSender()
dropsonde_metrics.Initialize(sender, nil)
{
LRP: rep.NewLRP(models.NewActualLRPKey("incompatible-stacks", 0, "domain"), resource),
AuctionRecord: auctiontypes.AuctionRecord{PlacementError: auctiontypes.ErrorCellMismatch.Error()},
},
},
FailedTasks: []auctiontypes.TaskAuction{
{
Task: rep.NewTask("failed-task", "domain", resource),
AuctionRecord: auctiontypes.AuctionRecord{PlacementError: rep.ErrorInsufficientResources.Error()},
},
},
})
Expect(metricSender.GetCounter("AuctioneerLRPAuctionsStarted")).To(BeNumerically("==", 1))
Expect(metricSender.GetCounter("AuctioneerTaskAuctionsStarted")).To(BeNumerically("==", 1))
Expect(metricSender.GetCounter("AuctioneerLRPAuctionsFailed")).To(BeNumerically("==", 2))
Expect(metricSender.GetCounter("AuctioneerTaskAuctionsFailed")).To(BeNumerically("==", 1))
})
})
Describe("FetchStatesCompleted", func() {
It("should adjust the metric counters", func() {
delegate.FetchStatesCompleted(1 * time.Second)
sentMetric := metricSender.GetValue("AuctioneerFetchStatesDuration")
Expect(sentMetric.Value).To(Equal(1e+09))
Expect(sentMetric.Unit).To(Equal("nanos"))
})
})
})
JustBeforeEach(func() {
reporter = ifrit.Envoke(&metrics.Reporter{
ExecutorSource: executorClient,
Interval: reportInterval,
Logger: logger,
})
})
AfterEach(func() {
reporter.Signal(os.Interrupt)
Eventually(reporter.Wait()).Should(Receive())
})
It("reports the current capacity on the given interval", func() {
Eventually(func() fake.Metric {
return sender.GetValue("CapacityTotalMemory")
}, reportInterval*2).Should(Equal(fake.Metric{
Value: 1024,
Unit: "MiB",
}))
Eventually(func() fake.Metric {
return sender.GetValue("CapacityTotalDisk")
}, reportInterval*2).Should(Equal(fake.Metric{
Value: 2048,
Unit: "MiB",
}))
Eventually(func() fake.Metric {
return sender.GetValue("CapacityTotalContainers")
}, reportInterval*2).Should(Equal(fake.Metric{
})
It("pushes them onto the queue", func() {
Eventually(fakeQueue.PushCallCount).Should(Equal(2))
enqueuedOperations := make([]operationq.Operation, 0, 2)
enqueuedOperations = append(enqueuedOperations, fakeQueue.PushArgsForCall(0))
enqueuedOperations = append(enqueuedOperations, fakeQueue.PushArgsForCall(1))
Expect(enqueuedOperations).To(ConsistOf(operation1, operation2))
})
It("emits the duration it took to generate the batch operations", func() {
Eventually(fakeQueue.PushCallCount).Should(Equal(2))
reportedDuration := sender.GetValue("RepBulkSyncDuration")
Expect(reportedDuration.Unit).To(Equal("nanos"))
Expect(reportedDuration.Value).To(BeNumerically("==", 10*time.Second))
})
})
Context("when generating the batch operations fails", func() {
disaster := errors.New("nope")
BeforeEach(func() {
fakeGenerator.BatchOperationsReturns(nil, disaster)
})
It("logs the error", func() {
Eventually(logger).Should(gbytes.Say("failed-to-generate-operations"))
Eventually(logger).Should(gbytes.Say("nope"))
})
JustBeforeEach(func() {
runner = encryptor.New(logger, fakeDB, keyManager, cryptor, clock.NewClock())
encryptorProcess = ifrit.Background(runner)
})
AfterEach(func() {
ginkgomon.Kill(encryptorProcess)
})
It("reports the duration that it took to encrypt", func() {
Eventually(encryptorProcess.Ready()).Should(BeClosed())
Eventually(logger.LogMessages).Should(ContainElement("test.encryptor.encryption-finished"))
reportedDuration := sender.GetValue("EncryptionDuration")
Expect(reportedDuration.Value).NotTo(BeZero())
Expect(reportedDuration.Unit).To(Equal("nanos"))
})
Context("when there is no current encryption key", func() {
BeforeEach(func() {
fakeDB.EncryptionKeyLabelReturns("", models.ErrResourceNotFound)
})
It("encrypts all the existing records", func() {
Eventually(encryptorProcess.Ready()).Should(BeClosed())
Eventually(logger.LogMessages).Should(ContainElement("test.encryptor.encryption-finished"))
Expect(fakeDB.PerformEncryptionCallCount()).To(Equal(1))
})
taskGuid = "some-guid"
taskGuid2 = "some-other-guid"
domain = "some-domain"
cellId = "cell-id"
)
JustBeforeEach(func() {
etcdDB.ConvergeTasks(logger, kickTasksDuration, expirePendingTaskDuration, expireCompletedTaskDuration)
})
It("bumps the convergence counter", func() {
Expect(sender.GetCounter("ConvergenceTaskRuns")).To(Equal(uint64(1)))
})
It("reports the duration that it took to converge", func() {
reportedDuration := sender.GetValue("ConvergenceTaskDuration")
Expect(reportedDuration.Unit).To(Equal("nanos"))
Expect(reportedDuration.Value).NotTo(BeZero())
})
It("emits -1 metrics", func() {
Expect(sender.GetValue("TasksPending").Value).To(Equal(float64(-1)))
Expect(sender.GetValue("TasksRunning").Value).To(Equal(float64(-1)))
Expect(sender.GetValue("TasksCompleted").Value).To(Equal(float64(-1)))
Expect(sender.GetValue("TasksResolving").Value).To(Equal(float64(-1)))
})
Context("when a Task is malformed", func() {
BeforeEach(func() {
etcdHelper.CreateMalformedTask(taskGuid)
})
_, err = sqlDB.CreateUnclaimedActualLRP(logger, &models.ActualLRPKey{ProcessGuid: processGuid, Index: 0, Domain: domain})
Expect(err).NotTo(HaveOccurred())
queryStr = `UPDATE actual_lrps SET evacuating = ?, expire_time = ? WHERE process_guid = ?`
if test_helpers.UsePostgres() {
queryStr = test_helpers.ReplaceQuestionMarks(queryStr)
}
_, err = db.Exec(queryStr, true, fakeClock.Now().UnixNano(), processGuid)
Expect(err).NotTo(HaveOccurred())
fakeClock.Increment(1 * time.Second)
})
Describe("general metrics", func() {
It("emits a metric for domains", func() {
sqlDB.ConvergeLRPs(logger, cellSet)
Expect(sender.GetValue("Domain." + freshDomain).Value).To(Equal(float64(1)))
})
It("emits metrics for lrps", func() {
convergenceLogger := lagertest.NewTestLogger("convergence")
sqlDB.ConvergeLRPs(convergenceLogger, cellSet)
Expect(sender.GetValue("LRPsDesired").Value).To(Equal(float64(38)))
Expect(sender.GetValue("LRPsClaimed").Value).To(Equal(float64(7)))
Expect(sender.GetValue("LRPsUnclaimed").Value).To(Equal(float64(32))) // 16 fresh + 5 expired + 11 evac
Expect(sender.GetValue("LRPsRunning").Value).To(Equal(float64(1)))
Expect(sender.GetValue("CrashedActualLRPs").Value).To(Equal(float64(2)))
Expect(sender.GetValue("CrashingDesiredLRPs").Value).To(Equal(float64(1)))
Consistently(convergenceLogger).ShouldNot(gbytes.Say("failed-.*"))
})
It("emits missing LRP metrics", func() {