Unable to open database

[mp-netis]

Hi,

I cannot get superhighway84 to go thru the first run. This is what gets output:

2022/05/30 19:42:53 initializing logger ...
2022/05/30 19:42:53 initializing cache ...
2022/05/30 19:42:53 initializing TUI and loading database, please wait ...
2022/05/30 19:42:53 initializing database ...
2022/05/30 19:42:54 connecting database ...
2022/05/30 19:52:54 unable to open database: unable to fetch database manifest: failed to get block for bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4: context deadline exceeded
panic: unable to open database: unable to fetch database manifest: failed to get block for bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4: context deadline exceeded

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

goroutine 1 [running]:
github.com/mrusme/superhighway84/database.(*Database).Disconnect(0xc00218d2c0)
    /home/runner/work/superhighway84/superhighway84/database/database.go:224 +0x27
panic({0x13e68e0, 0xc004195c40})
    /opt/hostedtoolcache/go/1.18.1/x64/src/runtime/panic.go:838 +0x207
log.Panicln({0xc0055ebf48?, 0xc002030e70?, 0x1832397?})
    /opt/hostedtoolcache/go/1.18.1/x64/src/log/log.go:399 +0x65
main.main()
    /home/runner/work/superhighway84/superhighway84/superhighway84.go:124 +0x8dd

The log file says:

2022-05-30T20:32:19.632+0200    DEBUG   database/database.go:148    getting config root path ...
2022-05-30T20:32:19.634+0200    DEBUG   database/database.go:154    setting up plugins ...
2022-05-30T20:32:19.634+0200    DEBUG   database/database.go:159    creating IPFS node ...
2022-05-30T20:32:20.287+0200    INFO    database/database.go:171    connecting to peers ...
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:124    connected!  {"peerID": "QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ"}
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:124    connected!  {"peerID": "QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ"}
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:124    connected!  {"peerID": "QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ"}
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:124    connected!  {"peerID": "QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ"}
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:124    connected!  {"peerID": "QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ"}
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:177    connected to peer!
2022-05-30T20:32:20.635+0200    INFO    database/database.go:182    initializing database connection ...
2022-05-30T20:32:20.635+0200    DEBUG   database/database.go:51 initializing NewOrbitDB ...
2022-05-30T20:32:20.706+0200    DEBUG   database/database.go:79 initializing OrbitDB.Docs ...
2022-05-30T20:32:20.706+0200    DEBUG   baseorbitdb/orbitdb.go:531  open orbitdb store  {"address": "/orbitdb/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84"}
2022-05-30T20:32:20.707+0200    DEBUG   baseorbitdb/orbitdb.go:553  Open database   {"dbAddress": "/orbitdb/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84"}
2022-05-30T20:32:20.707+0200    DEBUG   baseorbitdb/orbitdb.go:560  Look from   {"directory": "/home/milan/.cache/superhighway84/database"}
2022-05-30T20:32:20.707+0200    DEBUG   baseorbitdb/orbitdb.go:575  address '/orbitdb/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84' is valid
2022-05-30T20:32:20.707+0200    DEBUG   cacheleveldown/leveldown.go:88  opening cache db    {"path": "/home/milan/.cache/superhighway84/database/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84"}
2022-05-30T20:52:20.636+0200    ERROR   database/database.go:186    %s  {"error": "unable to open database: unable to fetch database manifest: failed to get block for bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4: context deadline exceeded", "errorVerbose": "failed to get block for bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4: context deadline exceeded\nunable to fetch database manifest\nberty.tech/go-orbit-db/baseorbitdb.(*orbitDB).Open\n\t/home/milan/go/pkg/mod/berty.tech/go-orbit-db@v1.17.1/baseorbitdb/orbitdb.go:597\nberty.tech/go-orbit-db.(*orbitDB).Docs\n\t/home/milan/go/pkg/mod/berty.tech/go-orbit-db@v1.17.1/orbitdb.go:143\ngithub.com/mrusme/superhighway84/database.(*Database).init\n\t/home/milan/work/superhighway84-0.2.0/database/database.go:80\ngithub.com/mrusme/superhighway84/database.(*Database).Connect\n\t/home/milan/work/superhighway84-0.2.0/database/database.go:184\nmain.main\n\t/home/milan/work/superhighway84-0.2.0/superhighway84.go:108\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:255\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1581\nunable to open database\nberty.tech/go-orbit-db.(*orbitDB).Docs\n\t/home/milan/go/pkg/mod/berty.tech/go-orbit-db@v1.17.1/orbitdb.go:145\ngithub.com/mrusme/superhighway84/database.(*Database).init\n\t/home/milan/work/superhighway84-0.2.0/database/database.go:80\ngithub.com/mrusme/superhighway84/database.(*Database).Connect\n\t/home/milan/work/superhighway84-0.2.0/database/database.go:184\nmain.main\n\t/home/milan/work/superhighway84-0.2.0/superhighway84.go:108\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:255\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1581"}
github.com/mrusme/superhighway84/database.(*Database).Connect
    /home/milan/work/superhighway84-0.2.0/database/database.go:186
