diff --git a/pkg/clients/array/flasharray/client.go b/pkg/clients/array/flasharray/client.go index 8608098d..ce78ae51 100644 --- a/pkg/clients/array/flasharray/client.go +++ b/pkg/clients/array/flasharray/client.go @@ -340,6 +340,14 @@ func (client *Client) performGet(url string, result interface{}) (interface{}, h if response.StatusCode() == 200 { return response.Result(), response.Header(), nil } + + // No error, and not a handled status code: let's print it for debugging + log.WithFields(log.Fields{ + "display_name": client.DisplayName, + "status_code": response.StatusCode(), + "url": url, + "body": response.String(), + }).Trace("Unhandled status code returned") } // Log we failed log.WithFields(log.Fields{ diff --git a/pkg/clients/array/flasharray/collector.go b/pkg/clients/array/flasharray/collector.go index ee880c7b..23cd7060 100644 --- a/pkg/clients/array/flasharray/collector.go +++ b/pkg/clients/array/flasharray/collector.go @@ -68,6 +68,8 @@ func (collector *Collector) GetAllArrayData() (*metrics.AllArrayData, error) { return nil, err // Can't mark the data without the array name } + log.WithField("display_name", collector.DisplayName).Trace("Array info collected, starting fetch goroutines") + // Fetch the opened, closed, and flagged alerts alertsChan := make(chan AlertResponseBundle) go collector.fetchAllAlerts(alertsChan) @@ -85,6 +87,7 @@ func (collector *Collector) GetAllArrayData() (*metrics.AllArrayData, error) { // we don't have a bit of metadata for it. arrayTags, err := collector.GetArrayTags() if err != nil { + log.WithError(err).WithField("display_name", collector.DisplayName).Warn("Failed to collect array tags, setting to empty map instead and proceeding") arrayTags = map[string]string{} } @@ -96,14 +99,18 @@ func (collector *Collector) GetAllArrayData() (*metrics.AllArrayData, error) { select { case message1 := <-alertsChan: alertResponseBundle = message1 + log.WithField("info", arrayInfo).Trace("Received alerts bundle") case message2 := <-arrayMetricsChan: arrayMetricsResponseBundle = message2 + log.WithField("info", arrayInfo).Trace("Received array metrics bundle") case message3 := <-objectCountChan: objectCountResponseBundle = message3 + log.WithField("info", arrayInfo).Trace("Received object counts bundle") } } timer.Stage("parse_responses") + log.WithField("display_name", collector.DisplayName).Trace("Received all metrics bundles, parsing and converting") // Record the current time for the metrics creationTime := time.Now().Unix() @@ -173,6 +180,8 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu return nil, err // Can't mark the data without the array name } + log.WithField("display_name", collector.DisplayName).Trace("Array info collected, beginning to fetch volume capacity metrics") + // Fetch the the various volume metrics timer.Stage("GetVolumeCapacityMetrics") capacityResponse, err := collector.Client.GetVolumeCapacityMetrics() @@ -181,6 +190,8 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu capacityResponse = []*VolumeCapacityMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch volume performance metrics") + timer.Stage("GetVolumePerformanceMetrics") performanceResponse, err := collector.Client.GetVolumePerformanceMetrics() if err != nil { @@ -188,6 +199,8 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu performanceResponse = []*VolumePerformanceMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch volume snapshot metrics") + timer.Stage("GetVolumeSnapshots") snapshotResponse, err := collector.Client.GetVolumeSnapshots() if err != nil { @@ -198,10 +211,12 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu // Fetch the array tags arrayTags, err := collector.GetArrayTags() if err != nil { + log.WithError(err).WithField("display_name", collector.DisplayName).Warn("Failed to collect array tags, setting to empty map instead and proceeding") arrayTags = map[string]string{} } timer.Stage("parse_responses") + log.WithField("display_name", collector.DisplayName).Trace("Fetched all metrics, parsing and converting") // Record the current time for the metrics creationTime := time.Now().Unix() @@ -312,18 +327,24 @@ func (collector *Collector) fetchAllAlerts(alertsChan chan AlertResponseBundle) timer := timing.NewStageTimer("flasharray.Collector.fetchAllAlerts", log.Fields{"display_name": collector.DisplayName}) defer timer.Finish() + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch flagged alerts") + alertsFlaggedResponse, err := collector.Client.GetAlertsFlagged() if err != nil { collector.logIncompleteData(err, "GetAlertsFlagged") alertsFlaggedResponse = []*AlertResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch alerts timeline") + alertsTimelineResponse, err := collector.Client.GetAlertsTimeline() if err != nil { collector.logIncompleteData(err, "GetAlertsTimeline") alertsTimelineResponse = []*AlertResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("All alerts fetched, returning bundle to channel") + responseBundle := AlertResponseBundle{ FlaggedResponse: alertsFlaggedResponse, TimelineResponse: alertsTimelineResponse, @@ -337,18 +358,24 @@ func (collector *Collector) fetchArrayMetrics(arrayMetricsChan chan ArrayMetrics timer := timing.NewStageTimer("flasharray.Collector.fetchArrayMetrics", log.Fields{"display_name": collector.DisplayName}) defer timer.Finish() + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array capacity metrics") + arrayCapacityResponse, err := collector.Client.GetArrayCapacityMetrics() if err != nil { collector.logIncompleteData(err, "GetArrayCapacityMetrics") arrayCapacityResponse = &ArrayCapacityMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array performance metrics") + arrayPerformanceResponse, err := collector.Client.GetArrayPerformanceMetrics() if err != nil { collector.logIncompleteData(err, "GetArrayPerformanceMetrics") arrayPerformanceResponse = &ArrayPerformanceMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("All array metrics fetched, returning bundle to channel") + responseBundle := ArrayMetricsResponseBundle{ CapacityMetricsResponse: arrayCapacityResponse, PerformanceMetricsResponse: arrayPerformanceResponse, @@ -362,23 +389,36 @@ func (collector *Collector) fetchObjectCounts(itemCountChan chan ObjectCountResp timer := timing.NewStageTimer("flasharray.Collector.fetchObjectCounts", log.Fields{"display_name": collector.DisplayName}) defer timer.Finish() + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array host count") + hostCount, err := collector.Client.GetHostCount() if err != nil { collector.logIncompleteData(err, "GetHostCount") } + + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array host count") + snapshotCount, err := collector.Client.GetVolumeSnapshotCount() if err != nil { collector.logIncompleteData(err, "GetSnapshotCount") } + + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array volume count") + volumeCount, err := collector.Client.GetVolumeCount() if err != nil { collector.logIncompleteData(err, "GetHostCount") } + + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array volume pending eradication count") + volumePendingEradicationCount, err := collector.Client.GetVolumePendingEradicationCount() if err != nil { collector.logIncompleteData(err, "GetVolumePendingEradicationCount") } + log.WithField("display_name", collector.DisplayName).Trace("Fetched all array object counts, returning bundle to channel") + responseBundle := ObjectCountResponseBundle{ HostCount: hostCount, SnapshotCount: snapshotCount, diff --git a/pkg/clients/array/flashblade/client.go b/pkg/clients/array/flashblade/client.go index b50f0f61..738e82f1 100644 --- a/pkg/clients/array/flashblade/client.go +++ b/pkg/clients/array/flashblade/client.go @@ -319,6 +319,14 @@ func (client *Client) performGet(url string, resultType interface{}) (interface{ if response.StatusCode() == 200 { return response.Result(), response.Header(), nil } + + // No error, and not a handled status code: let's print it for debugging + log.WithFields(log.Fields{ + "display_name": client.DisplayName, + "status_code": response.StatusCode(), + "url": url, + "body": response.String(), + }).Trace("Unhandled status code returned") } // Log we failed log.WithFields(log.Fields{ diff --git a/pkg/clients/array/flashblade/collector.go b/pkg/clients/array/flashblade/collector.go index 3d76e221..3d070a6b 100644 --- a/pkg/clients/array/flashblade/collector.go +++ b/pkg/clients/array/flashblade/collector.go @@ -68,6 +68,8 @@ func (collector *Collector) GetAllArrayData() (*metrics.AllArrayData, error) { return nil, err // Can't mark the data without the array name } + log.WithField("display_name", collector.DisplayName).Trace("Array info collected, starting fetch goroutines") + // Fetch all alerts alertsChan := make(chan []*AlertResponse) go collector.fetchAllAlerts(alertsChan) @@ -83,6 +85,7 @@ func (collector *Collector) GetAllArrayData() (*metrics.AllArrayData, error) { // Fetch the array tags arrayTags, err := collector.GetArrayTags() if err != nil { + log.WithError(err).WithField("display_name", collector.DisplayName).Warn("Failed to collect array tags, setting to empty map instead and proceeding") arrayTags = map[string]string{} } @@ -94,14 +97,18 @@ func (collector *Collector) GetAllArrayData() (*metrics.AllArrayData, error) { select { case message1 := <-alertsChan: alertResponses = message1 + log.WithField("info", arrayInfo).Trace("Received alerts bundle") case message2 := <-arrayMetricsChan: arrayMetricsResponseBundle = message2 + log.WithField("info", arrayInfo).Trace("Received array metrics bundle") case message3 := <-objectCountChan: objectCountResponseBundle = message3 + log.WithField("info", arrayInfo).Trace("Received object counts bundle") } } timer.Stage("parse_responses") + log.WithField("display_name", collector.DisplayName).Trace("Received all metrics bundles, parsing and converting") // Record the current time for the metrics creationTime := time.Now().Unix() @@ -167,6 +174,8 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu return nil, err // Can't mark the data without the array name } + log.WithField("display_name", collector.DisplayName).Trace("Array info collected, beginning to fetch filesystem capacity metrics") + // Get the various file system metrics timer.Stage("GetFileSystemCapacityMetrics") capacityResponse, err := collector.Client.GetFileSystemCapacityMetrics() @@ -175,12 +184,16 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu capacityResponse = []*FileSystemCapacityMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch filesystem performance metrics") + timer.Stage("GetFileSystemPerformanceMetrics") performanceResponse, err := collector.Client.GetFileSystemPerformanceMetrics(timeWindow) if err != nil { return nil, err // If we are missing performance data, it's too messy to tie things together } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch filesystem snapshot metrics") + timer.Stage("GetFileSystemSnapshots") snapshotsResponse, err := collector.Client.GetFileSystemSnapshots() if err != nil { @@ -191,10 +204,12 @@ func (collector *Collector) GetAllVolumeData(timeWindow int64) (*metrics.AllVolu // Fetch the array tags arrayTags, err := collector.GetArrayTags() if err != nil { + log.WithError(err).WithField("display_name", collector.DisplayName).Warn("Failed to collect array tags, setting to empty map instead and proceeding") arrayTags = map[string]string{} } timer.Stage("parse_responses") + log.WithField("display_name", collector.DisplayName).Trace("Fetched all metrics, parsing and converting") // Map the snapshots to their file systems to get a count volumeSnapshotCountMap := make(map[string]uint32) @@ -298,11 +313,14 @@ func (collector *Collector) fetchAllAlerts(alertsChan chan []*AlertResponse) { timer := timing.NewStageTimer("flashblade.Collector.fetchAllAlerts", log.Fields{"display_name": collector.DisplayName}) defer timer.Finish() + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch alerts") alertsResponse, err := collector.Client.GetAlerts() if err != nil { collector.logIncompleteData(err, "GetAlerts") alertsResponse = []*AlertResponse{} } + + log.WithField("display_name", collector.DisplayName).Trace("All alerts fetched, returning bundle to channel") alertsChan <- alertsResponse } @@ -311,18 +329,24 @@ func (collector *Collector) fetchArrayMetrics(arrayMetricsChan chan ArrayMetrics timer := timing.NewStageTimer("flashblade.Collector.fetchArrayMetrics", log.Fields{"display_name": collector.DisplayName}) defer timer.Finish() + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array capacity metrics") + capacityResponse, err := collector.Client.GetArrayCapacityMetrics() if err != nil { collector.logIncompleteData(err, "GetArrayCapacityMetrics") capacityResponse = &ArrayCapacityMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array performance metrics") + performanceResponse, err := collector.Client.GetArrayPerformanceMetrics() if err != nil { collector.logIncompleteData(err, "GetArrayPerformanceMetrics") performanceResponse = &ArrayPerformanceMetricsResponse{} } + log.WithField("display_name", collector.DisplayName).Trace("All array metrics fetched, returning bundle to channel") + responseBundle := ArrayMetricsResponseBundle{ CapacityMetricsResponse: capacityResponse, PerformanceMetricsResponse: performanceResponse, @@ -336,16 +360,22 @@ func (collector *Collector) fetchObjectCounts(itemCountChan chan ObjectCountResp timer := timing.NewStageTimer("flashblade.Collector.fetchObjectCounts", log.Fields{"display_name": collector.DisplayName}) defer timer.Finish() + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array filesystem count") + fileSystemCount, err := collector.Client.GetFileSystemCount() if err != nil { collector.logIncompleteData(err, "GetFileSystemCount") } + log.WithField("display_name", collector.DisplayName).Trace("Beginning to fetch array filesystem snapshot count") + snapshotCount, err := collector.Client.GetFileSystemSnapshotCount() if err != nil { collector.logIncompleteData(err, "GetFileSystemSnapshotCount") } + log.WithField("display_name", collector.DisplayName).Trace("Fetched all array object counts, returning bundle to channel") + responseBundle := ObjectCountResponseBundle{ FileSystemCount: fileSystemCount, SnapshotCount: snapshotCount, diff --git a/pkg/common/jobs/collect.go b/pkg/common/jobs/collect.go index 677ca6c3..d8b3e494 100644 --- a/pkg/common/jobs/collect.go +++ b/pkg/common/jobs/collect.go @@ -79,6 +79,7 @@ func (m *ArrayMetricCollectJob) Execute() { return } + log.WithField("array", *m.TargetArray).Trace("Connection/collector instantiated for array, collecting array data") timer.Stage("collecting") arrayMetrics, err := connection.GetAllArrayData() @@ -90,6 +91,8 @@ func (m *ArrayMetricCollectJob) Execute() { return } + log.WithField("array", *m.TargetArray).Trace("Array metrics collected, beginning to enqueue push jobs") + // Dispatch pushing jobs metricPushJob := &ArrayMetricPushJob{ Metric: arrayMetrics.ArrayMetric, @@ -148,6 +151,7 @@ func (m *ArrayVolumeMetricCollectJob) Execute() { return } + log.WithField("array", *m.TargetArray).Trace("Connection/collector instantiated for array, collecting volume data") timer.Stage("collecting") metrics, err := connection.GetAllVolumeData(m.TimeWindow) @@ -158,6 +162,7 @@ func (m *ArrayVolumeMetricCollectJob) Execute() { }).Error("Error collecting volume metrics") return } + log.WithField("array", *m.TargetArray).Trace("Volume metrics collected, beginning to enqueue push job") // Dispatch pushing job volumePushJob := &ArrayVolumeMetricPushJob{ diff --git a/pkg/common/timing/timer.go b/pkg/common/timing/timer.go index 8ae04a6a..ac95723d 100644 --- a/pkg/common/timing/timer.go +++ b/pkg/common/timing/timer.go @@ -44,6 +44,7 @@ func NewStageTimer(processName string, extraFields log.Fields) StageTimer { // Stage marks a delimiting point between sections of a timer func (s *StageTimer) Stage(stageName string) { s.marks = append(s.marks, step{stepName: stageName, stepTime: time.Now().UTC()}) + log.WithFields(s.extraFields).WithField("stage_name", stageName).Trace("StageTimer started new stage") } // Finish adds a stage called "finish" and logs all of the durations