Added more log lines to collectors to aid in deep debugging

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{

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,13 +190,17 @@ 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 {
 		collector.logIncompleteData(err, "GetVolumePerformanceMetrics")
 		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,

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{

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,

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{

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