nil pointer dereference in valueLog.write

[damz]

What version of Go are you using (go version)?

% go version
go version go1.13.5 linux/amd64

What version of Badger are you using?

465f28a

What did you do?

I just hit the following nil pointer dereference:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0xa5ca42]

goroutine 3336745 [running]:
github.com/dgraph-io/badger/v2.(*valueLog).write(0xc0ddfb81e0, 0xc145d1b7c0, 0x19, 0x28, 0x0, 0x0)
        badger/value.go:1365 +0x272
github.com/dgraph-io/badger/v2.(*DB).writeRequests(0xc0ddfb8000, 0xc145d1b7c0, 0x19, 0x28, 0xa6d25e, 0xc1359a5c80)
        badger/db.go:691 +0x106
github.com/dgraph-io/badger/v2.(*DB).doWrites.func1(0xc145d1b7c0, 0x19, 0x28)
        badger/db.go:763 +0x5a
created by github.com/dgraph-io/badger/v2.(*DB).doWrites
        badger/db.go:816 +0x329

This is on the database closing path.

[damz]

In the use case I'm working on, we have multiple badger database instances in the same process. As far as I can tell, there should be no concurrent writes happening to the database that was closing at the point of the crash.

[damz]

Chances are I'm doing something stupid here. But I would love a second pair of eyes on this.

[jarifibrahim]

@damz Are you closing the same badger instance multiple times?
Your program got a nil exception on this line

badger/value.go

Line 1365 in 0f2e629

p.Fid = curlf.fid

The curlf which is the current vlog file being written would not be nil under normal circumstances.

[damz]

Are you closing the same badger instance multiple times?

@jarifibrahim Not that I know of. And DB.Close runs into a sync.Once anyway. From the look of it, it feels like valueLog.write is called concurrently. But that is not something that should be happening.

I reproduced the issue a second time, basically at the same point. It seems to be happening when Close has to run a big L0 compaction.

[damz]

I tracked it down: it is crashing because it failed to create a vlog file on the previous iteration:

Create value log file. Path=/tmp/foo2/2020-01-02T00:00:00Z.2b0dd3352adbb6fc.db/metrics/000090.vlog. Error=open /tmp/foo2/2020-01-02T00:00:00Z.2b0dd3352adbb6fc.db/metrics/000090.vlog: too many open files

Once this happens, the next call to valueLog.write will crash.

[jarifibrahim]

The problem seems to be over here (and a few other places where we create vlog file)

badger/value.go

Lines 1388 to 1394 in 2a90c66

	newid := atomic.AddUint32(&vlog.maxFid, 1)
	y.AssertTruef(newid > 0, "newid has overflown uint32: %v", newid)
	newlf, err := vlog.createVlogFile(newid)
	if err != nil {
	return err
	}
	curlf = newlf

We've updated the maxFid but if we fail to create the vlog file we should decrement the maxFid which we're not doing right now.

Thanks for digging into this @damz . I'll send a patch to fix this.

[damz]

It is difficult for me to make sense of this maxFid property. It seems like the only place it is accessed in a concurrent context (not locked) is really the assertion on top of the valueLog.Read method.

The code there looks massively racy: it is accessing the maxFid value and then reading the offset (which might at this point relate to a new vlog file). It then proceeds to actually locking the file and reading it.

If that check could be moved inside valueLog.readValueBytes it looks like there would not be a need for atomic access to this variable and it feels like it would remove some of the confusion.

[jarifibrahim]

It is difficult for me to make sense of this maxFid property.

maxFid is the vlog file actively being written. All new writes will be added to vlog file with id=maxFid.

The code there looks massively racy: it is accessing the maxFid value and then reading the offset (which might at this point relate to a new vlog file). It then proceeds to actually locking the file and reading it.

I guess this is the code you're talking about

badger/value.go

Lines 1465 to 1470 in 2a90c66

	maxFid := atomic.LoadUint32(&vlog.maxFid)
	if vp.Fid == maxFid && vp.Offset >= vlog.woffset() {
	return nil, nil, errors.Errorf(
	"Invalid value pointer offset: %d greater than current offset: %d",
	vp.Offset, vlog.woffset())
	}

The woffset might have changed between line 1465 and 1466 but it doesn't matter here because the vp.offset will not change and the check on the line 1466 is just to ensure the read is within file limits.
Also, note that woffset() is accessed atomically

badger/value.go

Lines 1346 to 1349 in 2a90c66

	func (vlog *valueLog) woffset() uint32 {
	return atomic.LoadUint32(&vlog.writableLogOffset)
	}

If that check could be moved inside valueLog.readValueBytes it looks like there would not be a need for atomic access to this variable and it feels like it would remove some of the confusion.

We would still need the check. What if the vp.offset points to a file that no longer exists?

[damz]

The woffset might have changed between line 1465 and 1466 but it doesn't matter here because the vp.offset will not change and the check on the line 1466 is just to ensure the read is within file limits.

Unless I am missing something, this is actually really bad. If the new log file is created between line 1465 and 1466, the offset will reference to the new file, and as a consequence will be reset to the size of the header by valueLog.createVlogFile.

These two checks ("is this the last file" and "is the offset within the bounds of that last file") need to happen atomically. One way of doing that would be to keep valueLog.writableLogOffset but only check maxFid under valueLog.filesLock.RLock and only update it under valueLog.filesLock.Lock.