main.main
    /home/milan/work/superhighway84-0.2.0/superhighway84.go:108
runtime.main
    /usr/local/go/src/runtime/proc.go:255

The database LOG file in .cache says:

=============== May 30, 2022 (CEST) ===============
19:42:54.143405 log@legend F·NumFile S·FileSize N·Entry C·BadEntry B·BadBlock Ke·KeyError D·DroppedEntry L·Level Q·Se
qNum T·TimeElapsed
19:42:54.161259 db@open opening
19:42:54.161488 version@stat F·[] S·0B[] Sc·[]
19:42:54.168994 db@janitor F·2 G·0
19:42:54.169012 db@open done T·7.728795ms

This is version 0.2.0 and IPFS is 0.12.2 running on Ubuntu 20.04.4. I ran ipfs init and accepted all the default values offered by superhighway84.

I've tried everything I could find without effect:

1. Setting ulimit to 2048
2. Setting net.core.rmem_max to 2500000
3. Setting ipfs lowpower
4. Also tried it on macOS
5. Tried the previous version with older IPFS, also unsuccessful
6. Tried compiled and prebuilt
7. Tried increasing the timeouts in database.go from 600 to 1200

What else can I try? I would appreciate some hints.

Thnx.

[mrusme]

Hey there, can you try starting it several more times and waiting for the context to timeout? I saw a similar issue before but it disappeared before I got to debug it. It might have to do with https://github.com/mrusme/superhighway84/issues/46 which I'm currently investigating. You could try a Superhighway84 version < 0.2.0, since it was working flawlessly before the upgrade to IPFS 0.12.2.

[mp-netis]

Hi, thanks for the advice, I will run it several times and see what happens.

I did try v0.1.2 and it also panicked, but already at "initializing TUI and loading database" and much quicker.

[mp-netis]

Yeah ... I understand #46 is a priority. I hope you will tell us what you found after you crack it!

I ran version 0.2.0 about 10 times consecutively with the same results.

I then tried with 0.1.1 and it waits at:

TUI and loading database, please wait ...

I left that to work for 2 hours, without visible results, but it is doing tons of work in the background, not just hanging. I then restarted it after setting:

ipfs config profile apply lowpower

That might help, because I'm running it in a VM.

[mp-netis]

Hi,

I did a bit of debugging and it hangs in database.go at:

    storetype := "docstore"
    db.Store, err = db.OrbitDB.Docs(db.ctx, db.ConnectionString, &orbitdb.CreateDBOptions{
        AccessController:  ac,
        StoreType:         &storetype,
        StoreSpecificOpts: documentstore.DefaultStoreOptsForMap("id"),
    })

It never returns from that call.

Any idea why that could be?

[mrusme]

@mp-netis could you check this issue and see if any of that helps?

[mp-netis]

It does not seem to be that issue.

1. I did not modify go.mod
2. I initialize the repo with the same version of IPFS as mentioned in go.mod
3. IPFS otherwise works.

I do use go1.17.4 and not 1.17 ... but that should not be an issue.

[mrusme]

Thank you for confirming. Can you try resetting the IPFS repo and deleting the cache? Here is how that works. I honestly don't know what else to suggest for now otherwise and will have to dig deeper into this.

Yet again, 0.2.0 has some issues in general in which the database doesn't seem to correctly sync anymore, which I'm currently investigating. Maybe that same issue is what prevents a fresh install from starting in first place.

[mp-netis]

Hi, I have been resetting repo, cache and config all the time. I now tried it all together again, with the prebuilt 0.1.1. and all the kernel settings ... unfortunately same behaviour.

We must be missing something very trivial. If it works from fresh for you and also @diyism, there must be something strange on my end.

[mrusme]

@mp-netis v0.2.1 is building as I write this. Feel free to give it another try when it's published. It should support IPFS 0.12 and sync right away.

[raisen]

