Destroy() creates directory on Windows

[vweevers]

Repro:

test('destroy does not create a directory', function (t) {
  t.plan(3)

  const location = path.resolve('destroy-test')

  rimraf.sync(location)
  t.is(fs.existsSync(location), false, 'exists before')

  leveldown.destroy(location, function (err) {
    t.ifError(err, 'no error')
    t.is(fs.existsSync(location), false, 'exists after') // Fails
  })
})

Here's the relevant C++, comments mine:

Status DestroyDB(const std::string& dbname /*, .. */) {
  FileLock* lock;
  const std::string lockname = LockFileName(dbname); // "<location>/LOCK"
  Status result = env->LockFile(lockname, &lock); // Creates <location>/LOCK
  
  if (result.ok()) {
    // Delete files..
    // ..

    env->UnlockFile(lock);
    env->DeleteFile(lockname); // Succeeds, directory is empty
    env->DeleteDir(dbname);    // Yet this fails
  }

  return result;
}

The DeleteDir fails (silently) with:

IO error: Failed to remove dir: D:\xx\Level\rocksdb\destroy-test: Directory not empty

[ralphtheninja]

@vweevers Great find!

[ralphtheninja]

I just had a quick look and this is in the upstream code.

[ralphtheninja]

Current master looks identical

https://github.com/facebook/rocksdb/blob/edc258127ef5e64469798e0fa3696e1a9131effd/db/db_impl.cc#L2434-L2439

[vweevers]

Found the cause. There's a LOG file left when DeleteDir is called.

1. DestroyDB calls SanitizeOptions:

rocksdb/deps/leveldb/leveldb-rocksdb/db/db_impl.cc

