Skip to content

Commit

Permalink
Log telemetry instance counts by plan even if a plan has no instances
Browse files Browse the repository at this point in the history 
[#167423837]

Co-authored-by: Derik Evangelista <devangelista@pivotal.io>
  • Loading branch information
@gabrielecipriano
2 people authored and gabrielecipriano committed Jul 24, 2019
1 parent 444c100 commit b0e052d
Show file tree
Hide file tree
Showing 5 changed files with 71 additions and 63 deletions.
2 changes: 1 addition & 1 deletion brokerinitiator/start.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,7 @@ func Initiate(conf config.Config,
logger.Fatalf("error building instance lister: %s", err)
}

telemetryLogger := telemetry.Build(conf.Broker.EnableTelemetry, conf.ServiceCatalog.Name, logger)
telemetryLogger := telemetry.Build(conf.Broker.EnableTelemetry, conf.ServiceCatalog, logger)

var onDemandBroker apiserver.CombinedBroker
onDemandBroker, err = broker.New(
Expand Down
15 changes: 10 additions & 5 deletions brokerinitiator/start_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,9 +53,12 @@ var _ = Describe("Start", func() {
},
},
ServiceCatalog: config.ServiceOffering{
ID: "service-id",
Name: "service-name",
Plans: []config.Plan{{ID: "plan-id", Name: "plan-name"}},
ID: "service-id",
Name: "service-name",
Plans: []config.Plan{
{ID: "a-plan-id", Name: "plan-name"},
{ID: "another-plan-id", Name: "another-plan-name"},
},
},
ServiceAdapter: config.ServiceAdapter{
Path: "test_assets/executable.sh",
Expand Down Expand Up @@ -85,8 +88,8 @@ var _ = Describe("Start", func() {

It("logs telemetry data when telemetry is enabled", func() {
fakeCloudFoundryClient.GetInstancesReturns([]cf.Instance{
{GUID: "123", PlanUniqueID: "plan-id"},
{GUID: "321", PlanUniqueID: "plan-id"},
{GUID: "123", PlanUniqueID: "a-plan-id"},
{GUID: "321", PlanUniqueID: "a-plan-id"},
}, nil)

go brokerinitiator.Initiate(
Expand All @@ -100,6 +103,8 @@ var _ = Describe("Start", func() {
)

Eventually(logBuffer).Should(gbytes.Say(fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances":{"total":2},"event":{"item":"broker","operation":"startup"}}`, brokerConfig.ServiceCatalog.Name)))
Eventually(logBuffer).Should(gbytes.Say(fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"a-plan-id","total":2},"event":{"item":"broker","operation":"startup"}}`, brokerConfig.ServiceCatalog.Name)))
Eventually(logBuffer).Should(gbytes.Say(fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"another-plan-id","total":0},"event":{"item":"broker","operation":"startup"}}`, brokerConfig.ServiceCatalog.Name)))
})

It("doesn't log telemetry data when telemetry is not enabled", func() {
Expand Down
19 changes: 15 additions & 4 deletions system_tests/lifecycle/all_lifecycle_tests/feature_toggled_tests.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,14 @@ func FeatureToggledLifecycleTest(
By("logging telemetry data at startup", func() {
stdoutLogs := bosh_helpers.GetBrokerLogs(brokerInfo.DeploymentName)
telemetryLogTotal := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances":{"total":0},"event":{"item":"broker","operation":"startup"}}`, brokerInfo.ServiceName)
telemetryLogPlanSmall := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":0},"event":{"item":"broker","operation":"startup"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-small")
telemetryLogPlanMedium := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":0},"event":{"item":"broker","operation":"startup"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-medium")
Expect(stdoutLogs).To(ContainSubstring(telemetryLogTotal))
Expect(stdoutLogs).To(SatisfyAll(
ContainSubstring(telemetryLogTotal),
ContainSubstring(telemetryLogPlanSmall),
ContainSubstring(telemetryLogPlanMedium),
))
})

By("creating a service", func() {
Expand All @@ -52,10 +59,12 @@ func FeatureToggledLifecycleTest(
stdoutLogs := bosh_helpers.GetBrokerLogs(brokerInfo.DeploymentName)

telemetryLogTotal := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances":{"total":1},"event":{"item":"instance","operation":"create"}}`, brokerInfo.ServiceName)
telemetryLogPerPlan := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":1},"event":{"item":"instance","operation":"create"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-small")
telemetryLogPlanSmall := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":1},"event":{"item":"instance","operation":"create"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-small")
telemetryLogPlanMedium := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":0},"event":{"item":"instance","operation":"create"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-medium")
Expect(stdoutLogs).To(SatisfyAll(
ContainSubstring(telemetryLogTotal),
ContainSubstring(telemetryLogPerPlan),
ContainSubstring(telemetryLogPlanSmall),
ContainSubstring(telemetryLogPlanMedium),
))
})

Expand Down Expand Up @@ -128,10 +137,12 @@ func FeatureToggledLifecycleTest(
stdoutLogs := bosh_helpers.GetBrokerLogs(brokerInfo.DeploymentName)
// total number of instances will not decrease since we are using CF to get the count and CF is not aware of the result of delete at the point of logging.
telemetryLogTotal := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances":{"total":1},"event":{"item":"instance","operation":"delete"}}`, brokerInfo.ServiceName)
telemetryLogPerPlan := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":1},"event":{"item":"instance","operation":"create"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-small")
telemetryLogPlanSmall := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":0},"event":{"item":"instance","operation":"delete"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-small")
telemetryLogPlanMedium := fmt.Sprintf(`"telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"%s","total":1},"event":{"item":"instance","operation":"delete"}}`, brokerInfo.ServiceName, brokerInfo.PlanID+"-medium")
Expect(stdoutLogs).To(SatisfyAll(
ContainSubstring(telemetryLogTotal),
ContainSubstring(telemetryLogPerPlan),
ContainSubstring(telemetryLogPlanSmall),
ContainSubstring(telemetryLogPlanMedium),
))
})
}
Expand Down
26 changes: 15 additions & 11 deletions telemetry/telemetry.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package telemetry
import (
"encoding/json"
"github.com/pivotal-cf/on-demand-service-broker/broker"
"github.com/pivotal-cf/on-demand-service-broker/config"
. "github.com/pivotal-cf/on-demand-service-broker/service"
"log"
"time"
Expand Down Expand Up @@ -46,25 +47,27 @@ type PerPlanInstancesLog struct {
}

type TelemetryLogger struct {
logger *log.Logger
brokerIdentifier string
timer Timer
logger *log.Logger
brokerIdentifier string
timer Timer
brokerServicePlans config.Plans
}

func Build(enableLogging bool, brokerIdentifier string, logger *log.Logger) broker.TelemetryLogger {
func Build(enableLogging bool, serviceOffering config.ServiceOffering, logger *log.Logger) broker.TelemetryLogger {
if !enableLogging {
logger.Printf("Telemetry logging is disabled.")
return &NoopTelemetryLogger{}
}

return NewTelemetryLogger(logger, brokerIdentifier, &RealTime{format: time.RFC3339})
return NewTelemetryLogger(logger, serviceOffering, &RealTime{format: time.RFC3339})
}

func NewTelemetryLogger(logger *log.Logger, brokerIdentifier string, timer Timer) broker.TelemetryLogger {
func NewTelemetryLogger(logger *log.Logger, serviceOffering config.ServiceOffering, timer Timer) broker.TelemetryLogger {
return &TelemetryLogger{
logger: logger,
brokerIdentifier: "odb-" + brokerIdentifier,
timer: timer,
logger: logger,
brokerIdentifier: "odb-" + serviceOffering.Name,
brokerServicePlans: serviceOffering.Plans,
timer: timer,
}
}

Expand Down Expand Up @@ -98,13 +101,14 @@ func (t *TelemetryLogger) logInstancesPerPlan(instances []Instance, event Event)
instancesPerPlan[instance.PlanUniqueID]++
}

for planID, count := range instancesPerPlan {
for _, plan := range t.brokerServicePlans {
count := instancesPerPlan[plan.ID]
planInstancesLog := PerPlanInstancesLog{
TelemetryTime: t.timer.Now(),
TelemetrySource: t.brokerIdentifier,
Event: event,
ServiceInstancesPerPlan: ServiceInstancesPerPlan{
PlanID: planID,
PlanID: plan.ID,
Total: count,
},
}
Expand Down
72 changes: 30 additions & 42 deletions telemetry/telemetry_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
. "github.com/onsi/gomega"
"github.com/onsi/gomega/gbytes"
"github.com/pivotal-cf/on-demand-service-broker/broker"
"github.com/pivotal-cf/on-demand-service-broker/config"
"github.com/pivotal-cf/on-demand-service-broker/loggerfactory"
"github.com/pivotal-cf/on-demand-service-broker/service"
"github.com/pivotal-cf/on-demand-service-broker/service/fakes"
Expand All @@ -16,79 +17,66 @@ import (

var _ = Describe("Telemetry", func() {
var (
instanceLister *fakes.FakeInstanceLister
logBuffer *gbytes.Buffer
loggerFactory *loggerfactory.LoggerFactory
brokerIdentifier string
telemetryTime *FakeTime
instanceLister *fakes.FakeInstanceLister
logBuffer *gbytes.Buffer
loggerFactory *loggerfactory.LoggerFactory
serviceOffering config.ServiceOffering
telemetryTime *FakeTime
planID1, planID2, planID3 string
)

Describe("Telemetry Logger enabled", func() {
var telemetryLogger broker.TelemetryLogger

BeforeEach(func() {
brokerIdentifier = "a-cute-broker"
planID1 = "plan-unique-id"
planID2 = "another-plan-unique-id"
planID3 = "plan-id-with-no-instances"

serviceOffering = config.ServiceOffering{
Name: "offering-name",
Plans: config.Plans{
{ID: planID1},
{ID: planID2},
{ID: planID3},
},
}
logBuffer = gbytes.NewBuffer()
loggerFactory = loggerfactory.New(logBuffer, brokerIdentifier, loggerfactory.Flags)
loggerFactory = loggerfactory.New(logBuffer, serviceOffering.Name, loggerfactory.Flags)

instanceLister = new(fakes.FakeInstanceLister)
telemetryTime = new(FakeTime)

telemetryLogger = telemetry.NewTelemetryLogger(loggerFactory.New(), brokerIdentifier, telemetryTime)
telemetryLogger = telemetry.NewTelemetryLogger(loggerFactory.New(), serviceOffering, telemetryTime)
})

Describe("LogInstances", func() {
It("logs telemetry about the total number of instances", func() {
instanceLister.InstancesReturns([]service.Instance{
{
GUID: "test-guid",
PlanUniqueID: "plan-id",
},
}, nil)
instanceLister.InstancesReturns([]service.Instance{{GUID: "test-guid"}}, nil)

fakeTime := "2006-01-02 15:04:05"
telemetryTime.NowReturns(fakeTime)

telemetryLogger.LogInstances(instanceLister, "broker", "startup")

Eventually(logBuffer).Should(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances":{"total":1},"event":{"item":"broker","operation":"startup"}}`, fakeTime, brokerIdentifier)))
Eventually(logBuffer).Should(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances":{"total":1},"event":{"item":"broker","operation":"startup"}}`, fakeTime, serviceOffering.Name)))
})

It("logs telemetry about the number of instances per plan", func() {
instanceLister.InstancesReturns([]service.Instance{
{
GUID: "test-guid-1",
PlanUniqueID: "plan-unique-id",
},
{
GUID: "test-guid-2",
PlanUniqueID: "plan-unique-id",
},
{
GUID: "test-guid-3",
PlanUniqueID: "another-plan-unique-id",
},
{GUID: "test-guid-1", PlanUniqueID: planID1},
{GUID: "test-guid-2", PlanUniqueID: planID1},
{GUID: "test-guid-3", PlanUniqueID: planID2},
}, nil)

fakeTime := "fake-timer"
telemetryTime.NowReturns(fakeTime)

telemetryLogger.LogInstances(instanceLister, "broker", "startup")

Expect(logBuffer).To(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"plan-unique-id","total":2},"event":{"item":"broker","operation":"startup"}}`, fakeTime, brokerIdentifier)))
Expect(logBuffer).To(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":"another-plan-unique-id","total":1},"event":{"item":"broker","operation":"startup"}}`, fakeTime, brokerIdentifier)))
})

It("logs only about total when there are no instances", func() {
instanceLister.InstancesReturns([]service.Instance{}, nil)

fakeTime := "fake-timer"
telemetryTime.NowReturns(fakeTime)

telemetryLogger.LogInstances(instanceLister, "not-relevant", "not-relevant")

Expect(logBuffer).To(gbytes.Say(fmt.Sprintf(`"service-instances":{"total":0}`)))
Expect(logBuffer).ToNot(gbytes.Say(fmt.Sprintf(`service-instances-per-plan`)))
Expect(logBuffer).To(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":%q,"total":2},"event":{"item":"broker","operation":"startup"}}`, fakeTime, serviceOffering.Name, planID1)))
Expect(logBuffer).To(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":%q,"total":1},"event":{"item":"broker","operation":"startup"}}`, fakeTime, serviceOffering.Name, planID2)))
Expect(logBuffer).To(gbytes.Say(fmt.Sprintf(`{"telemetry-time":"%s","telemetry-source":"odb-%s","service-instances-per-plan":{"plan-id":%q,"total":0},"event":{"item":"broker","operation":"startup"}}`, fakeTime, serviceOffering.Name, planID3)))
})

It("logs error log when it cant get the total number of instances", func() {
Expand Down Expand Up @@ -116,7 +104,7 @@ var _ = Describe("Telemetry", func() {

Describe("LogInstances", func() {
It("does not log telemetry", func() {
telemetryLogger = telemetry.Build(false, brokerIdentifier, loggerFactory.New())
telemetryLogger = telemetry.Build(false, serviceOffering, loggerFactory.New())

telemetryLogger.LogInstances(instanceLister, "not-relevant", "not-relevant")

Expand Down

0 comments on commit b0e052d

Please sign in to comment.