Files
pmg/internal/eventlog/eventlog.go
T
327c9c7068 feat(cooldown): respect trusted_packages in dependency cooldown (#342)
* feat(cooldown): respect trusted_packages in dependency cooldown

Trusted packages are now treated as a superset waiver that bypasses every
PMG control (malware analysis, cooldown, and any future controls). A
globally trusted package is automatically exempt from the cooldown window
and no longer needs a duplicate entry in dependency_cooldown.skip.

The skip list remains the narrower, cooldown-only waiver for packages
that must bypass the cooldown wait but still be malware-scanned.

* refactor(cooldown): tag skip reason and audit-log skipped packages

Address review feedback on #342:

- Restore cooldownSkip to a pure single-list function (SRP); the merge
  into trusted_packages now happens in a separate mergeCooldownSkip step,
  driven by the exported CooldownSkip wrapper.
- Extend CooldownSkipInfo with a CooldownSkipReason (TrustedPackage /
  CooldownSkipList) on both SkipAll and per-version entries, so callers
  can tell apart the broad waiver from the cooldown-only one. When both
  lists match the same package, trusted_packages wins.
- Add audit.LogCooldownSkipped and emit it from the npm and PyPI
  interceptors on the SkipAll path, alongside the existing info log,
  carrying the source list as the reason.

* refactor(cooldown): inline list merge, audit per-version exemptions

Address further review feedback:

- Drop the separate mergeCooldownSkip helper; cooldownSkip now writes
  into a shared *CooldownSkipInfo and is called twice from CooldownSkip
  (cooldown skip list first, trusted_packages on top so trusted entries
  override the reason on overlap).
- Audit log every exemption, not just SkipAll: a new auditCooldownSkip
  helper in proxy/interceptors/cooldown.go emits one event per match
  (package-wide or per-version), each tagged with its source list.
  LogCooldownSkipped gains a version argument for the per-version case.
- Cover the trusted_packages reason path in TestCooldownSkip.

* fix(cooldown): avoid double-auditing trusted package exemptions

auditCooldownSkip now only emits EventTypeCooldownSkipped for entries
that came from dependency_cooldown.skip. Trusted-package exemptions
already get an EventTypeInstallTrustedAllowed event at tarball-download
time (proxy/interceptors/base_registry.go), so emitting a cooldown event
for them too would double-count the same waiver.

* emit trusted and cooldown skip events to cloud

* fix tests

* refactor(cooldown): return value from collectCooldownSkip, short-circuit on trusted SkipAll

Address PR review feedback:
- Rename cooldownSkip to collectCooldownSkip and return CooldownSkipInfo
  instead of mutating an input pointer.
- Add mergeCooldownSkip to combine per-list results with trusted_packages
  taking precedence on overlap.
- CooldownSkip now consults trusted_packages first and returns immediately
  on a package-wide trusted exemption (DC skip list cannot add anything).
- Extend tests to cover disjoint pinned entries across both lists and the
  case where DC version-less subsumes a trusted pinned entry.

* fix(audit): address cooldown review feedback

* fix(cooldown): audit cooldown skips at download time with concrete version

Backend rejects PackageVersion messages without a version, and audit logs
should reflect the runtime fact (a specific version was skipped) rather
than the config rule. Move the audit emission from metadata-request
handling to download-request handling, where the concrete version is
known, and require version in LogCooldownSkipped.

* chore(audit): drop dead scope assignment in LogCooldownSkipped

* refactor(cooldown): move skip-list logic into cooldown handlers

Registry interceptors no longer compute CooldownSkip or branch on SkipAll;
they just call HandleMetadataRequest. The npm and pypi cooldown handlers
own the skip lookup, the package-wide exemption short-circuit, and (for
pypi) the canonical-name denormalization. Also align LogCooldownSkipped
with other LogXxx signatures by taking *packagev1.PackageVersion.

* fix: Simplify audit logging for dependency cooldown skip

* refactor: Simplify cooldown handling and maintain separation of concepts for trusted and DC skip packages

* fix: Code review fixes

* fix: Emit cooldown skipped audit event ONLY when an in-window version is skipped

---------

Co-authored-by: Abhisek Datta <abhisek.datta@gmail.com>
2026-06-21 18:22:15 +05:30

306 lines
7.4 KiB
Go

package eventlog
import (
"encoding/json"
"fmt"
"io"
"os"
"path/filepath"
"sync"
"time"
"github.com/safedep/dry/log"
"github.com/safedep/pmg/config"
)
// EventType represents the type of event being logged
type EventType string
const (
EventTypeMalwareBlocked EventType = "malware_blocked"
EventTypeMalwareConfirmed EventType = "malware_confirmed"
EventTypeInstallAllowed EventType = "install_allowed"
EventTypeInstallTrustedAllowed EventType = "install_trusted_allowed"
EventTypeInstallStarted EventType = "install_started"
EventTypeDependencyResolved EventType = "dependency_resolved"
EventTypeInstallInsecureBypass EventType = "install_insecure_bypass"
EventTypeProxyHostObserved EventType = "proxy_host_observed"
EventTypeDependencyCooldown EventType = "dependency_cooldown"
EventTypeCooldownSkipped EventType = "dependency_cooldown_skipped"
EventTypeSandboxOverride EventType = "sandbox_override"
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 defines the contract for implementing event loggers.
type Logger interface {
// Log writes an event to the log file
Log(event Event) error
// Close closes the logger
Close() error
// IsActive returns whether the logger is active
IsActive() bool
}
// fileWithRotationLogger represents an event logger that writes to a file and rotates the
// file when it reaches a certain age
type fileWithRotationLogger struct {
file *os.File
writer io.Writer
mu sync.Mutex
active bool
}
// fileWithRotationLogger implements the Logger interface. This is the default logger
// that will be used. Future enhancements will introduce additional and optional loggers.
var _ Logger = &fileWithRotationLogger{}
var (
globalLogger Logger
once sync.Once
)
// GetDefaultLogDir returns the default log directory based on the OS
func GetDefaultLogDir() (string, error) {
return config.Get().EventLogDir(), nil
}
// Initialize sets up the global event logger with the default log directory
func Initialize() error {
if config.Get().Config.SkipEventLogging {
return nil
}
logDir, err := GetDefaultLogDir()
if err != nil {
return fmt.Errorf("failed to get default log directory: %w", err)
}
return InitializeWithDir(logDir)
}
// InitializeWithFile sets up the global event logger with a specific file path
func InitializeWithFile(filePath string) error {
if config.Get().Config.SkipEventLogging {
return nil
}
var initErr error
once.Do(func() {
fwrl := &fileWithRotationLogger{}
initErr = fwrl.initWithFile(filePath)
globalLogger = fwrl
})
return initErr
}
// InitializeWithDir sets up the global event logger with a custom log directory
func InitializeWithDir(logDir string) error {
if config.Get().Config.SkipEventLogging {
return nil
}
var initErr error
once.Do(func() {
fwrl := &fileWithRotationLogger{}
initErr = fwrl.init(logDir)
globalLogger = fwrl
})
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 {
if err := globalLogger.Close(); err != nil {
log.Warnf("failed to close existing logger: %v", err)
}
}
// Reset once
once = sync.Once{}
// Initialize new logger
return InitializeWithDir(logDir)
}
// init initializes the logger with the specified directory
func (l *fileWithRotationLogger) 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 *fileWithRotationLogger) 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 *fileWithRotationLogger) cleanupOldLogs(logDir string) {
cutoff := time.Now().AddDate(0, 0, -1*config.Get().Config.EventLogRetentionDays)
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 {
log.Warnf("Failed to get info for log file: %v", err)
continue
}
if info.ModTime().Before(cutoff) {
if err := os.Remove(filePath); err != nil {
log.Warnf("Failed to remove old log file: %v", err)
}
}
}
}
// Log writes an event to the log file
func (l *fileWithRotationLogger) 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 {
if err := l.file.Sync(); err != nil {
return fmt.Errorf("failed to sync file: %w", err)
}
}
return nil
}
// Close closes the logger
func (l *fileWithRotationLogger) 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
}
// IsActive returns whether the logger is active
func (l *fileWithRotationLogger) IsActive() bool {
return l.active
}
// LogEvent logs an event using the global logger
func LogEvent(event Event) error {
// If logger is not initialized or not active, silently fail
if globalLogger == nil || !globalLogger.IsActive() {
return nil
}
return globalLogger.Log(event)
}
// Close closes the global logger
func Close() error {
if globalLogger != nil {
return globalLogger.Close()
}
return nil
}