diff --git a/collector/logs/engine/batch.go b/collector/logs/engine/batch.go index 54ee699ad..e5b54cea4 100644 --- a/collector/logs/engine/batch.go +++ b/collector/logs/engine/batch.go @@ -5,6 +5,7 @@ import ( "time" "github.com/Azure/adx-mon/collector/logs/types" + "github.com/Azure/adx-mon/pkg/wal" ) type BatchConfig struct { @@ -13,6 +14,7 @@ type BatchConfig struct { InputQueue <-chan *types.Log OutputQueue chan<- *types.LogBatch AckGenerator func(log *types.Log) func() + SampleType wal.SampleType } func BatchLogs(ctx context.Context, config BatchConfig) { @@ -21,6 +23,7 @@ func BatchLogs(ctx context.Context, config BatchConfig) { currentBatch := types.LogBatchPool.Get(1024).(*types.LogBatch) currentBatch.Reset() + currentBatch.SampleType = config.SampleType for { select { case <-ctx.Done(): @@ -34,6 +37,7 @@ func BatchLogs(ctx context.Context, config BatchConfig) { flush(config, currentBatch) currentBatch = types.LogBatchPool.Get(1024).(*types.LogBatch) currentBatch.Reset() + currentBatch.SampleType = config.SampleType } case msg := <-config.InputQueue: currentBatch.Logs = append(currentBatch.Logs, msg) @@ -41,6 +45,7 @@ func BatchLogs(ctx context.Context, config BatchConfig) { flush(config, currentBatch) currentBatch = types.LogBatchPool.Get(1024).(*types.LogBatch) currentBatch.Reset() + currentBatch.SampleType = config.SampleType ticker.Reset(config.MaxBatchWait) } } diff --git a/collector/logs/sources/journal/journal_linux.go b/collector/logs/sources/journal/journal_linux.go index 54e17a9c5..63bb0c782 100644 --- a/collector/logs/sources/journal/journal_linux.go +++ b/collector/logs/sources/journal/journal_linux.go @@ -10,6 +10,7 @@ import ( "github.com/Azure/adx-mon/collector/logs/engine" "github.com/Azure/adx-mon/collector/logs/types" "github.com/Azure/adx-mon/pkg/logger" + "github.com/Azure/adx-mon/pkg/wal" "github.com/coreos/go-systemd/sdjournal" ) @@ -102,6 +103,7 @@ func (s *Source) Open(ctx context.Context) error { InputQueue: batchQueue, OutputQueue: outputQueue, AckGenerator: ackGenerator, + SampleType: wal.HostLogSampleType, } s.wg.Add(1) go func() { diff --git a/collector/logs/sources/kernel/kernel.go b/collector/logs/sources/kernel/kernel.go index bd61ac600..48d1d8d9a 100644 --- a/collector/logs/sources/kernel/kernel.go +++ b/collector/logs/sources/kernel/kernel.go @@ -14,6 +14,7 @@ import ( "github.com/Azure/adx-mon/collector/logs/engine" "github.com/Azure/adx-mon/collector/logs/types" "github.com/Azure/adx-mon/pkg/logger" + "github.com/Azure/adx-mon/pkg/wal" "github.com/siderolabs/go-kmsg" ) @@ -117,6 +118,7 @@ func (s *KernelSource) Open(ctx context.Context) error { InputQueue: batchQueue, OutputQueue: outputQueue, AckGenerator: s.ackGenerator, + SampleType: wal.HostLogSampleType, } s.wg.Add(1) diff --git a/collector/logs/sources/tail/tailer.go b/collector/logs/sources/tail/tailer.go index 6e4809fe6..87ce17a53 100644 --- a/collector/logs/sources/tail/tailer.go +++ b/collector/logs/sources/tail/tailer.go @@ -12,6 +12,7 @@ import ( "github.com/Azure/adx-mon/collector/logs/transforms/parser" "github.com/Azure/adx-mon/collector/logs/types" "github.com/Azure/adx-mon/pkg/logger" + "github.com/Azure/adx-mon/pkg/wal" "github.com/tenebris-tech/tail" ) @@ -91,6 +92,7 @@ func StartTailing(config TailerConfig) (*Tailer, error) { InputQueue: batchQueue, OutputQueue: outputQueue, AckGenerator: config.AckGenerator, + SampleType: wal.HostLogSampleType, } tailer.wg.Add(1) diff --git a/collector/logs/types/logs.go b/collector/logs/types/logs.go index 837ceaec8..27593d94f 100644 --- a/collector/logs/types/logs.go +++ b/collector/logs/types/logs.go @@ -7,6 +7,7 @@ import ( "sync/atomic" "github.com/Azure/adx-mon/pkg/logger" + "github.com/Azure/adx-mon/pkg/wal" ) var assertionsEnabledValue bool = false @@ -243,8 +244,9 @@ func (l *Log) GetResource() map[string]any { // LogBatch represents a batch of logs type LogBatch struct { - Logs []*Log - Ack func() + Logs []*Log + Ack func() + SampleType wal.SampleType } func (l *LogBatch) AddLiterals(literals []*LogLiteral) { @@ -260,6 +262,7 @@ func (l *LogBatch) Reset() { } l.Logs = l.Logs[:0] l.Ack = noop + l.SampleType = wal.UnknownSampleType } func noop() {} diff --git a/collector/logs/types/logs_test.go b/collector/logs/types/logs_test.go index 2edc3a916..d8fe52be5 100644 --- a/collector/logs/types/logs_test.go +++ b/collector/logs/types/logs_test.go @@ -4,6 +4,7 @@ import ( "errors" "testing" + "github.com/Azure/adx-mon/pkg/wal" "github.com/stretchr/testify/require" ) @@ -149,6 +150,7 @@ func TestLogBatch(t *testing.T) { Ack: func() { ackCalled = true }, + SampleType: wal.HostLogSampleType, } require.Equal(t, 2, len(batch.Logs)) @@ -159,6 +161,7 @@ func TestLogBatch(t *testing.T) { // Test Reset batch.Reset() require.Empty(t, batch.Logs) + require.Equal(t, wal.UnknownSampleType, batch.SampleType) } func BenchmarkLogWrites(b *testing.B) { diff --git a/collector/otlp/logs_transfer.go b/collector/otlp/logs_transfer.go index 144763f99..9a474f8f5 100644 --- a/collector/otlp/logs_transfer.go +++ b/collector/otlp/logs_transfer.go @@ -119,7 +119,7 @@ func (s *LogsService) Handler(w http.ResponseWriter, r *http.Request) { if convertedLogs == 0 { var status *status.Status if droppedLogMissingMetadata > 0 { - metrics.InvalidLogsDropped.WithLabelValues().Add(float64(droppedLogMissingMetadata)) + metrics.InvalidLogsDropped.WithLabelValues("missing_metadata").Add(float64(droppedLogMissingMetadata)) status = newErrorStatus("All logs dropped. Required kusto.database and kusto.table attributes or body fields are missing.") } else { status = newErrorStatus("No logs to process.") @@ -138,7 +138,7 @@ func (s *LogsService) Handler(w http.ResponseWriter, r *http.Request) { RejectedLogRecords: droppedLogMissingMetadata, ErrorMessage: "Logs lacking kube.database and kube.table attributes or body fields", }) - metrics.InvalidLogsDropped.WithLabelValues().Add(float64(droppedLogMissingMetadata)) + metrics.InvalidLogsDropped.WithLabelValues("missing_metadata").Add(float64(droppedLogMissingMetadata)) } respBodyBytes, err := proto.Marshal(resp) diff --git a/docs/quick-start.md b/docs/quick-start.md index 326f8ff6f..c412eb8e1 100644 --- a/docs/quick-start.md +++ b/docs/quick-start.md @@ -91,6 +91,34 @@ AdxmonCollectorLogsSent | summarize TotalSent=sum(Value) by Host=tostring(Labels.host), Source=tostring(Labels.source) ``` +```kql +// Estimate settled host-log loss by allowing uploads a grace period to arrive. +let grace = 30m; +let bucket = 1h; +let start = ago(2d); +let end = ago(grace); +let collected = +AdxmonCollectorLogsCommittedTotal +| where Timestamp between (start .. end) +| where Container == "collector" +| invoke prom_delta() +| extend Database=tostring(Labels.database), Table=tostring(Labels.table) +| summarize Collected=sum(Value) by Bucket=bin(Timestamp, bucket), Database, Table; +let uploaded = +AdxmonIngestorLogsUploadedTotal +| where Timestamp between (start + grace .. now()) +| where Container == "ingestor" +| invoke prom_delta() +| extend Database=tostring(Labels.database), Table=tostring(Labels.table) +| summarize Uploaded=sum(Value) by Bucket=bin(Timestamp - grace, bucket), Database, Table; +collected +| join kind=fullouter uploaded on Bucket, Database, Table +| extend Collected=coalesce(Collected, 0.0), Uploaded=coalesce(Uploaded, 0.0) +| extend SettledLoss=iff(Collected > Uploaded, Collected - Uploaded, 0.0) +| extend LossPct=iff(Collected > 0.0, 100.0 * SettledLoss / Collected, 0.0) +| order by Bucket asc, Database asc, Table asc +``` + ### Log Examples ```kql @@ -132,4 +160,4 @@ Here's a glimpse of what comes as part of the pre-built dashboards: #### Namespaces ![Namespaces](images/namespaces-dashboard.png "Namespaces Dashboard") #### Pods -![Pods](images/pods-dashboard.png "Pods Dashboard") \ No newline at end of file +![Pods](images/pods-dashboard.png "Pods Dashboard") diff --git a/ingestor/adx/uploader.go b/ingestor/adx/uploader.go index 6e6b1ef66..321d60706 100644 --- a/ingestor/adx/uploader.go +++ b/ingestor/adx/uploader.go @@ -269,6 +269,25 @@ func sanitizeErrorString(err error) error { return errors.New(errString) } +func countSegmentSamplesByType(segmentReaders []*wal.SegmentReader, sampleType wal.SampleType) uint32 { + var total uint32 + for _, sr := range segmentReaders { + st, sc := sr.SampleMetadata() + if st == sampleType { + total += sc + } + } + return total +} + +func observeUploadedHostLogs(database, table string, segmentReaders []*wal.SegmentReader) { + hostLogCount := countSegmentSamplesByType(segmentReaders, wal.HostLogSampleType) + if hostLogCount == 0 { + return + } + metrics.IngestorLogsUploaded.WithLabelValues(database, table).Add(float64(hostLogCount)) +} + func (n *uploader) upload(ctx context.Context) error { for { select { @@ -383,6 +402,7 @@ func (n *uploader) upload(ctx context.Context) error { logger.Errorf("Failed to remove batch: %s", err.Error()) } + observeUploadedHostLogs(database, table, segmentReaders) metrics.IngestorSegmentsUploadedTotal.WithLabelValues(batch.Prefix).Add(float64(len(segmentReaders))) }() diff --git a/ingestor/adx/uploader_test.go b/ingestor/adx/uploader_test.go index 7430e2317..d0761e221 100644 --- a/ingestor/adx/uploader_test.go +++ b/ingestor/adx/uploader_test.go @@ -7,10 +7,13 @@ import ( "io" "testing" + "github.com/Azure/adx-mon/metrics" "github.com/Azure/adx-mon/pkg/testutils" "github.com/Azure/adx-mon/pkg/testutils/kustainer" + "github.com/Azure/adx-mon/pkg/wal" "github.com/Azure/azure-kusto-go/azkustodata" kgzip "github.com/klauspost/compress/gzip" + dto "github.com/prometheus/client_model/go" "github.com/stretchr/testify/require" "github.com/testcontainers/testcontainers-go" ) @@ -72,3 +75,37 @@ func TestUploader_newGzipReader_PropagatesSourceError(t *testing.T) { require.Error(t, err) require.ErrorIs(t, err, expectedErr) } + +func TestObserveUploadedHostLogs(t *testing.T) { + metrics.IngestorLogsUploaded.Reset() + + dir := t.TempDir() + hostReader := newSegmentReaderWithMetadata(t, dir, wal.HostLogSampleType, 2) + defer hostReader.Close() + otherReader := newSegmentReaderWithMetadata(t, dir, wal.LogSampleType, 5) + defer otherReader.Close() + + observeUploadedHostLogs("Logs", "HostLogs", []*wal.SegmentReader{hostReader, otherReader}) + + var m dto.Metric + require.NoError(t, metrics.IngestorLogsUploaded.WithLabelValues("Logs", "HostLogs").Write(&m)) + require.Equal(t, float64(2), m.GetCounter().GetValue()) +} + +func newSegmentReaderWithMetadata(t *testing.T, dir string, sampleType wal.SampleType, count uint32) *wal.SegmentReader { + t.Helper() + + seg, err := wal.NewSegment(dir, "Logs_HostLogs") + require.NoError(t, err) + + _, err = seg.Write(context.Background(), []byte("value\n"), wal.WithSampleMetadata(sampleType, count)) + require.NoError(t, err) + path := seg.Path() + require.NoError(t, seg.Close()) + + reader, err := wal.NewSegmentReader(path) + require.NoError(t, err) + _, err = io.Copy(io.Discard, reader) + require.NoError(t, err) + return reader +} diff --git a/metrics/metrics.go b/metrics/metrics.go index 8e3351be2..14d90b740 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -85,12 +85,19 @@ var ( Help: "Counter of the number of segments uploaded to Kusto", }, []string{"metric"}) + IngestorLogsUploaded = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: Namespace, + Subsystem: "ingestor", + Name: "logs_uploaded_total", + Help: "Counter of host log records successfully uploaded to Kusto", + }, []string{"database", "table"}) + InvalidLogsDropped = promauto.NewCounterVec(prometheus.CounterOpts{ Namespace: Namespace, Subsystem: "ingestor", Name: "invalid_logs_dropped", Help: "Counter of the number of invalid logs dropped", - }, []string{}) + }, []string{"reason"}) SampleLatency = promauto.NewGaugeVec(prometheus.GaugeOpts{ Namespace: Namespace, @@ -185,6 +192,13 @@ var ( Help: "Counter of the number of logs dropped due to errors", }, []string{"source", "stage"}) + CollectorLogsCommitted = promauto.NewCounterVec(prometheus.CounterOpts{ + Namespace: Namespace, + Subsystem: "collector", + Name: "logs_committed_total", + Help: "Counter of host log records durably committed to the collector WAL", + }, []string{"database", "table"}) + MetricsRequestsReceived = promauto.NewCounterVec(prometheus.CounterOpts{ Namespace: Namespace, Subsystem: "collector", diff --git a/pkg/wal/wal.go b/pkg/wal/wal.go index e8f349050..417481e9c 100644 --- a/pkg/wal/wal.go +++ b/pkg/wal/wal.go @@ -113,6 +113,7 @@ const ( MetricSampleType TraceSampleType LogSampleType + HostLogSampleType ) type WriteOptions func([]byte) @@ -175,7 +176,7 @@ func (w *WAL) Write(ctx context.Context, buf []byte, opts ...WriteOptions) error n, err := w.tryWrite(ctx, buf, opts...) if errors.Is(err, ErrMaxSegmentSizeExceeded) { w.rotateSegmentIfNecessary() - n, err = w.tryWrite(ctx, buf) + n, err = w.tryWrite(ctx, buf, opts...) atomic.AddInt64(&w.segmentSize, int64(n)) return err } else if errors.Is(err, ErrSegmentClosed) { diff --git a/pkg/wal/wal_test.go b/pkg/wal/wal_test.go index 32c57a409..97bd4cb74 100644 --- a/pkg/wal/wal_test.go +++ b/pkg/wal/wal_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "crypto/rand" + "io" "os" "strings" "testing" @@ -182,6 +183,50 @@ func TestWAL_MaxSegmentCount(t *testing.T) { } } +func TestWAL_Write_PreservesSampleMetadataAfterRotation(t *testing.T) { + dir := t.TempDir() + const maxSegmentSize = 2048 + + w, err := wal.NewWAL(wal.WALOpts{ + Prefix: "Foo", + StorageDir: dir, + SegmentMaxSize: maxSegmentSize, + }) + require.NoError(t, err) + require.NoError(t, w.Open(context.Background())) + + filler := make([]byte, 128) + _, err = rand.Read(filler) + require.NoError(t, err) + + finalPayload := make([]byte, 512) + _, err = rand.Read(finalPayload) + require.NoError(t, err) + + for w.Size()+len(filler) < maxSegmentSize && w.Size()+len(finalPayload) < maxSegmentSize { + require.NoError(t, w.Write(context.Background(), filler)) + } + + require.GreaterOrEqual(t, w.Size()+len(finalPayload), maxSegmentSize) + + require.NoError(t, w.Write(context.Background(), finalPayload, wal.WithSampleMetadata(wal.HostLogSampleType, 1))) + require.NoError(t, w.Flush()) + + path := w.Path() + require.NoError(t, w.Close()) + + r, err := wal.NewSegmentReader(path) + require.NoError(t, err) + defer r.Close() + + _, err = io.Copy(io.Discard, r) + require.NoError(t, err) + + st, sc := r.SampleMetadata() + require.Equal(t, wal.HostLogSampleType, st) + require.Equal(t, uint32(1), sc) +} + func TestWAL_ActiveSegmentDiskUsageLeak(t *testing.T) { dir := t.TempDir() w, err := wal.NewWAL(wal.WALOpts{ diff --git a/storage/store.go b/storage/store.go index a732c51cf..55cca8b96 100644 --- a/storage/store.go +++ b/storage/store.go @@ -266,11 +266,20 @@ func (s *LocalStore) WriteNativeLogs(ctx context.Context, logs *types.LogBatch) return wal.ErrMaxDiskUsageExceeded } - if err := w.Write(ctx, enc.Bytes()); err != nil { + var writeOpts []wal.WriteOptions + if logs.SampleType != wal.UnknownSampleType { + writeOpts = append(writeOpts, wal.WithSampleMetadata(logs.SampleType, 1)) + } + + if err := w.Write(ctx, enc.Bytes(), writeOpts...); err != nil { atomic.AddInt64(&s.inflightWriteBytes, -int64(len(enc.Bytes()))) return err } + if logs.SampleType == wal.HostLogSampleType { + metrics.CollectorLogsCommitted.WithLabelValues(sanitizedDB, sanitizedTable).Inc() + } + // Decrement the inflight write bytes after writing to avoid double counting. atomic.AddInt64(&s.inflightWriteBytes, -int64(len(enc.Bytes()))) } diff --git a/storage/store_test.go b/storage/store_test.go index d561b37bb..5cc15cb91 100644 --- a/storage/store_test.go +++ b/storage/store_test.go @@ -15,6 +15,7 @@ import ( logsv1 "buf.build/gen/go/opentelemetry/opentelemetry/protocolbuffers/go/opentelemetry/proto/logs/v1" "github.com/Azure/adx-mon/collector/logs/types" + "github.com/Azure/adx-mon/metrics" "github.com/Azure/adx-mon/pkg/logger" "github.com/Azure/adx-mon/pkg/otlp" "github.com/Azure/adx-mon/pkg/prompb" @@ -22,6 +23,7 @@ import ( "github.com/Azure/adx-mon/schema" "github.com/Azure/adx-mon/storage" "github.com/davecgh/go-spew/spew" + dto "github.com/prometheus/client_model/go" "github.com/stretchr/testify/require" ) @@ -376,6 +378,57 @@ func TestStore_WriteNativeLogs_Empty(t *testing.T) { } } +func TestStore_WriteNativeLogs_HostLogAccounting(t *testing.T) { + metrics.CollectorLogsCommitted.Reset() + + ctx := context.Background() + dir := t.TempDir() + s := storage.NewLocalStore(storage.StoreOpts{ + StorageDir: dir, + SegmentMaxSize: 1024, + SegmentMaxAge: time.Minute, + MaxDiskUsage: 1024 * 1024, + }) + + require.NoError(t, s.Open(ctx)) + + valid := types.NewLog() + valid.SetBodyValue(types.BodyKeyMessage, "hello") + valid.SetAttributeValue(types.AttributeDatabaseName, "Logs") + valid.SetAttributeValue(types.AttributeTableName, "HostLogs") + + missingDestination := types.NewLog() + missingDestination.SetBodyValue(types.BodyKeyMessage, "ignored") + missingDestination.SetAttributeValue(types.AttributeDatabaseName, "Logs") + + require.NoError(t, s.WriteNativeLogs(ctx, &types.LogBatch{ + Logs: []*types.Log{valid, missingDestination}, + SampleType: wal.HostLogSampleType, + })) + + key := fmt.Appendf(make([]byte, 0, 64), "%s_%s_%s", "Logs", "HostLogs", strconv.FormatUint(schema.SchemaHash(schema.DefaultLogsMapping), 36)) + w, err := s.GetWAL(ctx, key) + require.NoError(t, err) + path := w.Path() + + require.NoError(t, s.Close()) + + r, err := wal.NewSegmentReader(path) + require.NoError(t, err) + defer r.Close() + + _, err = io.Copy(io.Discard, r) + require.NoError(t, err) + + st, sc := r.SampleMetadata() + require.Equal(t, wal.HostLogSampleType, st) + require.Equal(t, uint32(1), sc) + + var m dto.Metric + require.NoError(t, metrics.CollectorLogsCommitted.WithLabelValues("Logs", "HostLogs").Write(&m)) + require.Equal(t, float64(1), m.GetCounter().GetValue()) +} + func TestStore_SkipNonCSV(t *testing.T) { dir := t.TempDir() s := storage.NewLocalStore(storage.StoreOpts{ @@ -421,7 +474,8 @@ func TestStore_Import_Append(t *testing.T) { seg1, err := wal.NewSegment(dir, "Database_Metric") require.NoError(t, err) - seg1.Write(context.Background(), []byte("foo\n")) + _, err = seg1.Write(context.Background(), []byte("foo\n"), wal.WithSampleMetadata(wal.HostLogSampleType, 1)) + require.NoError(t, err) seg1Path := seg1.Path() require.NoError(t, seg1.Close()) seg1Bytes, err := os.ReadFile(seg1Path) @@ -429,7 +483,8 @@ func TestStore_Import_Append(t *testing.T) { seg2, err := wal.NewSegment(dir, "Database_Metric") require.NoError(t, err) - seg2.Write(context.Background(), []byte("bar\n")) + _, err = seg2.Write(context.Background(), []byte("bar\n"), wal.WithSampleMetadata(wal.HostLogSampleType, 2)) + require.NoError(t, err) seg2Path := seg2.Path() require.NoError(t, seg2.Close()) seg2Bytes, err := os.ReadFile(seg2Path) @@ -463,9 +518,13 @@ func TestStore_Import_Append(t *testing.T) { r, err := wal.NewSegmentReader(activeSegPath) require.NoError(t, err) + defer r.Close() data, err := io.ReadAll(r) require.NoError(t, err) require.Equal(t, "foo\nbar\n", string(data)) + st, sc := r.SampleMetadata() + require.Equal(t, wal.HostLogSampleType, st) + require.Equal(t, uint32(3), sc) }