Level / classic-level

An abstract-level database backed by LevelDB.
MIT License
58 stars 11 forks source link

"database is not open" on NFS #81

Closed aep closed 1 year ago

aep commented 1 year ago

we're (well.. the wife) users of the propriatary software mentioned in #63

they just say "must not use NFS" , and the reason appears somewhere in this library, since leveldb itself works just fine on NFS.

When opening a db on NFS, we just get

FoundryVTT | 2023-07-18 18:46:15 | [error] Database is not open
Error: Database is not open
    at LevelDatabase.keys (/home/foundry/resources/app/node_modules/abstract-level/abstract-level.js:697:13)
    at LevelDatabase.compactFull (file:///home/foundry/resources/app/dist/database/backend/level-database.mjs:1:1647)
    at LevelDatabase.close (file:///home/foundry/resources/app/dist/database/backend/level-database.mjs:1:1171)
    at Module.disconnect (file:///home/foundry/resources/app/dist/database/database.mjs:1:1658)
    at World.deactivate (file:///home/foundry/resources/app/dist/packages/world.mjs:1:11206)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

unfortunately the relevant code is obfuscated.

strace reveals no obvious reason why NFS would be a relevant factor. there is no call to flock.

/home/foundry # strace -f -p 87 2>&1 | grep messages
[pid    87] access("/data/Data/worlds/kmkm/data/messages", F_OK) = 0
[pid    94] mkdir("/data/Data/worlds/kmkm/data/messages", 0777 <unfinished ...>
[pid    96] statx(AT_FDCWD, "/data/Data/worlds/kmkm/data/messages", AT_STATX_SYNC_AS_STAT, STATX_ALL,  <unfinished ...>
[pid    95] mkdir("/data/Data/worlds/kmkm/data/messages", 0755 <unfinished ...>
[pid    95] rename("/data/Data/worlds/kmkm/data/messages/LOG", "/data/Data/worlds/kmkm/data/messages/LOG.old" <unfinished ...>
[pid    95] open("/data/Data/worlds/kmkm/data/messages/LOG", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666 <unfinished ...>
[pid    95] mkdir("/data/Data/worlds/kmkm/data/messages", 0755 <unfinished ...>
[pid    95] open("/data/Data/worlds/kmkm/data/messages/LOCK", O_RDWR|O_CREAT|O_LARGEFILE, 0644 <unfinished ...>
[pid    95] access("/data/Data/worlds/kmkm/data/messages/CURRENT", F_OK <unfinished ...>
[pid    95] open("/data/Data/worlds/kmkm/data/messages/CURRENT", O_RDONLY|O_LARGEFILE) = 39
[pid    95] open("/data/Data/worlds/kmkm/data/messages/MANIFEST-000002", O_RDONLY|O_LARGEFILE) = 39
[pid    95] open("/data/Data/worlds/kmkm/data/messages", O_RDONLY|O_LARGEFILE|O_CLOEXEC|O_DIRECTORY) = 39
[pid    95] open("/data/Data/worlds/kmkm/data/messages/000003.log", O_RDONLY|O_LARGEFILE) = 39
[pid    95] readv(39, [{iov_base="|\360\244_ \r\1\1\0\0\0\0\0\0\0\2\0\0\0\1\32!messages!J"..., iov_len=32767}, {iov_base="", iov_len=1024}], 2) = 3367
[pid    95] open("/data/Data/worlds/kmkm/data/messages/000005.ldb", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 39
[pid    95] writev(39, [{iov_base="", iov_len=0}, {iov_base="\242\32\200\0\"\253\f!messages!JMUZweuXaLnRGbw"..., iov_len=1950}], 2) = 1950
[pid    95] open("/data/Data/worlds/kmkm/data/messages/000005.ldb", O_RDONLY|O_LARGEFILE) = 39
[pid    95] stat("/data/Data/worlds/kmkm/data/messages/000005.ldb", {st_mode=S_IFREG|0644, st_size=2107, ...}) = 0
[pid    95] open("/data/Data/worlds/kmkm/data/messages/000005.sst", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
[pid    95] unlink("/data/Data/worlds/kmkm/data/messages/000005.ldb") = 0

https://github.com/felddy/foundryvtt-docker/issues/735

aep commented 1 year ago

npm test on nfs succeeds just fine

aep commented 1 year ago

the code that throws the error is:

async close(...e){
        return LevelDatabase.#e.delete(this.#a),await this.compactFull(),super.close(...e)
}

i dont know much javascript. doesnt this close the db before compact?

juliangruber commented 1 year ago

try this:

async close(...e){
        await LevelDatabase.#e.delete(this.#a)
        await this.compactFull()
        return super.close(...e)
}

You were running some operations in parallel

aep commented 1 year ago

i cant patch the code, it's proprietary software by @aaclayton

any idea how i can work around that, or if thats even the root cause?

aep commented 1 year ago

npm test also succeeds inside our production system. so clearly this must be related to how they use this library. i will attempt to figure out how to patch nodejs with gdb

aep commented 1 year ago

i figured out how to patch it. that solves that message but here's another one:

Error: Database is not open
    at LevelDatabase.keys (/home/foundry/resources/app/node_modules/abstract-level/abstract-level.js:697:13)
    at LevelDatabase.compactFull (file:///home/foundry/resources/app/dist/database/backend/level-database.mjs:8:445)
    at LevelDatabase.close (file:///home/foundry/resources/app/dist/database/backend/level-database.mjs:4:20)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Promise.all (index 2)
    at async Module.disconnect (file:///home/foundry/resources/app/dist/database/database.mjs:1:1667)

import {
    ClassicLevel
} from "classic-level";
import SublevelDatabase from "./sublevel-database.mjs";
import fs from "fs";

export default class LevelDatabase extends ClassicLevel {

    constructor(e, a, {
        sublevels: t = [],
        ...s
    } = {}) {
        if (!e || !a) throw new Error("You must provide a unique database name and file path location");
        if (LevelDatabase.#e.has(e)) throw new Error(`The database "${e}" is already open and cannot be re-created.`);
        s.keyEncoding = "utf8", s.valueEncoding = "json", super(a, s), this.#a = e, LevelDatabase.#e.set(e, this), this.setMaxListeners(Math.max(10, t.length + 1));
        const i = {
            keyEncoding: s.keyEncoding,
            valueEncoding: s.valueEncoding

        };
        for (const e of t) this.#t[e] = this.sublevel(e, i)
    }
    static async connect(e, a, t = {}) {
        const s = new this(e, a, {
            passive: !0,
            createIfMissing: !0,
            ...t
        });

        try {
            await s.open(), global.logger.info(`${global.vtt} | Connected to database "${e}"`)
        } catch (a) {
            throw a.message = `Failed to connect to database "${e}": ${a.message}`, a
        }
        return s
    }
    get name() {
        return this.#a
    }
    #a;
    get sublevels() {
        return this.#t
    }
    #t = {};
    static get databases() {
        return LevelDatabase.#e
    }
    static #e = new Map;
    static formatKey(...e) {
        return e.join(".")
    }
    async close(...e) {

        await LevelDatabase.#e.delete(this.#a)
        await this.compactFull()
        return super.close(...e)

    }

    async clone(e, a) {
        if (this.constructor.databases.has(e) || a === this.location) throw new Error("The cloned database name and location must be unique");
        const t = await this.constructor.connect(e, a, {
                sublevels: Object.keys(this.sublevels)
            }),
            s = t.batch(),
            i = this.iterator();
        for await (const [e, a] of i) s.put(e, a);
        return await i.close(), await s.write(), t
    }
    async destroy() {
        await this.close(), fs.rmSync(this.location, {
            recursive: !0
        })
    }
    async compactFull() {
        const e = this.keys({
                limit: 1,
                fillCache: !1
            }),
            a = await e.next();
        await e.close();
        const t = this.keys({
                limit: 1,
                reverse: !0,
                fillCache: !1
            }),
            s = await t.next();
        return await t.close(), this.compactRange(a, s, {
            keyEncoding: "utf8"
        })
    }
    async size() {
        const e = this.keys({
                limit: 1,
                fillCache: !1
            }),
            a = await e.next();
        await e.close();
        const t = this.keys({
                limit: 1,
                reverse: !0,
                fillCache: !1
            }),
            s = await t.next();
        return await t.close(), this.approximateSize(a, s, {
            keyEncoding: "utf8"
        })
    }
    _sublevel(e, a) {
        return new SublevelDatabase(this, e, a)
    }
}```
vweevers commented 1 year ago

Hard to say what is happening here, without full (meaning non-minified) code and a way to reproduce. Typically "Database is not open" means there was an explicit call to db.close(), FWIW.

aep commented 1 year ago

i dont think its in their code. it looks like the call to s.open() is failing, and the rest is just spurious. gdb hasnt been helpful.

i finally figured out that node_modules/abstract-level/abstract-level.js is hiding the error in this._open(options, (err) => { from c which is

[Error: IO error: /data/Data/worlds/kmkm/data/messages/000005.ldb: No such device] {
  code: 'LEVEL_IO_ERROR'
}
aep commented 1 year ago

the underlying issue is that that leveldb is unlinking a file and then writing to the open fd.

[pid  1963] unlink("/data/Data/worlds/kmkm/data/messages/000005.ldb") = 0
[pid  1953] write(1, "[Error: IO error: /data/Data/wor"..., 112[Error: IO error: /data/Data/worlds/kmkm/data/messages/000005.ldb: No such device] {

this is likely broken in NFS4 (?). I just dont understand why this only affecting this particular library, and not anything else leveldb related. is there a specific flag maybe

vweevers commented 1 year ago

why this only affecting this particular library

Perhaps because we use a rather old version of LevelDB here. What version(s) did you test against (in other libraries)?

aep commented 1 year ago

i tested leveldb 1.23, nothing else. maybe that just has an NFS workaround? its also possible this is a very unlucky combination, since NFS4 is fairly new and should natively support this, but i can see in strace that it clearly didnt work. i will investigate the nfs kernel client now.

aep commented 1 year ago

i still havent figured this out. Writing a deleted but open file works just fine on NFS.

I'd apprechiate if anyone has a small repro.

#include <stdio.h>
#include <fcntl.h>
#include <stdlib.h>
#include <unistd.h>
#include <string.h>

int main() {
    int fd = open("foo", O_CREAT | O_RDWR | O_TRUNC, 0644);
    if (fd < 0) {
        perror("open");
        exit(1);
    }

    unlink("foo");

    char *s = "hello world\n";
    int len = strlen(s);
    if (write(fd, s, len) != len) {
        perror("write");
        exit(1);
    }

    lseek(fd, 0, SEEK_SET);

    char buf[1024];
    int n = read(fd, buf, sizeof(buf));
    if (n < 0) {
        perror("read");
        exit(1);
    }

    write(STDOUT_FILENO, buf, n);

    close(fd);
    return 0;
}
aep commented 1 year ago

the story continues here: https://github.com/nfs-ganesha/nfs-ganesha/issues/980

I believe this is actually a kernel bug

what a rabbit hole

aep commented 1 year ago

i found it. the actual syscall failing is mmap. i think its just straight up broken on nfs3, and supposed to be correct on nfs4 but nobody can really confirm? this is likely the reason they say "nfs bad".

the only reason i did run into this and @felddy did not was that we tunnel NFS through virtiofs (i.e. fuse) and that enforces coherence, while nfs itself just accepts mmap anyway under conditions where it can lead to data loss.

https://gitlab.com/virtio-fs/virtiofsd/-/issues/105

thanks for providing a unique testcase. We have over 3K users and zero reports like this although eventually someone would have run into something related. I found plenty unrelated nfs bugs during this involuntary adventure,