* Lazy Versioning Check, Conditional SSE Entry Fetch, HEAD Request Optimization * revert Reverted the conditional versioning check to always check versioning status Reverted the conditional SSE entry fetch to always fetch entry metadata Reverted the conditional versioning check to always check versioning status Reverted the conditional SSE entry fetch to always fetch entry metadata * Lazy Entry Fetch for SSE, Skip Conditional Header Check * SSE-KMS headers are present, this is not an SSE-C request (mutually exclusive) * SSE-C is mutually exclusive with SSE-S3 and SSE-KMS * refactor * Removed Premature Mutual Exclusivity Check * check for the presence of the X-Amz-Server-Side-Encryption header * not used * fmt * directly read write volume servers * HTTP Range Request Support * set header * md5 * copy object * fix sse * fmt * implement sse * sse continue * fixed the suffix range bug (bytes=-N for "last N bytes") * debug logs * Missing PartsCount Header * profiling * url encoding * test_multipart_get_part * headers * debug * adjust log level * handle part number * Update s3api_object_handlers.go * nil safety * set ModifiedTsNs * remove * nil check * fix sse header * same logic as filer * decode values * decode ivBase64 * s3: Fix SSE decryption JWT authentication and streaming errors Critical fix for SSE (Server-Side Encryption) test failures: 1. **JWT Authentication Bug** (Root Cause): - Changed from GenJwtForFilerServer to GenJwtForVolumeServer - S3 API now uses correct JWT when directly reading from volume servers - Matches filer's authentication pattern for direct volume access - Fixes 'unexpected EOF' and 500 errors in SSE tests 2. **Streaming Error Handling**: - Added error propagation in getEncryptedStreamFromVolumes goroutine - Use CloseWithError() to properly communicate stream failures - Added debug logging for streaming errors 3. **Response Header Timing**: - Removed premature WriteHeader(http.StatusOK) call - Let Go's http package write status automatically on first write - Prevents header lock when errors occur during streaming 4. **Enhanced SSE Decryption Debugging**: - Added IV/Key validation and logging for SSE-C, SSE-KMS, SSE-S3 - Better error messages for missing or invalid encryption metadata - Added glog.V(2) debugging for decryption setup This fixes SSE integration test failures where encrypted objects could not be retrieved due to volume server authentication failures. The JWT bug was causing volume servers to reject requests, resulting in truncated/empty streams (EOF) or internal errors. * s3: Fix SSE multipart upload metadata preservation Critical fix for SSE multipart upload test failures (SSE-C and SSE-KMS): **Root Cause - Incomplete SSE Metadata Copying**: The old code only tried to copy 'SeaweedFSSSEKMSKey' from the first part to the completed object. This had TWO bugs: 1. **Wrong Constant Name** (Key Mismatch Bug): - Storage uses: SeaweedFSSSEKMSKeyHeader = 'X-SeaweedFS-SSE-KMS-Key' - Old code read: SeaweedFSSSEKMSKey = 'x-seaweedfs-sse-kms-key' - Result: SSE-KMS metadata was NEVER copied → 500 errors 2. **Missing SSE-C and SSE-S3 Headers**: - SSE-C requires: IV, Algorithm, KeyMD5 - SSE-S3 requires: encrypted key data + standard headers - Old code: copied nothing for SSE-C/SSE-S3 → decryption failures **Fix - Complete SSE Header Preservation**: Now copies ALL SSE headers from first part to completed object: - SSE-C: SeaweedFSSSEIV, CustomerAlgorithm, CustomerKeyMD5 - SSE-KMS: SeaweedFSSSEKMSKeyHeader, AwsKmsKeyId, ServerSideEncryption - SSE-S3: SeaweedFSSSES3Key, ServerSideEncryption Applied consistently to all 3 code paths: 1. Versioned buckets (creates version file) 2. Suspended versioning (creates main object with null versionId) 3. Non-versioned buckets (creates main object) **Why This Is Correct**: The headers copied EXACTLY match what putToFiler stores during part upload (lines 496-521 in s3api_object_handlers_put.go). This ensures detectPrimarySSEType() can correctly identify encrypted multipart objects and trigger inline decryption with proper metadata. Fixes: TestSSEMultipartUploadIntegration (SSE-C and SSE-KMS subtests) * s3: Add debug logging for versioning state diagnosis Temporary debug logging to diagnose test_versioning_obj_plain_null_version_overwrite_suspended failure. Added glog.V(0) logging to show: 1. setBucketVersioningStatus: when versioning status is changed 2. PutObjectHandler: what versioning state is detected (Enabled/Suspended/none) 3. PutObjectHandler: which code path is taken (putVersionedObject vs putSuspendedVersioningObject) This will help identify if: - The versioning status is being set correctly in bucket config - The cache is returning stale/incorrect versioning state - The switch statement is correctly routing to suspended vs enabled handlers * s3: Enhanced versioning state tracing for suspended versioning diagnosis Added comprehensive logging across the entire versioning state flow: PutBucketVersioningHandler: - Log requested status (Enabled/Suspended) - Log when calling setBucketVersioningStatus - Log success/failure of status change setBucketVersioningStatus: - Log bucket and status being set - Log when config is updated - Log completion with error code updateBucketConfig: - Log versioning state being written to cache - Immediate cache verification after Set - Log if cache verification fails getVersioningState: - Log bucket name and state being returned - Log if object lock forces VersioningEnabled - Log errors This will reveal: 1. If PutBucketVersioning(Suspended) is reaching the handler 2. If the cache update succeeds 3. What state getVersioningState returns during PUT 4. Any cache consistency issues Expected to show why bucket still reports 'Enabled' after 'Suspended' call. * s3: Add SSE chunk detection debugging for multipart uploads Added comprehensive logging to diagnose why TestSSEMultipartUploadIntegration fails: detectPrimarySSEType now logs: 1. Total chunk count and extended header count 2. All extended headers with 'sse'/'SSE'/'encryption' in the name 3. For each chunk: index, SseType, and whether it has metadata 4. Final SSE type counts (SSE-C, SSE-KMS, SSE-S3) This will reveal if: - Chunks are missing SSE metadata after multipart completion - Extended headers are copied correctly from first part - The SSE detection logic is working correctly Expected to show if chunks have SseType=0 (none) or proper SSE types set. * s3: Trace SSE chunk metadata through multipart completion and retrieval Added end-to-end logging to track SSE chunk metadata lifecycle: **During Multipart Completion (filer_multipart.go)**: 1. Log finalParts chunks BEFORE mkFile - shows SseType and metadata 2. Log versionEntry.Chunks INSIDE mkFile callback - shows if mkFile preserves SSE info 3. Log success after mkFile completes **During GET Retrieval (s3api_object_handlers.go)**: 1. Log retrieved entry chunks - shows SseType and metadata after retrieval 2. Log detected SSE type result This will reveal at which point SSE chunk metadata is lost: - If finalParts have SSE metadata but versionEntry.Chunks don't → mkFile bug - If versionEntry.Chunks have SSE metadata but retrieved chunks don't → storage/retrieval bug - If chunks never have SSE metadata → multipart completion SSE processing bug Expected to show chunks with SseType=NONE during retrieval even though they were created with proper SseType during multipart completion. * s3: Fix SSE-C multipart IV base64 decoding bug **Critical Bug Found**: SSE-C multipart uploads were failing because: Root Cause: - entry.Extended[SeaweedFSSSEIV] stores base64-encoded IV (24 bytes for 16-byte IV) - SerializeSSECMetadata expects raw IV bytes (16 bytes) - During multipart completion, we were passing base64 IV directly → serialization error Error Message: "Failed to serialize SSE-C metadata for chunk in part X: invalid IV length: expected 16 bytes, got 24" Fix: - Base64-decode IV before passing to SerializeSSECMetadata - Added error handling for decode failures Impact: - SSE-C multipart uploads will now correctly serialize chunk metadata - Chunks will have proper SSE metadata for decryption during GET This fixes the SSE-C subtest of TestSSEMultipartUploadIntegration. SSE-KMS still has a separate issue (error code 23) being investigated. * fixes * kms sse * handle retry if not found in .versions folder and should read the normal object * quick check (no retries) to see if the .versions/ directory exists * skip retry if object is not found * explicit update to avoid sync delay * fix map update lock * Remove fmt.Printf debug statements * Fix SSE-KMS multipart base IV fallback to fail instead of regenerating * fmt * Fix ACL grants storage logic * header handling * nil handling * range read for sse content * test range requests for sse objects * fmt * unused code * upload in chunks * header case * fix url * bucket policy error vs bucket not found * jwt handling * fmt * jwt in request header * Optimize Case-Insensitive Prefix Check * dead code * Eliminated Unnecessary Stream Prefetch for Multipart SSE * range sse * sse * refactor * context * fmt * fix type * fix SSE-C IV Mismatch * Fix Headers Being Set After WriteHeader * fix url parsing * propergate sse headers * multipart sse-s3 * aws sig v4 authen * sse kms * set content range * better errors * Update s3api_object_handlers_copy.go * Update s3api_object_handlers.go * Update s3api_object_handlers.go * avoid magic number * clean up * Update s3api_bucket_policy_handlers.go * fix url parsing * context * data and metadata both use background context * adjust the offset * SSE Range Request IV Calculation * adjust logs * IV relative to offset in each part, not the whole file * collect logs * offset * fix offset * fix url * logs * variable * jwt * Multipart ETag semantics: conditionally set object-level Md5 for single-chunk uploads only. * sse * adjust IV and offset * multipart boundaries * ensures PUT and GET operations return consistent ETags * Metadata Header Case * CommonPrefixes Sorting with URL Encoding * always sort * remove the extra PathUnescape call * fix the multipart get part ETag * the FileChunk is created without setting ModifiedTsNs * Sort CommonPrefixes lexicographically to match AWS S3 behavior * set md5 for multipart uploads * prevents any potential data loss or corruption in the small-file inline storage path * compiles correctly * decryptedReader will now be properly closed after use * Fixed URL encoding and sort order for CommonPrefixes * Update s3api_object_handlers_list.go * SSE-x Chunk View Decryption * Different IV offset calculations for single-part vs multipart objects * still too verbose in logs * less logs * ensure correct conversion * fix listing * nil check * minor fixes * nil check * single character delimiter * optimize * range on empty object or zero-length * correct IV based on its position within that part, not its position in the entire object * adjust offset * offset Fetch FULL encrypted chunk (not just the range) Adjust IV by PartOffset/ChunkOffset only Decrypt full chunk Skip in the DECRYPTED stream to reach OffsetInChunk * look breaking * refactor * error on no content * handle intra-block byte skipping * Incomplete HTTP Response Error Handling * multipart SSE * Update s3api_object_handlers.go * address comments * less logs * handling directory * Optimized rejectDirectoryObjectWithoutSlash() to avoid unnecessary lookups * Revert "handling directory" This reverts commit 3a335f0ac33c63f51975abc63c40e5328857a74b. * constant * Consolidate nil entry checks in GetObjectHandler * add range tests * Consolidate redundant nil entry checks in HeadObjectHandler * adjust logs * SSE type * large files * large files Reverted the plain-object range test * ErrNoEncryptionConfig * Fixed SSERangeReader Infinite Loop Vulnerability * Fixed SSE-KMS Multipart ChunkReader HTTP Body Leak * handle empty directory in S3, added PyArrow tests * purge unused code * Update s3_parquet_test.py * Update requirements.txt * According to S3 specifications, when both partNumber and Range are present, the Range should apply within the selected part's boundaries, not to the full object. * handle errors * errors after writing header * https * fix: Wait for volume assignment readiness before running Parquet tests The test-implicit-dir-with-server test was failing with an Internal Error because volume assignment was not ready when tests started. This fix adds a check that attempts a volume assignment and waits for it to succeed before proceeding with tests. This ensures that: 1. Volume servers are registered with the master 2. Volume growth is triggered if needed 3. The system can successfully assign volumes for writes Fixes the timeout issue where boto3 would retry 4 times and fail with 'We encountered an internal error, please try again.' * sse tests * store derived IV * fix: Clean up gRPC ports between tests to prevent port conflicts The second test (test-implicit-dir-with-server) was failing because the volume server's gRPC port (18080 = VOLUME_PORT + 10000) was still in use from the first test. The cleanup code only killed HTTP port processes, not gRPC port processes. Added cleanup for gRPC ports in all stop targets: - Master gRPC: MASTER_PORT + 10000 (19333) - Volume gRPC: VOLUME_PORT + 10000 (18080) - Filer gRPC: FILER_PORT + 10000 (18888) This ensures clean state between test runs in CI. * add import * address comments * docs: Add placeholder documentation files for Parquet test suite Added three missing documentation files referenced in test/s3/parquet/README.md: 1. TEST_COVERAGE.md - Documents 43 total test cases (17 Go unit tests, 6 Python integration tests, 20 Python end-to-end tests) 2. FINAL_ROOT_CAUSE_ANALYSIS.md - Explains the s3fs compatibility issue with PyArrow, the implicit directory problem, and how the fix works 3. MINIO_DIRECTORY_HANDLING.md - Compares MinIO's directory handling approach with SeaweedFS's implementation Each file contains: - Title and overview - Key technical details relevant to the topic - TODO sections for future expansion These placeholder files resolve the broken README links and provide structure for future detailed documentation. * clean up if metadata operation failed * Update s3_parquet_test.py * clean up * Update Makefile * Update s3_parquet_test.py * Update Makefile * Handle ivSkip for non-block-aligned offsets * Update README.md * stop volume server faster * stop volume server in 1 second * different IV for each chunk in SSE-S3 and SSE-KMS * clean up if fails * testing upload * error propagation * fmt * simplify * fix copying * less logs * endian * Added marshaling error handling * handling invalid ranges * error handling for adding to log buffer * fix logging * avoid returning too quickly and ensure proper cleaning up * Activity Tracking for Disk Reads * Cleanup Unused Parameters * Activity Tracking for Kafka Publishers * Proper Test Error Reporting * refactoring * less logs * less logs * go fmt * guard it with if entry.Attributes.TtlSec > 0 to match the pattern used elsewhere. * Handle bucket-default encryption config errors explicitly for multipart * consistent activity tracking * obsolete code for s3 on filer read/write handlers * Update weed/s3api/s3api_object_handlers_list.go Co-authored-by: gemini-code-assist[bot] <176961590+gemini-code-assist[bot]@users.noreply.github.com> --------- Co-authored-by: gemini-code-assist[bot] <176961590+gemini-code-assist[bot]@users.noreply.github.com>
698 lines
22 KiB
Go
698 lines
22 KiB
Go
package log_buffer
|
|
|
|
import (
|
|
"fmt"
|
|
"sync"
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
|
|
"github.com/seaweedfs/seaweedfs/weed/pb/mq_pb"
|
|
"google.golang.org/protobuf/proto"
|
|
)
|
|
|
|
// TestFlushOffsetGap_ReproduceDataLoss reproduces the critical bug where messages
|
|
// are lost in the gap between flushed disk data and in-memory buffer.
|
|
//
|
|
// OBSERVED BEHAVIOR FROM LOGS:
|
|
//
|
|
// Request offset: 1764
|
|
// Disk contains: 1000-1763 (764 messages)
|
|
// Memory buffer starts at: 1800
|
|
// Gap: 1764-1799 (36 messages) ← MISSING!
|
|
//
|
|
// This test verifies:
|
|
// 1. All messages sent to buffer are accounted for
|
|
// 2. No gaps exist between disk and memory offsets
|
|
// 3. Flushed data and in-memory data have continuous offset ranges
|
|
func TestFlushOffsetGap_ReproduceDataLoss(t *testing.T) {
|
|
var flushedMessages []*filer_pb.LogEntry
|
|
var flushMu sync.Mutex
|
|
|
|
flushFn := func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
|
|
t.Logf("FLUSH: minOffset=%d maxOffset=%d size=%d bytes", minOffset, maxOffset, len(buf))
|
|
|
|
// Parse and store flushed messages
|
|
flushMu.Lock()
|
|
defer flushMu.Unlock()
|
|
|
|
// Parse buffer to extract messages
|
|
parsedCount := 0
|
|
for pos := 0; pos+4 < len(buf); {
|
|
if pos+4 > len(buf) {
|
|
break
|
|
}
|
|
|
|
size := uint32(buf[pos])<<24 | uint32(buf[pos+1])<<16 | uint32(buf[pos+2])<<8 | uint32(buf[pos+3])
|
|
if pos+4+int(size) > len(buf) {
|
|
break
|
|
}
|
|
|
|
entryData := buf[pos+4 : pos+4+int(size)]
|
|
logEntry := &filer_pb.LogEntry{}
|
|
if err := proto.Unmarshal(entryData, logEntry); err == nil {
|
|
flushedMessages = append(flushedMessages, logEntry)
|
|
parsedCount++
|
|
}
|
|
|
|
pos += 4 + int(size)
|
|
}
|
|
|
|
t.Logf(" Parsed %d messages from flush buffer", parsedCount)
|
|
}
|
|
|
|
logBuffer := NewLogBuffer("test", 100*time.Millisecond, flushFn, nil, nil)
|
|
defer logBuffer.ShutdownLogBuffer()
|
|
|
|
// Send 100 messages
|
|
messageCount := 100
|
|
t.Logf("Sending %d messages...", messageCount)
|
|
|
|
for i := 0; i < messageCount; i++ {
|
|
if err := logBuffer.AddToBuffer(&mq_pb.DataMessage{
|
|
Key: []byte(fmt.Sprintf("key-%d", i)),
|
|
Value: []byte(fmt.Sprintf("message-%d", i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
}); err != nil {
|
|
t.Fatalf("Failed to add buffer: %v", err)
|
|
}
|
|
}
|
|
|
|
// Force flush multiple times to simulate real workload
|
|
t.Logf("Forcing flush...")
|
|
logBuffer.ForceFlush()
|
|
|
|
// Add more messages after flush
|
|
for i := messageCount; i < messageCount+50; i++ {
|
|
if err := logBuffer.AddToBuffer(&mq_pb.DataMessage{
|
|
Key: []byte(fmt.Sprintf("key-%d", i)),
|
|
Value: []byte(fmt.Sprintf("message-%d", i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
}); err != nil {
|
|
t.Fatalf("Failed to add buffer: %v", err)
|
|
}
|
|
}
|
|
|
|
// Force another flush
|
|
logBuffer.ForceFlush()
|
|
time.Sleep(200 * time.Millisecond) // Wait for flush to complete
|
|
|
|
// Now check the buffer state
|
|
logBuffer.RLock()
|
|
bufferStartOffset := logBuffer.bufferStartOffset
|
|
currentOffset := logBuffer.offset
|
|
pos := logBuffer.pos
|
|
logBuffer.RUnlock()
|
|
|
|
flushMu.Lock()
|
|
flushedCount := len(flushedMessages)
|
|
var maxFlushedOffset int64 = -1
|
|
var minFlushedOffset int64 = -1
|
|
if flushedCount > 0 {
|
|
minFlushedOffset = flushedMessages[0].Offset
|
|
maxFlushedOffset = flushedMessages[flushedCount-1].Offset
|
|
}
|
|
flushMu.Unlock()
|
|
|
|
t.Logf("\nBUFFER STATE AFTER FLUSH:")
|
|
t.Logf(" bufferStartOffset: %d", bufferStartOffset)
|
|
t.Logf(" currentOffset (HWM): %d", currentOffset)
|
|
t.Logf(" pos (bytes in buffer): %d", pos)
|
|
t.Logf(" Messages sent: %d (offsets 0-%d)", messageCount+50, messageCount+49)
|
|
t.Logf(" Messages flushed to disk: %d (offsets %d-%d)", flushedCount, minFlushedOffset, maxFlushedOffset)
|
|
|
|
// CRITICAL CHECK: Is there a gap between flushed data and memory buffer?
|
|
if flushedCount > 0 && maxFlushedOffset >= 0 {
|
|
gap := bufferStartOffset - (maxFlushedOffset + 1)
|
|
|
|
t.Logf("\nOFFSET CONTINUITY CHECK:")
|
|
t.Logf(" Last flushed offset: %d", maxFlushedOffset)
|
|
t.Logf(" Buffer starts at: %d", bufferStartOffset)
|
|
t.Logf(" Gap: %d offsets", gap)
|
|
|
|
if gap > 0 {
|
|
t.Errorf("CRITICAL BUG REPRODUCED: OFFSET GAP DETECTED!")
|
|
t.Errorf(" Disk has offsets %d-%d", minFlushedOffset, maxFlushedOffset)
|
|
t.Errorf(" Memory buffer starts at: %d", bufferStartOffset)
|
|
t.Errorf(" MISSING OFFSETS: %d-%d (%d messages)", maxFlushedOffset+1, bufferStartOffset-1, gap)
|
|
t.Errorf(" These messages are LOST - neither on disk nor in memory!")
|
|
} else if gap < 0 {
|
|
t.Errorf("OFFSET OVERLAP: Memory buffer starts BEFORE last flushed offset!")
|
|
t.Errorf(" This indicates data corruption or race condition")
|
|
} else {
|
|
t.Logf("PASS: No gap detected - offsets are continuous")
|
|
}
|
|
|
|
// Check if we can read all expected offsets
|
|
t.Logf("\nREADABILITY CHECK:")
|
|
for testOffset := int64(0); testOffset < currentOffset; testOffset += 10 {
|
|
// Try to read from buffer
|
|
requestPosition := NewMessagePositionFromOffset(testOffset)
|
|
buf, _, err := logBuffer.ReadFromBuffer(requestPosition)
|
|
|
|
isReadable := (buf != nil && len(buf.Bytes()) > 0) || err == ResumeFromDiskError
|
|
status := "OK"
|
|
if !isReadable && err == nil {
|
|
status = "NOT READABLE"
|
|
}
|
|
|
|
t.Logf(" Offset %d: %s (buf=%v, err=%v)", testOffset, status, buf != nil, err)
|
|
|
|
// If offset is in the gap, it should fail to read
|
|
if flushedCount > 0 && testOffset > maxFlushedOffset && testOffset < bufferStartOffset {
|
|
if isReadable {
|
|
t.Errorf(" Unexpected: Offset %d in gap range should NOT be readable!", testOffset)
|
|
} else {
|
|
t.Logf(" Expected: Offset %d in gap is not readable (data lost)", testOffset)
|
|
}
|
|
}
|
|
}
|
|
}
|
|
|
|
// Check that all sent messages are accounted for
|
|
expectedMessageCount := messageCount + 50
|
|
messagesInMemory := int(currentOffset - bufferStartOffset)
|
|
totalAccountedFor := flushedCount + messagesInMemory
|
|
|
|
t.Logf("\nMESSAGE ACCOUNTING:")
|
|
t.Logf(" Expected: %d messages", expectedMessageCount)
|
|
t.Logf(" Flushed to disk: %d", flushedCount)
|
|
t.Logf(" In memory buffer: %d (offset range %d-%d)", messagesInMemory, bufferStartOffset, currentOffset-1)
|
|
t.Logf(" Total accounted for: %d", totalAccountedFor)
|
|
t.Logf(" Missing: %d messages", expectedMessageCount-totalAccountedFor)
|
|
|
|
if totalAccountedFor < expectedMessageCount {
|
|
t.Errorf("DATA LOSS CONFIRMED: %d messages are missing!", expectedMessageCount-totalAccountedFor)
|
|
} else {
|
|
t.Logf("All messages accounted for")
|
|
}
|
|
}
|
|
|
|
// TestFlushOffsetGap_CheckPrevBuffers tests if messages might be stuck in prevBuffers
|
|
// instead of being properly flushed to disk.
|
|
func TestFlushOffsetGap_CheckPrevBuffers(t *testing.T) {
|
|
var flushCount int
|
|
var flushMu sync.Mutex
|
|
|
|
flushFn := func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
|
|
flushMu.Lock()
|
|
flushCount++
|
|
count := flushCount
|
|
flushMu.Unlock()
|
|
|
|
t.Logf("FLUSH #%d: minOffset=%d maxOffset=%d size=%d bytes", count, minOffset, maxOffset, len(buf))
|
|
}
|
|
|
|
logBuffer := NewLogBuffer("test", 100*time.Millisecond, flushFn, nil, nil)
|
|
defer logBuffer.ShutdownLogBuffer()
|
|
|
|
// Send messages in batches with flushes in between
|
|
for batch := 0; batch < 5; batch++ {
|
|
t.Logf("\nBatch %d:", batch)
|
|
|
|
// Send 20 messages
|
|
for i := 0; i < 20; i++ {
|
|
offset := int64(batch*20 + i)
|
|
if err := logBuffer.AddToBuffer(&mq_pb.DataMessage{
|
|
Key: []byte(fmt.Sprintf("key-%d", offset)),
|
|
Value: []byte(fmt.Sprintf("message-%d", offset)),
|
|
TsNs: time.Now().UnixNano(),
|
|
}); err != nil {
|
|
t.Fatalf("Failed to add buffer: %v", err)
|
|
}
|
|
}
|
|
|
|
// Check state before flush
|
|
logBuffer.RLock()
|
|
beforeFlushOffset := logBuffer.offset
|
|
beforeFlushStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
|
|
// Force flush
|
|
logBuffer.ForceFlush()
|
|
time.Sleep(50 * time.Millisecond)
|
|
|
|
// Check state after flush
|
|
logBuffer.RLock()
|
|
afterFlushOffset := logBuffer.offset
|
|
afterFlushStart := logBuffer.bufferStartOffset
|
|
prevBufferCount := len(logBuffer.prevBuffers.buffers)
|
|
|
|
// Check prevBuffers state
|
|
t.Logf(" Before flush: offset=%d, bufferStartOffset=%d", beforeFlushOffset, beforeFlushStart)
|
|
t.Logf(" After flush: offset=%d, bufferStartOffset=%d, prevBuffers=%d",
|
|
afterFlushOffset, afterFlushStart, prevBufferCount)
|
|
|
|
// Check each prevBuffer
|
|
for i, prevBuf := range logBuffer.prevBuffers.buffers {
|
|
if prevBuf.size > 0 {
|
|
t.Logf(" prevBuffer[%d]: offsets %d-%d, size=%d bytes (NOT FLUSHED!)",
|
|
i, prevBuf.startOffset, prevBuf.offset, prevBuf.size)
|
|
}
|
|
}
|
|
logBuffer.RUnlock()
|
|
|
|
// CRITICAL: Check if bufferStartOffset advanced correctly
|
|
expectedNewStart := beforeFlushOffset
|
|
if afterFlushStart != expectedNewStart {
|
|
t.Errorf(" bufferStartOffset mismatch!")
|
|
t.Errorf(" Expected: %d (= offset before flush)", expectedNewStart)
|
|
t.Errorf(" Actual: %d", afterFlushStart)
|
|
t.Errorf(" Gap: %d offsets", expectedNewStart-afterFlushStart)
|
|
}
|
|
}
|
|
}
|
|
|
|
// TestFlushOffsetGap_ConcurrentWriteAndFlush tests for race conditions
|
|
// between writing new messages and flushing old ones.
|
|
func TestFlushOffsetGap_ConcurrentWriteAndFlush(t *testing.T) {
|
|
var allFlushedOffsets []int64
|
|
var flushMu sync.Mutex
|
|
|
|
flushFn := func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
|
|
t.Logf("FLUSH: offsets %d-%d (%d bytes)", minOffset, maxOffset, len(buf))
|
|
|
|
flushMu.Lock()
|
|
// Record the offset range that was flushed
|
|
for offset := minOffset; offset <= maxOffset; offset++ {
|
|
allFlushedOffsets = append(allFlushedOffsets, offset)
|
|
}
|
|
flushMu.Unlock()
|
|
}
|
|
|
|
logBuffer := NewLogBuffer("test", 50*time.Millisecond, flushFn, nil, nil)
|
|
defer logBuffer.ShutdownLogBuffer()
|
|
|
|
// Concurrently write messages and force flushes
|
|
var wg sync.WaitGroup
|
|
|
|
// Writer goroutine
|
|
wg.Add(1)
|
|
go func() {
|
|
defer wg.Done()
|
|
for i := 0; i < 200; i++ {
|
|
if err := logBuffer.AddToBuffer(&mq_pb.DataMessage{
|
|
Key: []byte(fmt.Sprintf("key-%d", i)),
|
|
Value: []byte(fmt.Sprintf("message-%d", i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
}); err != nil {
|
|
t.Errorf("Failed to add buffer: %v", err)
|
|
return
|
|
}
|
|
if i%50 == 0 {
|
|
time.Sleep(10 * time.Millisecond)
|
|
}
|
|
}
|
|
}()
|
|
|
|
// Flusher goroutine
|
|
wg.Add(1)
|
|
go func() {
|
|
defer wg.Done()
|
|
for i := 0; i < 5; i++ {
|
|
time.Sleep(30 * time.Millisecond)
|
|
logBuffer.ForceFlush()
|
|
}
|
|
}()
|
|
|
|
wg.Wait()
|
|
time.Sleep(200 * time.Millisecond) // Wait for final flush
|
|
|
|
// Check final state
|
|
logBuffer.RLock()
|
|
finalOffset := logBuffer.offset
|
|
finalBufferStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
|
|
flushMu.Lock()
|
|
flushedCount := len(allFlushedOffsets)
|
|
flushMu.Unlock()
|
|
|
|
expectedCount := int(finalOffset)
|
|
inMemory := int(finalOffset - finalBufferStart)
|
|
totalAccountedFor := flushedCount + inMemory
|
|
|
|
t.Logf("\nFINAL STATE:")
|
|
t.Logf(" Total messages sent: %d (offsets 0-%d)", expectedCount, expectedCount-1)
|
|
t.Logf(" Flushed to disk: %d", flushedCount)
|
|
t.Logf(" In memory: %d (offsets %d-%d)", inMemory, finalBufferStart, finalOffset-1)
|
|
t.Logf(" Total accounted: %d", totalAccountedFor)
|
|
t.Logf(" Missing: %d", expectedCount-totalAccountedFor)
|
|
|
|
if totalAccountedFor < expectedCount {
|
|
t.Errorf("DATA LOSS in concurrent scenario: %d messages missing!", expectedCount-totalAccountedFor)
|
|
}
|
|
}
|
|
|
|
// TestFlushOffsetGap_ProductionScenario reproduces the actual production scenario
|
|
// where the broker uses AddLogEntryToBuffer with explicit Kafka offsets.
|
|
// This simulates leader publishing with offset assignment.
|
|
func TestFlushOffsetGap_ProductionScenario(t *testing.T) {
|
|
var flushedData []struct {
|
|
minOffset int64
|
|
maxOffset int64
|
|
messages []*filer_pb.LogEntry
|
|
}
|
|
var flushMu sync.Mutex
|
|
|
|
flushFn := func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
|
|
// Parse messages from buffer
|
|
messages := []*filer_pb.LogEntry{}
|
|
for pos := 0; pos+4 < len(buf); {
|
|
size := uint32(buf[pos])<<24 | uint32(buf[pos+1])<<16 | uint32(buf[pos+2])<<8 | uint32(buf[pos+3])
|
|
if pos+4+int(size) > len(buf) {
|
|
break
|
|
}
|
|
entryData := buf[pos+4 : pos+4+int(size)]
|
|
logEntry := &filer_pb.LogEntry{}
|
|
if err := proto.Unmarshal(entryData, logEntry); err == nil {
|
|
messages = append(messages, logEntry)
|
|
}
|
|
pos += 4 + int(size)
|
|
}
|
|
|
|
flushMu.Lock()
|
|
flushedData = append(flushedData, struct {
|
|
minOffset int64
|
|
maxOffset int64
|
|
messages []*filer_pb.LogEntry
|
|
}{minOffset, maxOffset, messages})
|
|
flushMu.Unlock()
|
|
|
|
t.Logf("FLUSH: minOffset=%d maxOffset=%d, parsed %d messages", minOffset, maxOffset, len(messages))
|
|
}
|
|
|
|
logBuffer := NewLogBuffer("test", time.Hour, flushFn, nil, nil)
|
|
defer logBuffer.ShutdownLogBuffer()
|
|
|
|
// Simulate broker behavior: assign Kafka offsets and add to buffer
|
|
// This is what PublishWithOffset() does
|
|
nextKafkaOffset := int64(0)
|
|
|
|
// Round 1: Add 50 messages with Kafka offsets 0-49
|
|
t.Logf("\n=== ROUND 1: Adding messages 0-49 ===")
|
|
for i := 0; i < 50; i++ {
|
|
logEntry := &filer_pb.LogEntry{
|
|
Key: []byte(fmt.Sprintf("key-%d", i)),
|
|
Data: []byte(fmt.Sprintf("message-%d", i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
Offset: nextKafkaOffset, // Explicit Kafka offset
|
|
}
|
|
if err := logBuffer.AddLogEntryToBuffer(logEntry); err != nil {
|
|
t.Fatalf("Failed to add log entry: %v", err)
|
|
}
|
|
nextKafkaOffset++
|
|
}
|
|
|
|
// Check buffer state before flush
|
|
logBuffer.RLock()
|
|
beforeFlushOffset := logBuffer.offset
|
|
beforeFlushStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
t.Logf("Before flush: logBuffer.offset=%d, bufferStartOffset=%d, nextKafkaOffset=%d",
|
|
beforeFlushOffset, beforeFlushStart, nextKafkaOffset)
|
|
|
|
// Flush
|
|
logBuffer.ForceFlush()
|
|
time.Sleep(100 * time.Millisecond)
|
|
|
|
// Check buffer state after flush
|
|
logBuffer.RLock()
|
|
afterFlushOffset := logBuffer.offset
|
|
afterFlushStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
t.Logf("After flush: logBuffer.offset=%d, bufferStartOffset=%d",
|
|
afterFlushOffset, afterFlushStart)
|
|
|
|
// Round 2: Add another 50 messages with Kafka offsets 50-99
|
|
t.Logf("\n=== ROUND 2: Adding messages 50-99 ===")
|
|
for i := 0; i < 50; i++ {
|
|
logEntry := &filer_pb.LogEntry{
|
|
Key: []byte(fmt.Sprintf("key-%d", 50+i)),
|
|
Data: []byte(fmt.Sprintf("message-%d", 50+i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
Offset: nextKafkaOffset,
|
|
}
|
|
if err := logBuffer.AddLogEntryToBuffer(logEntry); err != nil {
|
|
t.Fatalf("Failed to add log entry: %v", err)
|
|
}
|
|
nextKafkaOffset++
|
|
}
|
|
|
|
logBuffer.ForceFlush()
|
|
time.Sleep(100 * time.Millisecond)
|
|
|
|
// Verification: Check if all Kafka offsets are accounted for
|
|
flushMu.Lock()
|
|
t.Logf("\n=== VERIFICATION ===")
|
|
t.Logf("Expected Kafka offsets: 0-%d", nextKafkaOffset-1)
|
|
|
|
allOffsets := make(map[int64]bool)
|
|
for flushIdx, flush := range flushedData {
|
|
t.Logf("Flush #%d: minOffset=%d, maxOffset=%d, messages=%d",
|
|
flushIdx, flush.minOffset, flush.maxOffset, len(flush.messages))
|
|
|
|
for _, msg := range flush.messages {
|
|
if allOffsets[msg.Offset] {
|
|
t.Errorf(" DUPLICATE: Offset %d appears multiple times!", msg.Offset)
|
|
}
|
|
allOffsets[msg.Offset] = true
|
|
}
|
|
}
|
|
flushMu.Unlock()
|
|
|
|
// Check for missing offsets
|
|
missingOffsets := []int64{}
|
|
for expectedOffset := int64(0); expectedOffset < nextKafkaOffset; expectedOffset++ {
|
|
if !allOffsets[expectedOffset] {
|
|
missingOffsets = append(missingOffsets, expectedOffset)
|
|
}
|
|
}
|
|
|
|
if len(missingOffsets) > 0 {
|
|
t.Errorf("\nMISSING OFFSETS DETECTED: %d offsets missing", len(missingOffsets))
|
|
if len(missingOffsets) <= 20 {
|
|
t.Errorf("Missing: %v", missingOffsets)
|
|
} else {
|
|
t.Errorf("Missing: %v ... and %d more", missingOffsets[:20], len(missingOffsets)-20)
|
|
}
|
|
t.Errorf("\nThis reproduces the production bug!")
|
|
} else {
|
|
t.Logf("\nSUCCESS: All %d Kafka offsets accounted for (0-%d)", nextKafkaOffset, nextKafkaOffset-1)
|
|
}
|
|
|
|
// Check buffer offset consistency
|
|
logBuffer.RLock()
|
|
finalOffset := logBuffer.offset
|
|
finalBufferStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
|
|
t.Logf("\nFinal buffer state:")
|
|
t.Logf(" logBuffer.offset: %d", finalOffset)
|
|
t.Logf(" bufferStartOffset: %d", finalBufferStart)
|
|
t.Logf(" Expected (nextKafkaOffset): %d", nextKafkaOffset)
|
|
|
|
if finalOffset != nextKafkaOffset {
|
|
t.Errorf("logBuffer.offset mismatch: expected %d, got %d", nextKafkaOffset, finalOffset)
|
|
}
|
|
}
|
|
|
|
// TestFlushOffsetGap_ConcurrentReadDuringFlush tests if concurrent reads
|
|
// during flush can cause messages to be missed.
|
|
func TestFlushOffsetGap_ConcurrentReadDuringFlush(t *testing.T) {
|
|
var flushedOffsets []int64
|
|
var flushMu sync.Mutex
|
|
|
|
readFromDiskFn := func(startPosition MessagePosition, stopTsNs int64, eachLogEntryFn EachLogEntryFuncType) (MessagePosition, bool, error) {
|
|
// Simulate reading from disk - return flushed offsets
|
|
flushMu.Lock()
|
|
defer flushMu.Unlock()
|
|
|
|
for _, offset := range flushedOffsets {
|
|
if offset >= startPosition.Offset {
|
|
logEntry := &filer_pb.LogEntry{
|
|
Key: []byte(fmt.Sprintf("key-%d", offset)),
|
|
Data: []byte(fmt.Sprintf("message-%d", offset)),
|
|
TsNs: time.Now().UnixNano(),
|
|
Offset: offset,
|
|
}
|
|
isDone, err := eachLogEntryFn(logEntry)
|
|
if err != nil || isDone {
|
|
return NewMessagePositionFromOffset(offset + 1), isDone, err
|
|
}
|
|
}
|
|
}
|
|
return startPosition, false, nil
|
|
}
|
|
|
|
flushFn := func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
|
|
// Parse and store flushed offsets
|
|
flushMu.Lock()
|
|
defer flushMu.Unlock()
|
|
|
|
for pos := 0; pos+4 < len(buf); {
|
|
size := uint32(buf[pos])<<24 | uint32(buf[pos+1])<<16 | uint32(buf[pos+2])<<8 | uint32(buf[pos+3])
|
|
if pos+4+int(size) > len(buf) {
|
|
break
|
|
}
|
|
entryData := buf[pos+4 : pos+4+int(size)]
|
|
logEntry := &filer_pb.LogEntry{}
|
|
if err := proto.Unmarshal(entryData, logEntry); err == nil {
|
|
flushedOffsets = append(flushedOffsets, logEntry.Offset)
|
|
}
|
|
pos += 4 + int(size)
|
|
}
|
|
|
|
t.Logf("FLUSH: Stored %d offsets to disk (minOffset=%d, maxOffset=%d)",
|
|
len(flushedOffsets), minOffset, maxOffset)
|
|
}
|
|
|
|
logBuffer := NewLogBuffer("test", time.Hour, flushFn, readFromDiskFn, nil)
|
|
defer logBuffer.ShutdownLogBuffer()
|
|
|
|
// Add 100 messages
|
|
t.Logf("Adding 100 messages...")
|
|
for i := int64(0); i < 100; i++ {
|
|
logEntry := &filer_pb.LogEntry{
|
|
Key: []byte(fmt.Sprintf("key-%d", i)),
|
|
Data: []byte(fmt.Sprintf("message-%d", i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
Offset: i,
|
|
}
|
|
if err := logBuffer.AddLogEntryToBuffer(logEntry); err != nil {
|
|
t.Fatalf("Failed to add log entry: %v", err)
|
|
}
|
|
}
|
|
|
|
// Flush (moves data to disk)
|
|
t.Logf("Flushing...")
|
|
logBuffer.ForceFlush()
|
|
time.Sleep(100 * time.Millisecond)
|
|
|
|
// Now try to read all messages using ReadMessagesAtOffset
|
|
t.Logf("\nReading messages from offset 0...")
|
|
messages, nextOffset, hwm, endOfPartition, err := logBuffer.ReadMessagesAtOffset(0, 1000, 1024*1024)
|
|
|
|
t.Logf("Read result: messages=%d, nextOffset=%d, hwm=%d, endOfPartition=%v, err=%v",
|
|
len(messages), nextOffset, hwm, endOfPartition, err)
|
|
|
|
// Verify all offsets can be read
|
|
readOffsets := make(map[int64]bool)
|
|
for _, msg := range messages {
|
|
readOffsets[msg.Offset] = true
|
|
}
|
|
|
|
missingOffsets := []int64{}
|
|
for expectedOffset := int64(0); expectedOffset < 100; expectedOffset++ {
|
|
if !readOffsets[expectedOffset] {
|
|
missingOffsets = append(missingOffsets, expectedOffset)
|
|
}
|
|
}
|
|
|
|
if len(missingOffsets) > 0 {
|
|
t.Errorf("MISSING OFFSETS after flush: %d offsets cannot be read", len(missingOffsets))
|
|
if len(missingOffsets) <= 20 {
|
|
t.Errorf("Missing: %v", missingOffsets)
|
|
} else {
|
|
t.Errorf("Missing: %v ... and %d more", missingOffsets[:20], len(missingOffsets)-20)
|
|
}
|
|
} else {
|
|
t.Logf("All 100 offsets can be read after flush")
|
|
}
|
|
}
|
|
|
|
// TestFlushOffsetGap_ForceFlushAdvancesBuffer tests if ForceFlush
|
|
// properly advances bufferStartOffset after flushing.
|
|
func TestFlushOffsetGap_ForceFlushAdvancesBuffer(t *testing.T) {
|
|
flushedRanges := []struct{ min, max int64 }{}
|
|
var flushMu sync.Mutex
|
|
|
|
flushFn := func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
|
|
flushMu.Lock()
|
|
flushedRanges = append(flushedRanges, struct{ min, max int64 }{minOffset, maxOffset})
|
|
flushMu.Unlock()
|
|
t.Logf("FLUSH: offsets %d-%d", minOffset, maxOffset)
|
|
}
|
|
|
|
logBuffer := NewLogBuffer("test", time.Hour, flushFn, nil, nil) // Long interval, manual flush only
|
|
defer logBuffer.ShutdownLogBuffer()
|
|
|
|
// Send messages, flush, check state - repeat
|
|
for round := 0; round < 3; round++ {
|
|
t.Logf("\n=== ROUND %d ===", round)
|
|
|
|
// Check state before adding messages
|
|
logBuffer.RLock()
|
|
beforeOffset := logBuffer.offset
|
|
beforeStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
|
|
t.Logf("Before adding: offset=%d, bufferStartOffset=%d", beforeOffset, beforeStart)
|
|
|
|
// Add 10 messages
|
|
for i := 0; i < 10; i++ {
|
|
if err := logBuffer.AddToBuffer(&mq_pb.DataMessage{
|
|
Key: []byte(fmt.Sprintf("round-%d-msg-%d", round, i)),
|
|
Value: []byte(fmt.Sprintf("data-%d-%d", round, i)),
|
|
TsNs: time.Now().UnixNano(),
|
|
}); err != nil {
|
|
t.Fatalf("Failed to add buffer: %v", err)
|
|
}
|
|
}
|
|
|
|
// Check state after adding
|
|
logBuffer.RLock()
|
|
afterAddOffset := logBuffer.offset
|
|
afterAddStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
|
|
t.Logf("After adding: offset=%d, bufferStartOffset=%d", afterAddOffset, afterAddStart)
|
|
|
|
// Force flush
|
|
t.Logf("Forcing flush...")
|
|
logBuffer.ForceFlush()
|
|
time.Sleep(100 * time.Millisecond)
|
|
|
|
// Check state after flush
|
|
logBuffer.RLock()
|
|
afterFlushOffset := logBuffer.offset
|
|
afterFlushStart := logBuffer.bufferStartOffset
|
|
logBuffer.RUnlock()
|
|
|
|
t.Logf("After flush: offset=%d, bufferStartOffset=%d", afterFlushOffset, afterFlushStart)
|
|
|
|
// CRITICAL CHECK: bufferStartOffset should advance to where offset was before flush
|
|
if afterFlushStart != afterAddOffset {
|
|
t.Errorf("FLUSH BUG: bufferStartOffset did NOT advance correctly!")
|
|
t.Errorf(" Expected bufferStartOffset=%d (= offset after add)", afterAddOffset)
|
|
t.Errorf(" Actual bufferStartOffset=%d", afterFlushStart)
|
|
t.Errorf(" Gap: %d offsets WILL BE LOST", afterAddOffset-afterFlushStart)
|
|
} else {
|
|
t.Logf("bufferStartOffset correctly advanced to %d", afterFlushStart)
|
|
}
|
|
}
|
|
|
|
// Final verification: check all offset ranges are continuous
|
|
flushMu.Lock()
|
|
t.Logf("\n=== FLUSHED RANGES ===")
|
|
for i, r := range flushedRanges {
|
|
t.Logf("Flush #%d: offsets %d-%d", i, r.min, r.max)
|
|
|
|
// Check continuity with previous flush
|
|
if i > 0 {
|
|
prevMax := flushedRanges[i-1].max
|
|
currentMin := r.min
|
|
gap := currentMin - (prevMax + 1)
|
|
|
|
if gap > 0 {
|
|
t.Errorf("GAP between flush #%d and #%d: %d offsets missing!", i-1, i, gap)
|
|
} else if gap < 0 {
|
|
t.Errorf("OVERLAP between flush #%d and #%d: %d offsets duplicated!", i-1, i, -gap)
|
|
} else {
|
|
t.Logf(" Continuous with previous flush")
|
|
}
|
|
}
|
|
}
|
|
flushMu.Unlock()
|
|
}
|