Lines 6205 to 6206 in fc844eb

	Status DestroyDB(const std::string& dbname, const Options& options) {
	const ImmutableDBOptions soptions(SanitizeOptions(dbname, options));

2. Which calls CreateLoggerFromOptions:

rocksdb/deps/leveldb/leveldb-rocksdb/db/db_impl.cc

Lines 144 to 150 in fc844eb

	if (result.info_log == nullptr) {
	Status s = CreateLoggerFromOptions(dbname, result, &result.info_log);
	if (!s.ok()) {
	// No place suitable for logging
	result.info_log = nullptr;
	}
	}

3. Which creates the directory (!):

rocksdb/deps/leveldb/leveldb-rocksdb/db/auto_roll_logger.cc

Line 150 in fc844eb

env->CreateDirIfMissing(dbname); // In case it does not exist

4. And instantiates a Logger (not sure what this is for):

rocksdb/deps/leveldb/leveldb-rocksdb/db/auto_roll_logger.cc

Lines 170 to 173 in fc844eb

	auto s = env->NewLogger(fname, logger);
	if (logger->get() != nullptr) {
	(*logger)->SetInfoLogLevel(options.info_log_level);
	}

5. On Windows, the concrete implementation of that Logger is:

rocksdb/deps/leveldb/leveldb-rocksdb/port/win/win_logger.cc

Lines 31 to 52 in fc844eb

	WinLogger::WinLogger(uint64_t (*gettid)(), Env* env, HANDLE file,
	const InfoLogLevel log_level)
	: Logger(log_level),
	file_(file),
	gettid_(gettid),
	log_size_(0),
	last_flush_micros_(0),
	env_(env),
	flush_pending_(false) {}
	void WinLogger::DebugWriter(const char* str, int len) {
	DWORD bytesWritten = 0;
	BOOL ret = WriteFile(file_, str, len, &bytesWritten, NULL);
	if (ret == FALSE) {
	std::string errSz = GetWindowsErrSz(GetLastError());
	fprintf(stderr, errSz.c_str());
	}
	}
	WinLogger::~WinLogger() { close(); }
	void WinLogger::close() { CloseHandle(file_); }

6. When DestroyDB iterates the files in the directory, the delete call succeeds (I checked):

rocksdb/deps/leveldb/leveldb-rocksdb/db/db_impl.cc

Line 6230 in fc844eb

del = env->DeleteFile(path_to_delete);

7. But the Logger still has a open file handle. Windows marks the file for deletion, but won't actually delete the file until all handles are released. And that is why the call to DeleteDir at the end fails:

rocksdb/deps/leveldb/leveldb-rocksdb/db/db_impl.cc

Line 6289 in fc844eb

env->DeleteDir(dbname); // Ignore error in case dir contains other files

[vweevers]

Open questions:

• Is all of this the same upstream?
• When is the logger closed?
• Can we disable the logger?

[ralphtheninja]

Is all of this the same upstream?

Afaik, everything under rocksdb/deps/leveldb/leveldb-rocksdb is the same upstream.

When is the logger closed?

No idea.

Can we disable the logger?

Maybe we could through options (guessing). There's #13 that @MeirionHughes created. Might be related.

[ralphtheninja]

@vweevers What does the LOG file contain? Is it just for debugging?

[vweevers]

Yeah, info, warnings and errors it seems.

[ralphtheninja]

Sheesh. That's a tonne of i/o enabled by default.

[vweevers]

Oh, no, I didn't check which log levels are enabled by default.

[vweevers]

Also I can't find an option to completely disable the log, but there is an option to change its path:

rocksdb/deps/leveldb/leveldb-rocksdb/db/auto_roll_logger.cc

Lines 147 to 148 in fc844eb

	std::string fname =
	InfoLogFileName(dbname, db_absolute_path, options.db_log_dir);

[ralphtheninja]

Gawd. Logging should never be enabled by default 🙄

[ralphtheninja]

Hmm, but what about the caller of CreateLoggerFromOptions()

[ralphtheninja]

Was about to post an issue about it but if you have questions you need to use facebook lol.

[vweevers]

We could implement our own noop-logger and pass it to rocksdb via the options.

[vweevers]

See also facebook/rocksdb#494.

[ralphtheninja]

I can't believe there's no option for turning off the logging completely. It seems you can only tune the log level which is not what we want.

[ralphtheninja]

We could implement our own noop-logger and pass it to rocksdb via the options.

We could also have a fork of the whole project, with logging disabled 😀

[ralphtheninja]

One the one hand I think trying to close the LOG file would be the simplest fix, because then there would be no file handle to it and destroy will work.

One the other hand something tells me that it might be difficult to get this right since all form of logging basically can take place anywhere in the code base.

So the real fix is probably implementing our own no-op logger. However, if we do that, this would change behavior and we should release a new major.

[vweevers]

Agree. Disabling logging not only fixes the destroy issue, but also, well, gets rid of the logging 😸

It should be an option though (defaulting to disabled). And since this diverges from leveldown, we should also copy leveldown's API docs to here, and document the additional option(s).

How would it look like in JS-land?

levelup(rocksdb(location), { log: true })

Or make it a loglevel, adding none to rocksdb's loglevels?

levelup(rocksdb(location), { loglevel: 'none' }) // our default
levelup(rocksdb(location), { loglevel: 'info' })
levelup(rocksdb(location), { loglevel: 'warning' }) // etc 

Assuming there is such an option. I couldn't figure out if it's a build-time or runtime option.

[MeirionHughes]

the docs kind of imply it isn't just a "log" file though; it serves as a "backup" of the in-memory recent-commits before they are flushed to the main storage file. If there is a crash before the data is written, then the log file will be used to "reconstruct" the missing data. Remove that and you potentially lose data when/if you crash.

[vweevers]

@MeirionHughes I think (but could use confirmation) these are two different things. Here are the rocksdb file types:

rocksdb/deps/leveldb/leveldb-rocksdb/db/filename.h

Lines 31 to 42 in fc844eb

	enum FileType {
	kLogFile,
	kDBLockFile,
	kTableFile,
	kDescriptorFile,
	kCurrentFile,
	kTempFile,
	kInfoLogFile, // Either the current one, or an old one
	kMetaDatabase,
	kIdentityFile,
	kOptionsFile
	};

I think you're talking about kLogFile, we're talking about kInfoLogFile (this).

[MeirionHughes]

ah ok; just double-checking. :P

[ralphtheninja]

@vweevers Some research

It seems that ImmutableDBOptions is taking care of cleaning up the Logger object:

rocksdb/deps/leveldb/leveldb-rocksdb/db/db_impl.cc

Lines 6205 to 6208 in fc844eb

	Status DestroyDB(const std::string& dbname, const Options& options) {
	const ImmutableDBOptions soptions(SanitizeOptions(dbname, options));
	Env* env = soptions.env;
	std::vector<std::string> filenames;

It has a member std::shared_ptr<Logger> info_log; which will be deleted, causing the Logger-destructor to be invoked when the ImmutbleDBOptions object exits out of scope, i.e. when DestroyDB() exits.

So this answers when the logger object dies. It in turn does fclose(file_) in all implementations, be it PosixLogger or WinLogger.

[vweevers]

That means that a simple fs.rmdir(location) in JS-land would also work.

[ralphtheninja]

So the problem we have is that DestroyDB() creates LOG, cleans up all files (but cleaning up LOG fails since it has an open handle), then the file handle is closed after.

I think DestroyDB() should not log at all, so in this case we should use a noop-logger unconditionally.

[ralphtheninja]

That means that a simple fs.rmdir(location) in JS-land would also work.

That's probably the best fix!

[vweevers]

I'll try that out in a bit :)

[ralphtheninja]

I also made some logging in c++ land just to see when the Logger object was created/destroyed. Turns out that db.close() also closes the file, but once we do leveldown.destroy() the file is created again and then closed.

Just FYI.

[vweevers]

OK doing fs.rmdir works!

And I wanted to write a unit test, but we also have this:

rocksdb/test/destroy-test.js

Lines 27 to 33 in fc844eb

	test('test destroy non-existant directory', function (t) {
	leveldown.destroy('/1/2/3/4', function () {
	t.equal(arguments.length, 1, 'error object returned on callback')
	t.equal(/.*IO error.*\/1\/2\/3\/4\/LOCK.*/.test(arguments[0]), true)
	t.end()
	})
	})

Which still passes. So if the parent directory doesn't exist destroy will return an error. But if it's only the child that doesn't exist, destroy is silent.

@ralphtheninja does leveldown have the same behavior?

[ralphtheninja]

OK doing fs.rmdir works!

👍

Which still passes. So if the parent directory doesn't exist destroy will return an error. But if it's only the child that doesn't exist, destroy is silent.

I don't know. You would have to test this.

[vweevers]

Yup, leveldown works the same. So I'll add a test to leveldown too.

Scratch that, I made a mistake testing it. leveldown is different, doesn't throw in either case.