nexedi / wendelin.core

Changed title: Protocol error when commiting transaction in an existing ZODB in VM shared directory → Protocol error when committing transaction in an existing ZODB in VM shared directory

@adrien.dessy thanks for reporting. I've reproduced this situation and unfortunately this turned out to be a virtualbox bug (checked on latest 5.1.12_Debian), here is why:

When your test program is executed under strace it shows:

...
open("test.tmp", O_RDWR|O_CREAT|O_TRUNC, 0666) = 4
fstat(4, {st_mode=S_IFREG|0770, st_size=0, ...}) = 0
getcwd("/media/sf_shared", 1024)        = 17
open("test", O_RDWR)                    = 5
fstat(5, {st_mode=S_IFREG|0770, st_size=838, ...}) = 0
stat("test.index", {st_mode=S_IFREG|0770, st_size=51, ...}) = 0
open("test.index", O_RDONLY)            = 6
fstat(6, {st_mode=S_IFREG|0770, st_size=51, ...}) = 0
fstat(6, {st_mode=S_IFREG|0770, st_size=51, ...}) = 0 
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbbb84000
read(6, "MF\3.(U\6\0\0\0\0\0\0U \0\0\0\1\0\2\0\3\0\0\0\0\0\271\0\0\0"..., 4096) = 51
close(6)                                = 0
munmap(0x7fbcbbb84000, 4096)            = 0
fstat(5, {st_mode=S_IFREG|0770, st_size=838, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbbb84000
fstat(5, {st_mode=S_IFREG|0770, st_size=838, ...}) = 0
lseek(5, 0, SEEK_SET)                   = 0
read(5, "FS21\3\274p\343\362\263\263f\0\0\0\0\0\0\0\226 \0\0\0\31\0\0initi"..., 838) = 838
lseek(5, 838, SEEK_SET)                 = 838
lseek(5, 838, SEEK_SET)                 = 838
lseek(5, 838, SEEK_SET)                 = 838
lseek(5, 838, SEEK_SET)                 = 838
lseek(5, 838, SEEK_SET)                 = 838
lseek(5, 838, SEEK_SET)                 = 838
fstat(5, {st_mode=S_IFREG|0770, st_size=838, ...}) = 0
lseek(5, 0, SEEK_SET)                   = 0
read(5, "FS21\3\274p\343\362\263\263f\0\0\0\0\0\0\0\226 \0\0\0\31\0\0initi"..., 4096) = 838
lseek(5, 838, SEEK_SET)                 = 838
lseek(5, 0, SEEK_SET)                   = 0
read(5, "FS21\3\274p\343\362\263\263f\0\0\0\0\0\0\0\226 \0\0\0\31\0\0initi"..., 4096) = 838
read(5, "", 4096)                       = 0
open("/media/sf_shared/test", O_RDONLY) = 6
fstat(6, {st_mode=S_IFREG|0770, st_size=838, ...}) = 0
fstat(6, {st_mode=S_IFREG|0770, st_size=838, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbbb83000
lseek(6, 0, SEEK_SET)                   = 0
read(6, "FS21\3\274p\343\362\263\263f\0\0\0\0\0\0\0\226 \0\0\0\31\0\0initi"..., 185) = 185
read(6, "\0\0\0\0\0\0\0\0\3\274p\343\362\264jD\0\0\0\0\0\0\0004\0\0\0\0\0\0\0\242"..., 4096) = 653
lseek(6, 838, SEEK_SET)                 = 838
lseek(6, 838, SEEK_SET)                 = 838
fstat(4, {st_mode=S_IFREG|0770, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbbb82000
lseek(4, 0, SEEK_SET)                   = 0
lseek(5, 0, SEEK_SET)                   = 0
read(5, "FS21\3\274p\343\362\263\263f\0\0\0\0\0\0\0\226 \0\0\0\31\0\0initi"..., 185) = 185
read(5, "\0\0\0\0\0\0\0\0\3\274p\343\362\264jD\0\0\0\0\0\0\0004\0\0\0\0\0\0\0\242"..., 4096) = 653
write(4, "\0\0\0\0\0\0\0\0\3\274p\355B\246\3163\0\0\0\0\0\0\0\271\0\0\0\0\0\0\3F"..., 645) = 645
lseek(4, 0, SEEK_SET)                   = 0
lseek(5, 0, SEEK_SET)                   = 0
read(5, "FS21\3\274p\343\362\263\263f\0\0\0\0\0\0\0\226 \0\0\0\31\0\0initi"..., 4096) = 838
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbbb81000
read(4, 0x7fbcbbb82000, 4096)           = -1 EPROTO (Protocol error)
...

So test.tmp is reopened/truncated; wrote to; then read from and on read we get EPROTO.

I've made a small C program reproducing this:

#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>

void die_errno(const char *msg) {
        perror(msg);
        exit(1);
}

static const char data[1024] = "0123456789...........";
static char data2[1024];

int main() {
        int fd, err;
        off_t off;

        fd = open("testfile", O_RDWR|O_CREAT|O_TRUNC, 0666);
        if (fd == -1) {
                die_errno("open testfile");
        }

        // fstat
        // fstat

        off = lseek(fd, 0, SEEK_SET);
        if (off == -1) {
                die_errno("lseek");
        }

        err = write(fd, data, 645);
        if (err == -1) {
                perror("write");
        }

        off = lseek(fd, 0, SEEK_SET);
        if (off == -1) {
                die_errno("lseek2");
        }

        //err = read(fd, data2, 4096);
        err = read(fd, data2, 645);
        if (err == -1) {
                die_errno("read");
        }

        return 0;
}

and after compiling and running it in /media/sf_shared/ it gives:

(test)kirr@test1:/media/sf_shared$ gcc -Wall -o vboxsf-eproto vboxsf-eproto.c 
(test)kirr@test1:/media/sf_shared$ rm -f testfile 
(test)kirr@test1:/media/sf_shared$ ./vboxsf-eproto    # first time ok - when the file was not there initially
(test)kirr@test1:/media/sf_shared$ ./vboxsf-eproto    # second time -> EPROTO on read
read: Protocol error

---

Googling for e.g. "virtualbox protocol error vboxsf" gives many places. I guess the best we can do is to report this additional info to upstream virtualbox issue tracker here: https://www.virtualbox.org/ticket/8463

Overal I suggest not to use virtualbox filesystem (the filesystem which provides mounting of shared folder from inside guest) for actual data storage.

OK, thanks for the diagnosis! I'm not as fluent in system calls 🙂

My laptop does not have that much of disk space. That's why a shared directory looked like a good compromise.

I guess the issue can be closed then.

Status changed to closed

Thanks for feedback. For the reference, I have not tried, but probably something like NFS is more well implemented.

mentioned in merge request slapos!182 (merged)