diff --git a/.gitignore b/.gitignore index 6922ba8..f0d815e 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,5 @@ # Binaries -hal +/hal # Test coverage cover.out @@ -7,3 +7,11 @@ cover.out # Databases sqlite.db* test-results.json + +# SQLite database files and related WAL/SHM files +*.db +*.db-wal +*.db-shm +**/*.db +**/*.db-wal +**/*.db-shm diff --git a/cmd/hal/commands/logs.go b/cmd/hal/commands/logs.go new file mode 100644 index 0000000..09da939 --- /dev/null +++ b/cmd/hal/commands/logs.go @@ -0,0 +1,149 @@ +package commands + +import ( + "fmt" + "strconv" + "strings" + "time" + + "github.com/dansimau/hal/store" + "github.com/spf13/cobra" +) + +// NewLogsCmd creates the logs command +func NewLogsCmd() *cobra.Command { + var fromTime string + var toTime string + var lastDuration string + var entityID string + + cmd := &cobra.Command{ + Use: "logs", + Aliases: []string{"log"}, + Short: "Display HAL log entries", + Long: `Display log entries from the HAL automation system. +Shows logs in chronological order with optional filtering by time range or entity.`, + Example: ` hal logs # Show all logs in chronological order + hal logs --from "2024-01-01" # Show logs from a specific date + hal logs --to "2024-01-31" # Show logs up to a specific date + hal logs --from "2024-01-01" --to "2024-01-31" # Show logs in date range + hal logs --last 5m # Show logs from last 5 minutes + hal logs --last 1h # Show logs from last 1 hour + hal logs --last 1d # Show logs from last 1 day + hal logs --entity-id "light.kitchen" # Show logs for specific entity`, + RunE: func(cmd *cobra.Command, args []string) error { + return runLogsCommand(fromTime, toTime, lastDuration, entityID) + }, + } + + cmd.Flags().StringVar(&fromTime, "from", "", "Start time for filtering logs (YYYY-MM-DD or YYYY-MM-DD HH:MM:SS)") + cmd.Flags().StringVar(&toTime, "to", "", "End time for filtering logs (YYYY-MM-DD or YYYY-MM-DD HH:MM:SS)") + cmd.Flags().StringVar(&lastDuration, "last", "", "Show logs from last duration (e.g., 5m, 1h, 2d)") + cmd.Flags().StringVar(&entityID, "entity-id", "", "Filter logs by entity ID") + + return cmd +} + +func runLogsCommand(fromTime, toTime, lastDuration, entityID string) error { + // Open database connection using default path + db, err := store.Open("sqlite.db") + if err != nil { + return fmt.Errorf("failed to open database: %w", err) + } + + // Build query with filters + query := db.Model(&store.Log{}) + + // Apply time filters + if lastDuration != "" { + duration, err := parseDuration(lastDuration) + if err != nil { + return fmt.Errorf("invalid duration format: %w", err) + } + since := time.Now().Add(-duration) + query = query.Where("timestamp > ?", since) + } else { + if fromTime != "" { + from, err := parseTime(fromTime) + if err != nil { + return fmt.Errorf("invalid from time format: %w", err) + } + query = query.Where("timestamp >= ?", from) + } + if toTime != "" { + to, err := parseTime(toTime) + if err != nil { + return fmt.Errorf("invalid to time format: %w", err) + } + query = query.Where("timestamp <= ?", to) + } + } + + // Apply entity filter + if entityID != "" { + query = query.Where("entity_id = ?", entityID) + } + + // Execute query and get results + var logs []store.Log + if err := query.Order("timestamp ASC").Find(&logs).Error; err != nil { + return fmt.Errorf("failed to query logs: %w", err) + } + + // Print results + return printLogs(logs) +} + +func parseDuration(durationStr string) (time.Duration, error) { + // Handle common duration formats like 5m, 1h, 2d + if strings.HasSuffix(durationStr, "d") { + days, err := strconv.Atoi(strings.TrimSuffix(durationStr, "d")) + if err != nil { + return 0, err + } + return time.Duration(days) * 24 * time.Hour, nil + } + + // For other formats (m, h, s), use standard time.ParseDuration + return time.ParseDuration(durationStr) +} + +func parseTime(timeStr string) (time.Time, error) { + // Try different time formats + formats := []string{ + "2006-01-02 15:04:05", + "2006-01-02 15:04", + "2006-01-02", + } + + for _, format := range formats { + if t, err := time.Parse(format, timeStr); err == nil { + return t, nil + } + } + + return time.Time{}, fmt.Errorf("unable to parse time: %s (expected formats: YYYY-MM-DD, YYYY-MM-DD HH:MM, or YYYY-MM-DD HH:MM:SS)", timeStr) +} + +func printLogs(logs []store.Log) error { + if len(logs) == 0 { + fmt.Println("No logs found") + return nil + } + + // Print logs without header to look like a log file + for _, log := range logs { + entityIDStr := "" + if log.EntityID != nil { + entityIDStr = fmt.Sprintf(" [%s]", *log.EntityID) + } + + fmt.Printf("%s%s %s\n", + log.Timestamp.Format("2006-01-02 15:04:05"), + entityIDStr, + log.LogText, + ) + } + + return nil +} \ No newline at end of file diff --git a/cmd/hal/main.go b/cmd/hal/main.go index 1d62280..8226a3a 100644 --- a/cmd/hal/main.go +++ b/cmd/hal/main.go @@ -22,4 +22,5 @@ func main() { func init() { rootCmd.AddCommand(commands.NewStatsCmd()) + rootCmd.AddCommand(commands.NewLogsCmd()) } \ No newline at end of file diff --git a/connection.go b/connection.go index 88c5293..d27b264 100644 --- a/connection.go +++ b/connection.go @@ -2,12 +2,12 @@ package hal import ( "fmt" - "log/slog" "os" "sync" "time" "github.com/dansimau/hal/hassws" + "github.com/dansimau/hal/logging" "github.com/dansimau/hal/metrics" "github.com/dansimau/hal/perf" "github.com/dansimau/hal/store" @@ -29,8 +29,9 @@ type Connection struct { // Lock to serialize state updates and ensure automations fire in order. mutex sync.RWMutex - homeAssistant *hassws.Client - metricsService *metrics.Service + homeAssistant *hassws.Client + metricsService *metrics.Service + loggingService *logging.Service *SunTimes } @@ -58,10 +59,11 @@ func NewConnection(cfg Config) *Connection { }) return &Connection{ - config: cfg, - db: db, - homeAssistant: api, - metricsService: metrics.NewService(db), + config: cfg, + db: db, + homeAssistant: api, + metricsService: metrics.NewService(db), + loggingService: logging.NewService(db), automations: make(map[string][]Automation), entities: make(map[string]EntityInterface), @@ -82,7 +84,7 @@ func (h *Connection) FindEntities(v any) { // RegisterAutomations registers automations and binds them to the relevant entities. func (h *Connection) RegisterAutomations(automations ...Automation) { for _, automation := range automations { - slog.Info("Registering automation", "Name", automation.Name()) + h.loggingService.Info("Registering automation", nil, "Name", automation.Name()) for _, entity := range automation.Entities() { h.automations[entity.GetID()] = append(h.automations[entity.GetID()], automation) @@ -93,7 +95,8 @@ func (h *Connection) RegisterAutomations(automations ...Automation) { // RegisterEntities registers entities and binds them to the connection. func (h *Connection) RegisterEntities(entities ...EntityInterface) { for _, entity := range entities { - slog.Info("Registering entity", "EntityID", entity.GetID()) + entityID := entity.GetID() + h.loggingService.Info("Registering entity", &entityID, "EntityID", entityID) entity.BindConnection(h) h.entities[entity.GetID()] = entity @@ -106,8 +109,9 @@ func (h *Connection) RegisterEntities(entities ...EntityInterface) { // Start connects to the Home Assistant websocket and starts listening for events. func (h *Connection) Start() error { - // Start metrics service + // Start services h.metricsService.Start() + h.loggingService.Start() if err := h.homeAssistant.Connect(); err != nil { return err @@ -126,12 +130,13 @@ func (h *Connection) Start() error { func (h *Connection) Close() { h.metricsService.Stop() + h.loggingService.Stop() h.homeAssistant.Close() } func (h *Connection) syncStates() error { defer perf.Timer(func(timeTaken time.Duration) { - slog.Info("Initial state sync complete", "duration", timeTaken) + h.loggingService.Info("Initial state sync complete", nil, "duration", timeTaken) })() states, err := h.homeAssistant.GetStates() @@ -145,7 +150,7 @@ func (h *Connection) syncStates() error { continue } - slog.Debug("Setting initial state", "EntityID", state.EntityID, "State", state) + h.loggingService.Debug("Setting initial state", &state.EntityID, "EntityID", state.EntityID, "State", state) entity.SetState(state) } @@ -157,7 +162,7 @@ func (h *Connection) syncStates() error { // entity and fire any automations listening for state changes to this entity. func (h *Connection) StateChangeEvent(event hassws.EventMessage) { defer perf.Timer(func(timeTaken time.Duration) { - slog.Debug("Tick processing time", "duration", timeTaken) + h.loggingService.Debug("Tick processing time", &event.Event.EventData.EntityID, "duration", timeTaken) // Record tick processing time metric h.metricsService.RecordTimer(store.MetricTypeTickProcessingTime, timeTaken, event.Event.EventData.EntityID, "") })() @@ -167,14 +172,12 @@ func (h *Connection) StateChangeEvent(event hassws.EventMessage) { entity, ok := h.entities[event.Event.EventData.EntityID] if !ok { - slog.Debug("Entity not registered", "EntityID", event.Event.EventData.EntityID) + h.loggingService.Debug("Entity not registered", &event.Event.EventData.EntityID, "EntityID", event.Event.EventData.EntityID) return } - slog.Debug("State changed for", - "EntityID", event.Event.EventData.EntityID, - ) + h.loggingService.Debug("State changed for", &event.Event.EventData.EntityID, "EntityID", event.Event.EventData.EntityID) fmt.Fprintf(os.Stderr, "Diff:\n%s\n", cmp.Diff(event.Event.EventData.OldState, event.Event.EventData.NewState)) @@ -193,14 +196,14 @@ func (h *Connection) StateChangeEvent(event hassws.EventMessage) { // Prevent loops by not running automations that originate from hal if event.Event.Context.UserID == h.config.HomeAssistant.UserID { - slog.Debug("Skipping automation from own action", "EntityID", event.Event.EventData.EntityID) + h.loggingService.Debug("Skipping automation from own action", &event.Event.EventData.EntityID, "EntityID", event.Event.EventData.EntityID) return } // Dispatch automations for _, automation := range h.automations[event.Event.EventData.EntityID] { - slog.Info("Running automation", "name", automation.Name()) + h.loggingService.Info("Running automation", &event.Event.EventData.EntityID, "name", automation.Name()) // Record automation triggered metric h.metricsService.RecordCounter(store.MetricTypeAutomationTriggered, event.Event.EventData.EntityID, automation.Name()) automation.Action(entity) diff --git a/entity_button.go b/entity_button.go index ea94cc2..414d671 100644 --- a/entity_button.go +++ b/entity_button.go @@ -1,7 +1,6 @@ package hal import ( - "log/slog" "time" ) @@ -39,7 +38,8 @@ func (b *Button) Action(_ EntityInterface) { b.pressedTimes = 1 } - slog.Info("Button pressed", "entity", b.GetID(), "times", b.pressedTimes) + entityID := b.GetID() + b.connection.loggingService.Info("Button pressed", &entityID, "entity", entityID, "times", b.pressedTimes) b.lastPressed = time.Now() } diff --git a/entity_input_boolean.go b/entity_input_boolean.go index 532d6cf..83d6ea6 100644 --- a/entity_input_boolean.go +++ b/entity_input_boolean.go @@ -24,13 +24,15 @@ func (s *InputBoolean) IsOn() bool { } func (s *InputBoolean) TurnOn(attributes ...map[string]any) error { + entityID := s.GetID() if s.connection == nil { - slog.Error("InputBoolean not registered", "entity", s.GetID()) + // Use slog directly when connection is nil + slog.Error("InputBoolean not registered", "entity", entityID) return ErrEntityNotRegistered } - slog.Debug("Turning on virtual switch", "entity", s.GetID()) + s.connection.loggingService.Debug("Turning on virtual switch", &entityID, "entity", entityID) data := map[string]any{ "entity_id": []string{s.GetID()}, @@ -49,20 +51,23 @@ func (s *InputBoolean) TurnOn(attributes ...map[string]any) error { Data: data, }) if err != nil { - slog.Error("Error turning on virtual switch", "entity", s.GetID(), "error", err) + entityID := s.GetID() + s.connection.loggingService.Error("Error turning on virtual switch", &entityID, "entity", entityID, "error", err) } return err } func (s *InputBoolean) TurnOff() error { + entityID := s.GetID() if s.connection == nil { - slog.Error("InputBoolean not registered", "entity", s.GetID()) + // Use slog directly when connection is nil + slog.Error("InputBoolean not registered", "entity", entityID) return ErrEntityNotRegistered } - slog.Info("Turning off virtual switch", "entity", s.GetID()) + s.connection.loggingService.Info("Turning off virtual switch", &entityID, "entity", entityID) _, err := s.connection.CallService(hassws.CallServiceRequest{ Type: hassws.MessageTypeCallService, @@ -73,7 +78,8 @@ func (s *InputBoolean) TurnOff() error { }, }) if err != nil { - slog.Error("Error turning off virtual switch", "entity", s.GetID(), "error", err) + entityID := s.GetID() + s.connection.loggingService.Error("Error turning off virtual switch", &entityID, "entity", entityID, "error", err) } return err diff --git a/entity_light.go b/entity_light.go index 2bae032..ec95c42 100644 --- a/entity_light.go +++ b/entity_light.go @@ -39,13 +39,15 @@ func (l *Light) IsOn() bool { } func (l *Light) TurnOn(attributes ...map[string]any) error { + entityID := l.GetID() if l.connection == nil { - slog.Error("Light not registered", "entity", l.GetID()) + // Use slog directly when connection is nil + slog.Error("Light not registered", "entity", entityID) return ErrEntityNotRegistered } - slog.Debug("Turning on light", "entity", l.GetID()) + l.connection.loggingService.Debug("Turning on light", &entityID, "entity", entityID) data := map[string]any{ "entity_id": []string{l.GetID()}, @@ -64,7 +66,8 @@ func (l *Light) TurnOn(attributes ...map[string]any) error { Data: data, }) if err != nil { - slog.Error("Error turning on light", "entity", l.GetID(), "error", err) + entityID := l.GetID() + l.connection.loggingService.Error("Error turning on light", &entityID, "entity", entityID, "error", err) return err } @@ -73,13 +76,15 @@ func (l *Light) TurnOn(attributes ...map[string]any) error { } func (l *Light) TurnOff() error { + entityID := l.GetID() if l.connection == nil { - slog.Error("Light not registered", "entity", l.GetID()) + // Use slog directly when connection is nil + slog.Error("Light not registered", "entity", entityID) return ErrEntityNotRegistered } - slog.Info("Turning off light", "entity", l.GetID()) + l.connection.loggingService.Info("Turning off light", &entityID, "entity", entityID) data := map[string]any{ "entity_id": []string{l.GetID()}, @@ -92,7 +97,8 @@ func (l *Light) TurnOff() error { Data: data, }) if err != nil { - slog.Error("Error turning off light", "entity", l.GetID(), "error", err) + entityID := l.GetID() + l.connection.loggingService.Error("Error turning off light", &entityID, "entity", entityID, "error", err) return err } diff --git a/go.mod b/go.mod index 8cca60d..7123bbd 100644 --- a/go.mod +++ b/go.mod @@ -10,6 +10,7 @@ require ( github.com/google/go-cmp v0.5.9 github.com/gorilla/websocket v1.5.3 github.com/nathan-osman/go-sunrise v1.1.0 + github.com/spf13/cobra v1.9.1 gopkg.in/yaml.v3 v3.0.1 gorm.io/gorm v1.25.12 gotest.tools/v3 v3.5.1 @@ -24,7 +25,6 @@ require ( github.com/jinzhu/now v1.1.5 // indirect github.com/mattn/go-isatty v0.0.17 // indirect github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect - github.com/spf13/cobra v1.9.1 // indirect github.com/spf13/pflag v1.0.6 // indirect golang.org/x/sys v0.7.0 // indirect golang.org/x/text v0.14.0 // indirect diff --git a/logging/service.go b/logging/service.go new file mode 100644 index 0000000..573016a --- /dev/null +++ b/logging/service.go @@ -0,0 +1,121 @@ +package logging + +import ( + "log/slog" + "time" + + "github.com/dansimau/hal/store" + "gorm.io/gorm" +) + +// Service handles logging to both console and database +type Service struct { + db *gorm.DB + pruneInterval time.Duration // How often to prune old logs (default: daily) + retentionTime time.Duration // How long to keep logs (default: 1 month) + stopChan chan struct{} +} + +// NewService creates a new logging service +func NewService(db *gorm.DB) *Service { + return &Service{ + db: db, + pruneInterval: 24 * time.Hour, // Prune daily + retentionTime: 30 * 24 * time.Hour, // Keep 1 month of logs + stopChan: make(chan struct{}), + } +} + +// Start begins the log pruning goroutine +func (s *Service) Start() { + go s.pruneLogs() + slog.Info("Logging service started") +} + +// Stop stops the logging service +func (s *Service) Stop() { + close(s.stopChan) + slog.Info("Logging service stopped") +} + +// Info logs an info message to both console and database +func (s *Service) Info(msg string, entityID *string, args ...any) { + // Log to console using slog + if entityID != nil { + args = append([]any{"entity_id", *entityID}, args...) + } + slog.Info(msg, args...) + + // Log to database + s.logToDatabase(msg, entityID) +} + +// Error logs an error message to both console and database +func (s *Service) Error(msg string, entityID *string, args ...any) { + // Log to console using slog + if entityID != nil { + args = append([]any{"entity_id", *entityID}, args...) + } + slog.Error(msg, args...) + + // Log to database + s.logToDatabase(msg, entityID) +} + +// Debug logs a debug message to both console and database +func (s *Service) Debug(msg string, entityID *string, args ...any) { + // Log to console using slog + if entityID != nil { + args = append([]any{"entity_id", *entityID}, args...) + } + slog.Debug(msg, args...) + + // Log to database + s.logToDatabase(msg, entityID) +} + +// Warn logs a warning message to both console and database +func (s *Service) Warn(msg string, entityID *string, args ...any) { + // Log to console using slog + if entityID != nil { + args = append([]any{"entity_id", *entityID}, args...) + } + slog.Warn(msg, args...) + + // Log to database + s.logToDatabase(msg, entityID) +} + +// logToDatabase writes the log entry to the database +func (s *Service) logToDatabase(msg string, entityID *string) { + log := store.Log{ + Timestamp: time.Now(), + EntityID: entityID, + LogText: msg, + } + + if err := s.db.Create(&log).Error; err != nil { + slog.Error("Failed to write log to database", "error", err, "message", msg) + } +} + +// pruneLogs runs in a goroutine to periodically remove old logs +func (s *Service) pruneLogs() { + ticker := time.NewTicker(s.pruneInterval) + defer ticker.Stop() + + for { + select { + case <-s.stopChan: + return + case <-ticker.C: + cutoffTime := time.Now().Add(-s.retentionTime) + result := s.db.Where("timestamp < ?", cutoffTime).Delete(&store.Log{}) + if result.Error != nil { + slog.Error("Failed to prune old logs", "error", result.Error) + } else if result.RowsAffected > 0 { + slog.Info("Pruned old logs", "count", result.RowsAffected, "cutoff", cutoffTime) + } + } + } +} \ No newline at end of file diff --git a/logging/service_test.go b/logging/service_test.go new file mode 100644 index 0000000..4c0bec7 --- /dev/null +++ b/logging/service_test.go @@ -0,0 +1,107 @@ +package logging + +import ( + "os" + "testing" + "time" + + "github.com/dansimau/hal/store" +) + +func TestLoggingService(t *testing.T) { + // Create temporary database + tmpDB := "test_logs.db" + defer os.Remove(tmpDB) + + // Open database + db, err := store.Open(tmpDB) + if err != nil { + t.Fatalf("Failed to open test database: %v", err) + } + + // Create logging service + service := NewService(db) + + // Test logging with entity ID + entityID := "light.kitchen" + service.Info("Light turned on", &entityID) + service.Error("Failed to turn off light", &entityID) + + // Test logging without entity ID + service.Info("System started", nil) + service.Debug("Debug message", nil) + + // Verify logs were written to database + var logs []store.Log + if err := db.Find(&logs).Error; err != nil { + t.Fatalf("Failed to query logs: %v", err) + } + + if len(logs) != 4 { + t.Errorf("Expected 4 logs, got %d", len(logs)) + } + + // Check first log with entity ID + if logs[0].LogText != "Light turned on" { + t.Errorf("Expected log text 'Light turned on', got '%s'", logs[0].LogText) + } + if logs[0].EntityID == nil || *logs[0].EntityID != "light.kitchen" { + t.Errorf("Expected entity ID 'light.kitchen', got %v", logs[0].EntityID) + } + + // Check log without entity ID + if logs[2].LogText != "System started" { + t.Errorf("Expected log text 'System started', got '%s'", logs[2].LogText) + } + if logs[2].EntityID != nil { + t.Errorf("Expected entity ID to be nil, got %v", logs[2].EntityID) + } +} + +func TestLogPruning(t *testing.T) { + // Create temporary database + tmpDB := "test_prune_logs.db" + defer os.Remove(tmpDB) + + // Open database + db, err := store.Open(tmpDB) + if err != nil { + t.Fatalf("Failed to open test database: %v", err) + } + + // Create logging service with short retention for testing + service := &Service{ + db: db, + retentionTime: 1 * time.Second, // Very short retention for testing + } + + // Add some logs + service.Info("Old log", nil) + + // Wait for retention period to pass + time.Sleep(2 * time.Second) + + // Add a new log + service.Info("New log", nil) + + // Manually trigger pruning + cutoffTime := time.Now().Add(-service.retentionTime) + result := db.Where("timestamp < ?", cutoffTime).Delete(&store.Log{}) + if result.Error != nil { + t.Fatalf("Failed to prune logs: %v", result.Error) + } + + // Verify that only the new log remains + var logs []store.Log + if err := db.Find(&logs).Error; err != nil { + t.Fatalf("Failed to query logs: %v", err) + } + + if len(logs) != 1 { + t.Errorf("Expected 1 log after pruning, got %d", len(logs)) + } + + if logs[0].LogText != "New log" { + t.Errorf("Expected remaining log to be 'New log', got '%s'", logs[0].LogText) + } +} \ No newline at end of file diff --git a/store/models.go b/store/models.go index 19c02ce..6868700 100644 --- a/store/models.go +++ b/store/models.go @@ -37,3 +37,11 @@ type Metric struct { EntityID string `gorm:"size:100"` // Optional: which entity triggered this AutomationName string `gorm:"size:100"` // Optional: which automation was involved } + +// Log represents a single log entry +type Log struct { + ID uint `gorm:"primaryKey;autoIncrement"` + Timestamp time.Time `gorm:"index;not null"` + EntityID *string `gorm:"index;size:255"` // Optional: which entity this log relates to + LogText string `gorm:"not null;type:text"` +} diff --git a/store/sqlite.go b/store/sqlite.go index 839b590..ca5d1bb 100644 --- a/store/sqlite.go +++ b/store/sqlite.go @@ -19,7 +19,7 @@ func Open(path string) (*gorm.DB, error) { return nil, err } - if err := db.AutoMigrate(&Entity{}, &Metric{}); err != nil { + if err := db.AutoMigrate(&Entity{}, &Metric{}, &Log{}); err != nil { return nil, err }