feat(T1.2): implement structured logging and Prometheus metrics

- Add internal/logging package with zap-based structured JSON logging
- Support development (colored) and production (JSON) modes via ENVIRONMENT env var
- Add logging helpers: Info(), Error(), Warn(), Debug(), Fatal()
- Add field helpers: String(), Int(), Int64(), Err()
- Add internal/metrics package with 16 comprehensive Prometheus metrics
- Track workflows: starts, completions, duration by type/status
- Track activities: starts, completions, duration, retries by type
- Track LLM calls: total calls and latency by model
- Track git operations: total and duration by operation type
- Track judge decisions: decisions by type
- Track Temporal errors: connection errors by type
- Track cache efficiency: hits and misses by cache type
- Track tasks in progress: gauge metric by task type
- Metrics exported on /metrics endpoint (Prometheus text format)
- Integrate structured logging in cmd/worker and cmd/starter
- Replace all log.Printf/log.Fatalf with structured logging
- Add /metrics endpoint to health check server
- 8/8 logging tests passing, 13/13 metrics tests passing
- All verification criteria met

Dependencies added:
- go.uber.org/zap v1.28.0 (structured logging)
- github.com/prometheus/client_golang v1.24.1 (metrics export)

Closes T1.2
This commit is contained in:
Test
2026-08-23 16:33:49 -07:00
parent 90fcd6a9df
commit 59a1eeed85
11 changed files with 808 additions and 66 deletions
+4
View File
@@ -3,6 +3,8 @@ package health
import (
"encoding/json"
"net/http"
"github.com/prometheus/client_golang/prometheus/promhttp"
)
// Handler provides HTTP endpoints for health checks
@@ -22,6 +24,8 @@ func (h *Handler) RegisterRoutes(mux *http.ServeMux) {
mux.HandleFunc("/health", h.handleHealth)
mux.HandleFunc("/health/live", h.handleLive)
mux.HandleFunc("/health/ready", h.handleReady)
// Prometheus metrics endpoint
mux.Handle("/metrics", promhttp.Handler())
}
// handleHealth returns full health report
+97
View File
@@ -0,0 +1,97 @@
package logging
import (
"os"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
var logger *zap.Logger
// InitLogger initializes the global logger
func InitLogger() error {
var config zap.Config
// Use pretty config in development, JSON in production
if os.Getenv("ENVIRONMENT") == "production" {
config = zap.NewProductionConfig()
} else {
config = zap.NewDevelopmentConfig()
config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
}
var err error
logger, err = config.Build()
if err != nil {
return err
}
return nil
}
// GetLogger returns the global logger
func GetLogger() *zap.Logger {
if logger == nil {
logger, _ = zap.NewProduction()
}
return logger
}
// Info logs an info message
func Info(message string, fields ...zap.Field) {
GetLogger().Info(message, fields...)
}
// Error logs an error message
func Error(message string, fields ...zap.Field) {
GetLogger().Error(message, fields...)
}
// Warn logs a warning message
func Warn(message string, fields ...zap.Field) {
GetLogger().Warn(message, fields...)
}
// Debug logs a debug message
func Debug(message string, fields ...zap.Field) {
GetLogger().Debug(message, fields...)
}
// Fatal logs a fatal message and exits
func Fatal(message string, fields ...zap.Field) {
GetLogger().Fatal(message, fields...)
}
// Sync flushes any buffered log entries
func Sync() error {
if logger != nil {
return logger.Sync()
}
return nil
}
// With returns a child logger with additional fields
func With(fields ...zap.Field) *zap.Logger {
return GetLogger().With(fields...)
}
// String is a helper for creating a string field
func String(key, value string) zap.Field {
return zap.String(key, value)
}
// Int is a helper for creating an int field
func Int(key string, value int) zap.Field {
return zap.Int(key, value)
}
// Int64 is a helper for creating an int64 field
func Int64(key string, value int64) zap.Field {
return zap.Int64(key, value)
}
// Error field helper
func Err(err error) zap.Field {
return zap.Error(err)
}
+74
View File
@@ -0,0 +1,74 @@
package logging
import (
"testing"
"github.com/stretchr/testify/assert"
)
func TestInitLogger(t *testing.T) {
err := InitLogger()
assert.NoError(t, err)
}
func TestGetLogger(t *testing.T) {
lg := GetLogger()
assert.NotNil(t, lg)
}
func TestStringField(t *testing.T) {
field := String("key", "value")
assert.NotNil(t, field)
assert.Equal(t, "key", field.Key)
}
func TestIntField(t *testing.T) {
field := Int("counter", 42)
assert.NotNil(t, field)
assert.Equal(t, "counter", field.Key)
}
func TestInt64Field(t *testing.T) {
field := Int64("bignum", 9223372036854775807)
assert.NotNil(t, field)
assert.Equal(t, "bignum", field.Key)
}
func TestErrorField(t *testing.T) {
err := assert.AnError
field := Err(err)
assert.NotNil(t, field)
assert.Equal(t, "error", field.Key)
}
// Note: TestSync is omitted because zap.Sync() may fail on stderr in test environment
// This is expected behavior and doesn't affect production use
func TestWith(t *testing.T) {
InitLogger()
lg := With(String("test", "value"))
assert.NotNil(t, lg)
}
// TestLoggingFunctions tests that logging functions don't panic
func TestLoggingFunctions(t *testing.T) {
InitLogger()
defer Sync()
// These should not panic
assert.NotPanics(t, func() {
Info("test info", String("field", "value"))
})
assert.NotPanics(t, func() {
Warn("test warn", String("field", "value"))
})
assert.NotPanics(t, func() {
Debug("test debug", String("field", "value"))
})
assert.NotPanics(t, func() {
Error("test error", String("field", "value"))
})
}
+220
View File
@@ -0,0 +1,220 @@
package metrics
import (
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto"
)
// WorkflowMetrics holds all workflow-related prometheus metrics
var (
// WorkflowExecutionsStarted tracks total workflows started
WorkflowExecutionsStarted = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_workflow_executions_started_total",
Help: "Total number of workflow executions started",
},
[]string{"workflow_type"},
)
// WorkflowExecutionsCompleted tracks total workflows completed
WorkflowExecutionsCompleted = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_workflow_executions_completed_total",
Help: "Total number of workflow executions completed",
},
[]string{"workflow_type", "status"},
)
// WorkflowDuration tracks workflow execution duration
WorkflowDuration = promauto.NewHistogramVec(
prometheus.HistogramOpts{
Name: "poimen_workflow_duration_seconds",
Help: "Workflow execution duration in seconds",
Buckets: prometheus.DefBuckets,
},
[]string{"workflow_type"},
)
// ActivityExecutionsStarted tracks total activities started
ActivityExecutionsStarted = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_activity_executions_started_total",
Help: "Total number of activity executions started",
},
[]string{"activity_type"},
)
// ActivityExecutionsCompleted tracks total activities completed
ActivityExecutionsCompleted = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_activity_executions_completed_total",
Help: "Total number of activity executions completed",
},
[]string{"activity_type", "status"},
)
// ActivityDuration tracks activity execution duration
ActivityDuration = promauto.NewHistogramVec(
prometheus.HistogramOpts{
Name: "poimen_activity_duration_seconds",
Help: "Activity execution duration in seconds",
Buckets: prometheus.DefBuckets,
},
[]string{"activity_type"},
)
// ActivityRetries tracks activity retries
ActivityRetries = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_activity_retries_total",
Help: "Total number of activity retries",
},
[]string{"activity_type"},
)
// LLMAPICallsTotal tracks LLM API calls
LLMAPICallsTotal = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_llm_api_calls_total",
Help: "Total number of LLM API calls",
},
[]string{"model_id", "status"},
)
// LLMAPILatency tracks LLM API call latency
LLMAPILatency = promauto.NewHistogramVec(
prometheus.HistogramOpts{
Name: "poimen_llm_api_latency_seconds",
Help: "LLM API call latency in seconds",
Buckets: prometheus.DefBuckets,
},
[]string{"model_id"},
)
// GitOperationsTotal tracks git operations
GitOperationsTotal = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_git_operations_total",
Help: "Total number of git operations",
},
[]string{"operation", "status"},
)
// GitOperationsDuration tracks git operation duration
GitOperationsDuration = promauto.NewHistogramVec(
prometheus.HistogramOpts{
Name: "poimen_git_operations_duration_seconds",
Help: "Git operation duration in seconds",
Buckets: prometheus.DefBuckets,
},
[]string{"operation"},
)
// TasksInProgress tracks current tasks in progress
TasksInProgress = promauto.NewGaugeVec(
prometheus.GaugeOpts{
Name: "poimen_tasks_in_progress",
Help: "Current number of tasks in progress",
},
[]string{"task_type"},
)
// JudgeDecisionsTotal tracks judge decisions
JudgeDecisionsTotal = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_judge_decisions_total",
Help: "Total number of judge decisions",
},
[]string{"decision"},
)
// TemporalConnectionErrors tracks Temporal connection errors
TemporalConnectionErrors = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_temporal_connection_errors_total",
Help: "Total number of Temporal connection errors",
},
[]string{"error_type"},
)
// CacheHitRate tracks cache hit/miss ratio
CacheHits = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_cache_hits_total",
Help: "Total number of cache hits",
},
[]string{"cache_type"},
)
CacheMisses = promauto.NewCounterVec(
prometheus.CounterOpts{
Name: "poimen_cache_misses_total",
Help: "Total number of cache misses",
},
[]string{"cache_type"},
)
)
// RecordWorkflowStarted records a workflow execution start
func RecordWorkflowStarted(workflowType string) {
WorkflowExecutionsStarted.WithLabelValues(workflowType).Inc()
}
// RecordWorkflowCompleted records a workflow execution completion
func RecordWorkflowCompleted(workflowType, status string, durationSeconds float64) {
WorkflowExecutionsCompleted.WithLabelValues(workflowType, status).Inc()
WorkflowDuration.WithLabelValues(workflowType).Observe(durationSeconds)
}
// RecordActivityStarted records an activity execution start
func RecordActivityStarted(activityType string) {
ActivityExecutionsStarted.WithLabelValues(activityType).Inc()
}
// RecordActivityCompleted records an activity execution completion
func RecordActivityCompleted(activityType, status string, durationSeconds float64) {
ActivityExecutionsCompleted.WithLabelValues(activityType, status).Inc()
ActivityDuration.WithLabelValues(activityType).Observe(durationSeconds)
}
// RecordActivityRetry records an activity retry
func RecordActivityRetry(activityType string) {
ActivityRetries.WithLabelValues(activityType).Inc()
}
// RecordLLMAPICall records an LLM API call
func RecordLLMAPICall(modelID, status string, latencySeconds float64) {
LLMAPICallsTotal.WithLabelValues(modelID, status).Inc()
LLMAPILatency.WithLabelValues(modelID).Observe(latencySeconds)
}
// RecordGitOperation records a git operation
func RecordGitOperation(operation, status string, durationSeconds float64) {
GitOperationsTotal.WithLabelValues(operation, status).Inc()
GitOperationsDuration.WithLabelValues(operation).Observe(durationSeconds)
}
// RecordJudgeDecision records a judge decision
func RecordJudgeDecision(decision string) {
JudgeDecisionsTotal.WithLabelValues(decision).Inc()
}
// RecordTemporalConnectionError records a Temporal connection error
func RecordTemporalConnectionError(errorType string) {
TemporalConnectionErrors.WithLabelValues(errorType).Inc()
}
// RecordCacheHit records a cache hit
func RecordCacheHit(cacheType string) {
CacheHits.WithLabelValues(cacheType).Inc()
}
// RecordCacheMiss records a cache miss
func RecordCacheMiss(cacheType string) {
CacheMisses.WithLabelValues(cacheType).Inc()
}
// UpdateTasksInProgress updates the current number of tasks in progress
func UpdateTasksInProgress(taskType string, count float64) {
TasksInProgress.WithLabelValues(taskType).Set(count)
}
+111
View File
@@ -0,0 +1,111 @@
package metrics
import (
"testing"
"github.com/stretchr/testify/assert"
)
func TestRecordWorkflowStarted(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordWorkflowStarted("TestWorkflow")
})
}
func TestRecordWorkflowCompleted(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordWorkflowCompleted("TestWorkflow", "success", 1.5)
})
}
func TestRecordActivityStarted(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordActivityStarted("TestActivity")
})
}
func TestRecordActivityCompleted(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordActivityCompleted("TestActivity", "success", 0.5)
})
}
func TestRecordActivityRetry(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordActivityRetry("TestActivity")
})
}
func TestRecordLLMAPICall(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordLLMAPICall("claude-opus", "success", 2.0)
})
}
func TestRecordGitOperation(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordGitOperation("clone", "success", 5.0)
})
}
func TestRecordJudgeDecision(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordJudgeDecision("approve")
})
}
func TestRecordTemporalConnectionError(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordTemporalConnectionError("connection_timeout")
})
}
func TestRecordCacheHit(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordCacheHit("llm_response")
})
}
func TestRecordCacheMiss(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
RecordCacheMiss("llm_response")
})
}
func TestUpdateTasksInProgress(t *testing.T) {
// Should not panic
assert.NotPanics(t, func() {
UpdateTasksInProgress("T0", 5.0)
})
}
// TestMetricsExist verifies all metrics are registered
func TestMetricsExist(t *testing.T) {
assert.NotNil(t, WorkflowExecutionsStarted)
assert.NotNil(t, WorkflowExecutionsCompleted)
assert.NotNil(t, WorkflowDuration)
assert.NotNil(t, ActivityExecutionsStarted)
assert.NotNil(t, ActivityExecutionsCompleted)
assert.NotNil(t, ActivityDuration)
assert.NotNil(t, ActivityRetries)
assert.NotNil(t, LLMAPICallsTotal)
assert.NotNil(t, LLMAPILatency)
assert.NotNil(t, GitOperationsTotal)
assert.NotNil(t, GitOperationsDuration)
assert.NotNil(t, TasksInProgress)
assert.NotNil(t, JudgeDecisionsTotal)
assert.NotNil(t, TemporalConnectionErrors)
assert.NotNil(t, CacheHits)
assert.NotNil(t, CacheMisses)
}