Add comprehensive event logging system (#82)

* Add comprehensive event logging system with OS-specific location and rotation Features: - Event logging for security-relevant events (malware detection, installations) - OS-specific default log locations (~/.pmg/logs/ on macOS/Linux, %LOCALAPPDATA%\pmg\logs\ on Windows) - Automatic 7-day log rotation with daily log files (YYYYMMDD-pmg.log format) - Support for custom log files via --log flag - Thread-safe JSON logging with zero external dependencies Implementation: - New internal/eventlog package with comprehensive logging functionality - Integration with guard.go to log malware detections and blocks - Integration with main.go for initialization and cleanup - Log file naming: YYYYMMDD-pmg.log (e.g., 20251216-pmg.log) - Fail-safe design - PMG continues if logging fails Event Types: - malware_blocked: Malicious package blocked from installation - malware_confirmed: User proceeded with flagged package - install_allowed: Clean package installation allowed - install_started: Package manager command initiated - error: Error events Testing: - Comprehensive test suite with 6 passing tests - Verified with real malware detection (e.g., @postman/tunnel-agent) - Works with all package managers (npm, pip, etc.) Technical Details: - Thread-safe with mutex protection - JSON format for easy parsing - Automatic cleanup of logs >7 days old - Background cleanup goroutine - Uses only Go standard library (encoding/json, os, path/filepath, sync, time) * Add update command support and improve event logging robustness Features: - Add support for npm/pnpm/bun/yarn update/upgrade/ci commands - These commands now scan packages for malware before updating - Closes security gap where update commands bypassed PMG protection Improvements: - Make event logging more defensive (graceful failure when not initialized) - Add nil check for packageManager in guard to prevent test failures - Add comprehensive tests for update commands Testing: - All 33+ unit tests passing - Integration tests verified with real malware detection - Tested with npm update, npm ci, npm upgrade, pnpm update, yarn upgrade Files changed: - packagemanager/npm.go: Added update/upgrade/ci to InstallCommands - packagemanager/npm_test.go: Added 4 new test cases for update commands - guard/guard.go: Added nil check for packageManager - internal/eventlog/eventlog.go: Made logging more defensive * Address review feedback: use log.Warnf instead of silently failing Replace silent error handling in cleanupOldLogs with log.Warnf to avoid completely swallowing errors when reading log directory. Fixes reviewer feedback from abhisek. * Remove update/upgrade command support, keep logging improvements - Remove update/upgrade/ci commands from InstallCommands for npm, pnpm, bun, yarn - Remove special handling for update/upgrade/ci commands in ParseCommand - Remove update command test cases and restore original test - Preserve logging improvements (nil check in guard.go, defensive check in eventlog.go) All tests passing.
2026-08-03 07:24:09 +02:00 · 2025-12-31 16:05:31 +05:30
parent 2bc500f817
commit 698bd3dd13
4 changed files with 698 additions and 2 deletions
@@ -0,0 +1,350 @@
+package eventlog
+
+import (
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+	"path/filepath"
+	"runtime"
+	"sync"
+	"time"
+
+	"github.com/safedep/dry/log"
+)
+
+// EventType represents the type of event being logged
+type EventType string
+
+const (
+	EventTypeMalwareBlocked    EventType = "malware_blocked"
+	EventTypeMalwareConfirmed  EventType = "malware_confirmed"
+	EventTypeInstallAllowed    EventType = "install_allowed"
+	EventTypeInstallStarted    EventType = "install_started"
+	EventTypeDependencyResolved EventType = "dependency_resolved"
+	EventTypeError             EventType = "error"
+)
+
+// Event represents a security event
+type Event struct {
+	Timestamp   time.Time              `json:"timestamp"`
+	EventType   EventType              `json:"event_type"`
+	Message     string                 `json:"message"`
+	PackageName string                 `json:"package_name,omitempty"`
+	Version     string                 `json:"version,omitempty"`
+	Ecosystem   string                 `json:"ecosystem,omitempty"`
+	Details     map[string]interface{} `json:"details,omitempty"`
+}
+
+// Logger represents an event logger
+type Logger struct {
+	file   *os.File
+	writer io.Writer
+	mu     sync.Mutex
+	active bool
+}
+
+var (
+	globalLogger *Logger
+	once         sync.Once
+)
+
+// GetDefaultLogDir returns the default log directory based on the OS
+func GetDefaultLogDir() (string, error) {
+	var baseDir string
+
+	switch runtime.GOOS {
+	case "windows":
+		// Windows: %LOCALAPPDATA%\pmg\logs or %USERPROFILE%\.pmg\logs
+		baseDir = os.Getenv("LOCALAPPDATA")
+		if baseDir == "" {
+			baseDir = os.Getenv("USERPROFILE")
+			if baseDir == "" {
+				return "", fmt.Errorf("could not determine Windows user directory")
+			}
+			return filepath.Join(baseDir, ".pmg", "logs"), nil
+		}
+		return filepath.Join(baseDir, "pmg", "logs"), nil
+	case "darwin", "linux":
+		// macOS and Linux: ~/.pmg/logs
+		homeDir, err := os.UserHomeDir()
+		if err != nil {
+			return "", fmt.Errorf("could not determine home directory: %w", err)
+		}
+		return filepath.Join(homeDir, ".pmg", "logs"), nil
+	default:
+		return "", fmt.Errorf("unsupported operating system: %s", runtime.GOOS)
+	}
+}
+
+// Initialize sets up the global event logger with the default log directory
+func Initialize() error {
+	logDir, err := GetDefaultLogDir()
+	if err != nil {
+		return err
+	}
+	return InitializeWithDir(logDir)
+}
+
+// InitializeWithFile sets up the global event logger with a specific file path
+func InitializeWithFile(filePath string) error {
+	var initErr error
+	once.Do(func() {
+		globalLogger = &Logger{}
+		initErr = globalLogger.initWithFile(filePath)
+	})
+	return initErr
+}
+
+// InitializeWithDir sets up the global event logger with a custom log directory
+func InitializeWithDir(logDir string) error {
+	var initErr error
+	once.Do(func() {
+		globalLogger = &Logger{}
+		initErr = globalLogger.init(logDir)
+	})
+	return initErr
+}
+
+// reinitializeForTest resets and reinitializes the logger for testing purposes
+// This should only be used in tests
+func reinitializeForTest(logDir string) error {
+	// Close existing logger if any
+	if globalLogger != nil {
+		globalLogger.Close()
+	}
+	
+	// Reset once
+	once = sync.Once{}
+	
+	// Initialize new logger
+	return InitializeWithDir(logDir)
+}
+
+// init initializes the logger with the specified directory
+func (l *Logger) init(logDir string) error {
+	// Create log directory if it doesn't exist
+	if err := os.MkdirAll(logDir, 0755); err != nil {
+		return fmt.Errorf("failed to create log directory: %w", err)
+	}
+
+	// Create log file with timestamp-based naming
+	logFileName := time.Now().Format("20060102") + "-pmg.log"
+	logFilePath := filepath.Join(logDir, logFileName)
+
+	file, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644)
+	if err != nil {
+		return fmt.Errorf("failed to open log file: %w", err)
+	}
+
+	l.file = file
+	l.writer = file
+	l.active = true
+
+	// Clean up old logs in background
+	go l.cleanupOldLogs(logDir)
+
+	return nil
+}
+
+// initWithFile initializes the logger with a specific file path
+func (l *Logger) initWithFile(filePath string) error {
+	// Create directory if it doesn't exist
+	dir := filepath.Dir(filePath)
+	if dir != "" && dir != "." {
+		if err := os.MkdirAll(dir, 0755); err != nil {
+			return fmt.Errorf("failed to create log directory: %w", err)
+		}
+	}
+
+	file, err := os.OpenFile(filePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644)
+	if err != nil {
+		return fmt.Errorf("failed to open log file: %w", err)
+	}
+
+	l.file = file
+	l.writer = file
+	l.active = true
+
+	// No cleanup needed for custom log files (user manages them)
+
+	return nil
+}
+
+// cleanupOldLogs removes log files older than 7 days
+func (l *Logger) cleanupOldLogs(logDir string) {
+	cutoff := time.Now().AddDate(0, 0, -7)
+
+	entries, err := os.ReadDir(logDir)
+	if err != nil {
+		log.Warnf("Failed to read log directory for cleanup: %v", err)
+		return
+	}
+
+	for _, entry := range entries {
+		if entry.IsDir() {
+			continue
+		}
+
+		// Only process *-pmg.log files
+		name := entry.Name()
+		matched, err := filepath.Match("*-pmg.log", name)
+		if err != nil || !matched {
+			continue
+		}
+
+		filePath := filepath.Join(logDir, name)
+		info, err := entry.Info()
+		if err != nil {
+			continue
+		}
+
+		if info.ModTime().Before(cutoff) {
+			os.Remove(filePath)
+		}
+	}
+}
+
+// Log writes an event to the log file
+func (l *Logger) Log(event Event) error {
+	if !l.active {
+		return nil
+	}
+
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	// Set timestamp if not already set
+	if event.Timestamp.IsZero() {
+		event.Timestamp = time.Now()
+	}
+
+	// Marshal event to JSON
+	data, err := json.Marshal(event)
+	if err != nil {
+		return fmt.Errorf("failed to marshal event: %w", err)
+	}
+
+	// Write to file
+	_, err = l.writer.Write(append(data, '\n'))
+	if err != nil {
+		return fmt.Errorf("failed to write event: %w", err)
+	}
+
+	// Flush to ensure data is written
+	if l.file != nil {
+		l.file.Sync()
+	}
+
+	return nil
+}
+
+// Close closes the logger
+func (l *Logger) Close() error {
+	if !l.active {
+		return nil
+	}
+
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	l.active = false
+	if l.file != nil {
+		return l.file.Close()
+	}
+	return nil
+}
+
+// Global logging functions
+
+// LogEvent logs an event using the global logger
+func LogEvent(event Event) error {
+	if globalLogger == nil || !globalLogger.active {
+		// If logger is not initialized or not active, silently fail
+		return nil
+	}
+	return globalLogger.Log(event)
+}
+
+// LogMalwareBlocked logs when malware is blocked
+func LogMalwareBlocked(packageName, version, ecosystem, reason string, details map[string]interface{}) {
+	event := Event{
+		EventType:   EventTypeMalwareBlocked,
+		Message:     fmt.Sprintf("Blocked installation of malicious package: %s@%s", packageName, version),
+		PackageName: packageName,
+		Version:     version,
+		Ecosystem:   ecosystem,
+		Details:     details,
+	}
+	if details == nil {
+		event.Details = make(map[string]interface{})
+	}
+	event.Details["reason"] = reason
+	LogEvent(event)
+}
+
+// LogMalwareConfirmed logs when user confirms installation despite warning
+func LogMalwareConfirmed(packageName, version, ecosystem string) {
+	event := Event{
+		EventType:   EventTypeMalwareConfirmed,
+		Message:     fmt.Sprintf("User confirmed installation of flagged package: %s@%s", packageName, version),
+		PackageName: packageName,
+		Version:     version,
+		Ecosystem:   ecosystem,
+	}
+	LogEvent(event)
+}
+
+// LogInstallAllowed logs when an installation is allowed
+func LogInstallAllowed(packageName, version, ecosystem string, packageCount int) {
+	event := Event{
+		EventType:   EventTypeInstallAllowed,
+		Message:     fmt.Sprintf("Installation allowed for %s@%s (%d packages analyzed)", packageName, version, packageCount),
+		PackageName: packageName,
+		Version:     version,
+		Ecosystem:   ecosystem,
+		Details: map[string]interface{}{
+			"packages_analyzed": packageCount,
+		},
+	}
+	LogEvent(event)
+}
+
+// LogInstallStarted logs when an installation starts
+func LogInstallStarted(packageManager string, args []string) {
+	event := Event{
+		EventType: EventTypeInstallStarted,
+		Message:   fmt.Sprintf("Starting package installation with %s", packageManager),
+		Details: map[string]interface{}{
+			"package_manager": packageManager,
+			"arguments":       args,
+		},
+	}
+	LogEvent(event)
+}
+
+// LogError logs an error event
+func LogError(message string, err error) {
+	event := Event{
+		EventType: EventTypeError,
+		Message:   message,
+		Details: map[string]interface{}{
+			"error": err.Error(),
+		},
+	}
+	LogEvent(event)
+}
+
+// Close closes the global logger
+func Close() error {
+	if globalLogger != nil {
+		return globalLogger.Close()
+	}
+	return nil
+}
+
+// IsInitialized returns whether the global logger is initialized
+func IsInitialized() bool {
+	return globalLogger != nil && globalLogger.active
+}
+
@@ -0,0 +1,254 @@
+package eventlog
+
+import (
+	"encoding/json"
+	"os"
+	"path/filepath"
+	"sync"
+	"testing"
+	"time"
+)
+
+func TestGetDefaultLogDir(t *testing.T) {
+	logDir, err := GetDefaultLogDir()
+	if err != nil {
+		t.Fatalf("GetDefaultLogDir() failed: %v", err)
+	}
+
+	if logDir == "" {
+		t.Error("Expected non-empty log directory")
+	}
+
+	// Check that it contains expected path components
+	expectedDir := ".pmg"
+	if filepath.Base(filepath.Dir(logDir)) != expectedDir && filepath.Base(filepath.Dir(filepath.Dir(logDir))) != expectedDir {
+		t.Errorf("Expected log directory to contain %s, got: %s", expectedDir, logDir)
+	}
+}
+
+func TestLoggerInitialization(t *testing.T) {
+	// Create a temporary directory for testing
+	tmpDir := t.TempDir()
+	logDir := filepath.Join(tmpDir, ".pmg", "logs")
+
+	// Initialize logger
+	err := InitializeWithDir(logDir)
+	if err != nil {
+		t.Fatalf("Failed to initialize logger: %v", err)
+	}
+	defer Close()
+
+	// Check that directory was created
+	if _, err := os.Stat(logDir); os.IsNotExist(err) {
+		t.Errorf("Log directory was not created: %s", logDir)
+	}
+
+	// Check that log file was created
+	expectedLogFile := filepath.Join(logDir, time.Now().Format("20060102")+"-pmg.log")
+	if _, err := os.Stat(expectedLogFile); os.IsNotExist(err) {
+		t.Errorf("Log file was not created: %s", expectedLogFile)
+	}
+}
+
+func TestLogEvent(t *testing.T) {
+	// Create a temporary directory for testing
+	tmpDir := t.TempDir()
+	logDir := filepath.Join(tmpDir, ".pmg", "logs")
+
+	// Initialize logger
+	err := reinitializeForTest(logDir)
+	if err != nil {
+		t.Fatalf("Failed to initialize logger: %v", err)
+	}
+	defer Close()
+
+	// Log an event
+	event := Event{
+		EventType:   EventTypeMalwareBlocked,
+		Message:     "Test malware blocked",
+		PackageName: "evil-package",
+		Version:     "1.0.0",
+		Ecosystem:   "npm",
+		Details: map[string]interface{}{
+			"reason": "Known malicious",
+		},
+	}
+
+	err = LogEvent(event)
+	if err != nil {
+		t.Fatalf("Failed to log event: %v", err)
+	}
+
+	// Read the log file and verify the event was written
+	logFilePath := filepath.Join(logDir, time.Now().Format("20060102")+"-pmg.log")
+	data, err := os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("Failed to read log file: %v", err)
+	}
+
+	// Parse the JSON
+	var loggedEvent Event
+	err = json.Unmarshal(data, &loggedEvent)
+	if err != nil {
+		t.Fatalf("Failed to parse logged event: %v", err)
+	}
+
+	// Verify the event
+	if loggedEvent.EventType != EventTypeMalwareBlocked {
+		t.Errorf("Expected event type %s, got %s", EventTypeMalwareBlocked, loggedEvent.EventType)
+	}
+	if loggedEvent.PackageName != "evil-package" {
+		t.Errorf("Expected package name 'evil-package', got '%s'", loggedEvent.PackageName)
+	}
+}
+
+func TestLogMalwareBlocked(t *testing.T) {
+	// Create a temporary directory for testing
+	tmpDir := t.TempDir()
+	logDir := filepath.Join(tmpDir, ".pmg", "logs")
+
+	// Initialize logger
+	err := reinitializeForTest(logDir)
+	if err != nil {
+		t.Fatalf("Failed to initialize logger: %v", err)
+	}
+	defer Close()
+
+	// Log malware blocked event
+	LogMalwareBlocked("malicious-pkg", "2.0.0", "pypi", "Contains known malware", nil)
+
+	// Read and verify
+	logFilePath := filepath.Join(logDir, time.Now().Format("20060102")+"-pmg.log")
+	data, err := os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("Failed to read log file: %v", err)
+	}
+
+	var event Event
+	err = json.Unmarshal(data, &event)
+	if err != nil {
+		t.Fatalf("Failed to parse event: %v", err)
+	}
+
+	if event.EventType != EventTypeMalwareBlocked {
+		t.Errorf("Expected event type %s, got %s", EventTypeMalwareBlocked, event.EventType)
+	}
+	if event.PackageName != "malicious-pkg" {
+		t.Errorf("Expected package 'malicious-pkg', got '%s'", event.PackageName)
+	}
+	if event.Ecosystem != "pypi" {
+		t.Errorf("Expected ecosystem 'pypi', got '%s'", event.Ecosystem)
+	}
+}
+
+func TestInitializeWithFile(t *testing.T) {
+	// Create a temporary directory for testing
+	tmpDir := t.TempDir()
+	logFile := filepath.Join(tmpDir, "custom.log")
+
+	// Initialize logger with custom file
+	err := reinitializeForTest("")
+	if err == nil {
+		Close()
+	}
+	
+	// Reset for custom file
+	once = sync.Once{}
+	err = InitializeWithFile(logFile)
+	if err != nil {
+		t.Fatalf("Failed to initialize logger with file: %v", err)
+	}
+	defer Close()
+
+	// Log an event
+	event := Event{
+		EventType:   EventTypeMalwareBlocked,
+		Message:     "Test custom file logging",
+		PackageName: "test-package",
+		Version:     "1.0.0",
+		Ecosystem:   "npm",
+	}
+
+	err = LogEvent(event)
+	if err != nil {
+		t.Fatalf("Failed to log event: %v", err)
+	}
+
+	// Verify the custom log file was created and contains the event
+	if _, err := os.Stat(logFile); os.IsNotExist(err) {
+		t.Errorf("Custom log file was not created: %s", logFile)
+	}
+
+	data, err := os.ReadFile(logFile)
+	if err != nil {
+		t.Fatalf("Failed to read custom log file: %v", err)
+	}
+
+	if len(data) == 0 {
+		t.Error("Custom log file is empty")
+	}
+
+	var loggedEvent Event
+	err = json.Unmarshal(data, &loggedEvent)
+	if err != nil {
+		t.Fatalf("Failed to parse logged event: %v", err)
+	}
+
+	if loggedEvent.PackageName != "test-package" {
+		t.Errorf("Expected package 'test-package', got '%s'", loggedEvent.PackageName)
+	}
+}
+
+func TestCleanupOldLogs(t *testing.T) {
+	// Create a temporary directory for testing
+	tmpDir := t.TempDir()
+	logDir := filepath.Join(tmpDir, ".pmg", "logs")
+	err := os.MkdirAll(logDir, 0755)
+	if err != nil {
+		t.Fatalf("Failed to create log directory: %v", err)
+	}
+
+	// Create old log files
+	oldDate := time.Now().AddDate(0, 0, -10)
+	oldLogFile := filepath.Join(logDir, oldDate.Format("20060102")+"-pmg.log")
+	err = os.WriteFile(oldLogFile, []byte("old log"), 0644)
+	if err != nil {
+		t.Fatalf("Failed to create old log file: %v", err)
+	}
+
+	// Change the modification time to make it appear old
+	oldTime := time.Now().AddDate(0, 0, -10)
+	err = os.Chtimes(oldLogFile, oldTime, oldTime)
+	if err != nil {
+		t.Fatalf("Failed to change file time: %v", err)
+	}
+
+	// Create a recent log file
+	recentLogFile := filepath.Join(logDir, time.Now().Format("20060102")+"-pmg.log")
+	err = os.WriteFile(recentLogFile, []byte("recent log"), 0644)
+	if err != nil {
+		t.Fatalf("Failed to create recent log file: %v", err)
+	}
+
+	// Initialize logger (which triggers cleanup)
+	logger := &Logger{}
+	err = logger.init(logDir)
+	if err != nil {
+		t.Fatalf("Failed to initialize logger: %v", err)
+	}
+	defer logger.Close()
+
+	// Give cleanup goroutine time to run
+	time.Sleep(100 * time.Millisecond)
+
+	// Check that old file was deleted
+	if _, err := os.Stat(oldLogFile); !os.IsNotExist(err) {
+		t.Error("Old log file should have been deleted")
+	}
+
+	// Check that recent file still exists
+	if _, err := os.Stat(recentLogFile); os.IsNotExist(err) {
+		t.Error("Recent log file should still exist")
+	}
+}
+