Hey @mrusme I'm having the same issue as @mp-netis . I am trying to runsh84 behind Docker though. This is my current Dockerfile:

FROM golang:latest AS superhighway84
RUN git clone https://github.com/mrusme/superhighway84.git
RUN cd superhighway84 && go build .

FROM ubuntu:latest
RUN apt-get -y update && apt-get install -y libssl-dev
COPY --from=ipfs/kubo:v0.16.0 /usr/local/bin/ipfs /usr/local/bin/ipfs
COPY --from=superhighway84 /go/superhighway84/superhighway84 /usr/local/bin/superhighway84

ENTRYPOINT sh -c "/usr/local/bin/ipfs init && /usr/local/bin/superhighway84"

Building and running docker as (I've tried without --net=host and --privileged as well):

docker build -t superhighway84 .
docker run -it --rm --privileged --net=host superhighway84

Any ideas?

[mrusme]

Hey there, have you checked the SH84 log that's usually under ~/.cache/superhighway84.log? Can you share the output?

[raisen]

Thanks for the quick reply. That's the output:

2023-01-17T02:58:45.167Z        DEBUG   database/database.go:146        getting config root path ...
2023-01-17T02:58:45.167Z        DEBUG   database/database.go:152        setting up plugins ...
2023-01-17T02:58:45.171Z        DEBUG   database/database.go:157        creating IPFS node ...
2023-01-17T02:58:45.565Z        INFO    database/database.go:169        connecting to peers ...
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:122        connected!      {"peerID": "QmNnooDu7bfjPFoTZYxMNLWUQJyrVwtbZg5gBMjTezGAJN"}
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:122        connected!      {"peerID": "QmNnooDu7bfjPFoTZYxMNLWUQJyrVwtbZg5gBMjTezGAJN"}
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:122        connected!      {"peerID": "QmNnooDu7bfjPFoTZYxMNLWUQJyrVwtbZg5gBMjTezGAJN"}
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:122        connected!      {"peerID": "QmNnooDu7bfjPFoTZYxMNLWUQJyrVwtbZg5gBMjTezGAJN"}
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:122        connected!      {"peerID": "QmNnooDu7bfjPFoTZYxMNLWUQJyrVwtbZg5gBMjTezGAJN"}
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:175        connected to peer!
2023-01-17T02:58:45.565Z        INFO    database/database.go:179        initializing database connection ...
2023-01-17T02:58:45.565Z        DEBUG   database/database.go:49 initializing NewOrbitDB ...
2023-01-17T02:58:45.636Z        DEBUG   database/database.go:77 initializing OrbitDB.Docs ...
2023-01-17T02:58:45.636Z        DEBUG   baseorbitdb/orbitdb.go:537      open orbitdb store      {"address": "/orbitdb/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84"}
2023-01-17T02:58:45.636Z        DEBUG   baseorbitdb/orbitdb.go:559      Open database   {"dbAddress": "/orbitdb/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84"}
2023-01-17T02:58:45.636Z        DEBUG   baseorbitdb/orbitdb.go:566      Look from       {"directory": "/root/.cache/superhighway84/database"}
2023-01-17T02:58:45.636Z        DEBUG   cacheleveldown/leveldown.go:88  opening cache db        {"path": "/root/.cache/superhighway84/database/bafyreifdpagppa7ve45odxuvudz5snbzcybwyfer777huckl4li4zbc5k4/superhighway84"}
2023-01-17T03:08:45.682Z        ERROR   database/database.go:183        %s      {"error": "unable to open database: unable to fetch database manifest: context deadline exceeded"}
github.com/mrusme/superhighway84/database.(*Database).Connect
        /go/superhighway84/database/database.go:183
main.main
        /go/superhighway84/superhighway84.go:109
runtime.main
        /usr/local/go/src/runtime/proc.go:250

[mrusme]

Thanks, could you give the lowpower mode a try, as well as the RelayClient? Also make sure to -p 4001:4001 on your container as well as (ideally) on your router.

[raisen]

Thanks. I tried these but didn't help. I'm not sure if you were able to replicate using the Dockerfile. I tried on Ubuntu 22.04.

This is the first IPFS project I tried. I'll get more familiar with IPFS and see if I can find a solution for what's going on.

[mrusme]

Haven't tried running it within a Docker container tbh. If you don't mind the effort, launch some micro VPS online and try launching it there. If it fails to connect on that as well there might indeed be an issue. So far I'd say though that it's simply not able to fetch the DB in time, before the context cancels. That could be due to it being unable to set up P2P connectivity.