Storj v3 Storage Node service not starting

snowsnail · June 26, 2020, 1:42pm

Hi!! Much more info!!

PS C:\Program Files\Storj\Storage Node> ./storagenode run --config-dir “$env:ProgramFiles\Storj\Storage Node” --log.level debug --log.output stdout
2020-06-26T15:39:17.541+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-06-26T15:39:17.629+0200 DEBUG Anonymized tracing disabled
2020-06-26T15:39:17.639+0200 INFO Operator email {“Address”: “mail@gmail.com”}
2020-06-26T15:39:17.639+0200 INFO Operator wallet {“Address”: “payout_addr”}
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x28 pc=0xd6b904]

goroutine 1 [running]:
github.com/spacemonkeygo/monkit/v3.newSpan.func1(0xc0003f4f20)
/go/pkg/mod/github.com/spacemonkeygo/monkit/v3@v3.0.7-0.20200515175308-072401d8c752/ctx.go:147 +0x3af
panic(0x116a9a0, 0x103c200)
/usr/local/go/src/runtime/panic.go:679 +0x1c0
storj.io/storj/storagenode/storagenodedb.(*DB).closeDatabase(0xc0004600f0, 0x12e7084, 0xa, 0x103c7e0, 0x3)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:395 +0x84
storj.io/storj/storagenode/storagenodedb.(*DB).closeDatabases(0xc0004600f0, 0x12e7084, 0xa)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:384 +0xb5
storj.io/storj/storagenode/storagenodedb.(*DB).openDatabases(0xc0004600f0, 0xc0004600f0, 0x12e43d3)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:242 +0x39b
storj.io/storj/storagenode/storagenodedb.New(0xc0004ae4e0, 0xc000458570, 0xe, 0xc000133160, 0x1b, 0xc0001331c0, 0x15, 0x0, 0x0, 0xc000458570, …)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:172 +0x860
main.cmdRun(0x1048260, 0xc000159980, 0x0, 0x6, 0x0, 0x0)
/go/src/storj.io/storj/cmd/storagenode/main.go:147 +0x5cd
storj.io/private/process.cleanup.func1.4(0x1485b00, 0xc00045d220)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:359 +0x142
storj.io/private/process.cleanup.func1(0x1048260, 0xc000159980, 0x0, 0x6, 0x0, 0x0)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:377 +0x21c9
github.com/spf13/cobra.(*Command).execute(0x1048260, 0xc0001598c0, 0x6, 0x6, 0x1048260, 0xc0001598c0)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:840 +0x467
github.com/spf13/cobra.(*Command).ExecuteC(0x1047fc0, 0xc000062000, 0x1336268, 0x0)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:945 +0x31e
github.com/spf13/cobra.(*Command).Execute(…)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:885
storj.io/private/process.ExecWithCustomConfig(0x1047fc0, 0x0, 0x1336268)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:88 +0x196
storj.io/private/process.ExecCustomDebug(...)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:70
main.main()
/go/src/storj.io/storj/cmd/storagenode/main.go:320 +0x45
PS C:\Program Files\Storj\Storage Node>

Alexey · June 26, 2020, 6:07pm

We have created an internal ticket for that issue

snowsnail · June 26, 2020, 6:35pm

Thank you!! Please contact me if you need more info.

SGC · June 26, 2020, 7:40pm

have you tried a reboot of the computer and a reinstall of the node… ofc using the existing identity and data folders if any data on the node…

else makes sure the software like “docker” or whatever is the recommended version
also running a windows update sometimes can help with general weirdness.

maybe checking that your antivirus did mess with the install

and ofc start from the easiest solutions to test first

snowsnail · June 26, 2020, 11:21pm

Yeah, I have been doing all our recommendations. The node has 7TB of data and it’s full. It has been running very well since I installed it in january.
I fear it’s some type of weird permissions problem, but I can’t find what is.

SGC · June 27, 2020, 6:59am

you migrated it recently? or why would you think it’s permissions… ?

snowsnail · June 29, 2020, 2:58pm

I has not been migrated. Was “born” in Windows GUI. I think that’s permissions because I don’t have any other explanation.

Alexey · June 29, 2020, 11:50pm

6 posts were split to a new topic: Windows GUI Service doesn’t start (1067 error)

thev · July 10, 2020, 10:04pm

I am getting

Error 1067: The Process terminated unexpectedly

(I’ve replaced my real wallet addres and email with ‘…’)

PS C:\Program Files\Storj\Storage Node> Get-Content “$env:ProgramFiles/Storj/Storage Node/storagenode-2020-07.log” -Tail 20 -Wait
2020-07-10T23:47:52.699+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:47:52.699+0200 INFO Operator wallet {“Address”: “…”}
2020-07-10T23:47:56.715+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-10T23:47:56.721+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:47:56.722+0200 INFO Operator wallet {“Address”: “…”}
2020-07-10T23:48:07.071+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-10T23:48:07.078+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:48:07.078+0200 INFO Operator wallet {“Address”: “…”}
2020-07-10T23:48:30.554+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-10T23:48:30.562+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:48:30.562+0200 INFO Operator wallet {“Address”: “…”}
2020-07-10T23:51:55.872+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-10T23:51:55.880+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:51:55.880+0200 INFO Operator wallet {“Address”: “…”}
2020-07-10T23:56:12.973+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-10T23:56:12.979+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:56:12.979+0200 INFO Operator wallet {“Address”: “…”}
2020-07-10T23:58:12.631+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-10T23:58:12.638+0200 INFO Operator email {“Address”: “…”}
2020-07-10T23:58:12.639+0200 INFO Operator wallet {“Address”: “…”}

As there was nothing interesting in storagenode.log, I tried this way:

PS C:\Program Files\Storj\Storage Node> .\storagenode.exe run
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x28 pc=0xd6b904]

goroutine 1 [running]:
github.com/spacemonkeygo/monkit/v3.newSpan.func1(0xc000369ac0)
/go/pkg/mod/github.com/spacemonkeygo/monkit/v3@v3.0.7-0.20200515175308-072401d8c752/ctx.go:147 +0x3af
panic(0x116a9a0, 0x103c200)
/usr/local/go/src/runtime/panic.go:679 +0x1c0
storj.io/storj/storagenode/storagenodedb.(*DB).closeDatabase(0xc0004000f0, 0x12e7278, 0xa, 0x103c7e0, 0x3)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:395 +0x84
storj.io/storj/storagenode/storagenodedb.(*DB).closeDatabases(0xc0004000f0, 0x12e2df3, 0x6)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:384 +0xb5
storj.io/storj/storagenode/storagenodedb.(*DB).openDatabases(0xc0004000f0, 0xc0004000f0, 0x12e43d3)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:197 +0x87e
storj.io/storj/storagenode/storagenodedb.New(0xc00046a060, 0xc0003eed80, 0x9, 0xc0003d8040, 0x16, 0xc00047c040, 0x10, 0x0, 0x0, 0xc0003eed80, …)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:172 +0x860
main.cmdRun(0x1048260, 0x1bbfbd0, 0x0, 0x0, 0x0, 0x0)
/go/src/storj.io/storj/cmd/storagenode/main.go:147 +0x5cd
storj.io/private/process.cleanup.func1.4(0x1485b00, 0xc0003fa960)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:359 +0x142
storj.io/private/process.cleanup.func1(0x1048260, 0x1bbfbd0, 0x0, 0x0, 0x0, 0x0)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:377 +0x21c9
github.com/spf13/cobra.(*Command).execute(0x1048260, 0x1bbfbd0, 0x0, 0x0, 0x1048260, 0x1bbfbd0)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:840 +0x467
github.com/spf13/cobra.(*Command).ExecuteC(0x1047fc0, 0xc00007e000, 0x1336268, 0x0)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:945 +0x31e
github.com/spf13/cobra.(*Command).Execute(...)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:885
storj.io/private/process.ExecWithCustomConfig(0x1047fc0, 0x0, 0x1336268)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:88 +0x196
storj.io/private/process.ExecCustomDebug(...)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:70
main.main()
/go/src/storj.io/storj/cmd/storagenode/main.go:320 +0x45

snowsnail · July 17, 2020, 9:45pm

I have reinstalled the machine but I keep getting the 1067 error, so I thing the node installation is ok. If I change the route for the storage the node starts ok. It’s something related to the database perhaps?? The log in debug node doesn’t give any info.

SGC · July 17, 2020, 9:57pm

might as well post what the log does say… remember to remove what you consider private information…

usually tho if the node keeps restarting, then it’s a router port issues or a firewall issue… usually router port redirection to your storagenode. it’s kinda well covered in the storagenode documentation, but sometimes you will need ISP information…

another option is that your ISP or the current service you are subscribed to at your ISP doesn’t do port redirection…

thats afaik the most common issue when setting up a new storagenode.

sorry i cannot be of more help… i’m sure somebody will go through it all in great detail if you wait around a bit…

the route for the storage… most network storage protocols won’t work well… such a NFS or SMB/samba, iscsi i believe is the solution people have had the best results with… but network storage for your storagenode is not a great idea…

if you by changed route means you changes the port numbers or the storagenode data location… then ofc double and triple check your ports and locations… sometimes deleting them and typing them back in can help, because one can sort of get blind to a miss configuration of a port number of a slight deviation in the location address…

snowsnail · July 17, 2020, 10:09pm

No, the node tries to start gives the 1067 error and stops. The log says that:

2020-07-17T23:40:44.490+0200 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-17T23:40:44.510+0200 DEBUG Anonymized tracing disabled
2020-07-17T23:40:44.511+0200 DEBUG debug server listening on 127.0.0.1:51201
2020-07-17T23:40:44.523+0200 INFO Operator email {“Address”: “xxxxxxxx@gmail.com”}
2020-07-17T23:40:44.523+0200 INFO Operator wallet {“Address”: “0xxxxxxxxx”}

SGC · July 18, 2020, 8:42am

yeah doesn’t look like it connects online correctly…
this is mine in docker on linux… sadly the logs are not the same exactly and doesn’t give us any easy to read indication of what is wrong… but as you can see it will very early on… try to connect online… so either ports or ip’s the ports are routed to are wrong… or something in that regard… its either that or storage location.

but mine seems to check the version number almost as the first thing… which yours seems to timeout or fail at…
sorry the logs in this are kinda terrible… if one isn’t very familiar with them… i mean it wouldn’t take much for it to tell us what failed… instead of just being silent…

anyways… my bet it on that it doesn’t connect correctly to the internet…

but you might have better luck with somebody like @nerdatwork @Alexey @BrightSilence
they are very well versed in the details of the node… but do double check your routing, it’s the most common configuration failure…

2020-07-02T20:01:45.552Z 2020-07-02T20:01:45.553Z 2020-07-02T20:01:45.585Z 2020-07-02T20:01:45.585Z 2020-07-02T20:01:45.683Z 2020-07-02T20:01:46.336Z 2020-07-02T20:01:46.336Z 2020-07-02T20:01:46.337Z 2020-07-02T20:01:46.337Z 2020-07-02T20:01:46.346Z 2020-07-02T20:01:46.357Z 2020-07-02T20:01:46.368Z 2020-07-02T20:01:48.458Z 2020-07-02T20:01:49.091Z 2020-07-02T20:01:49.094Z 2020-07-02T20:01:49.094Z 2020-07-02T20:01:49.095Z 2020-07-02T20:01:49.095Z 2020-07-02T20:01:49.095Z 2020-07-02T20:01:49.095Z 2020-07-02T20:01:49.095Z 2020-07-02T20:01:50.970Z 2020-07-02T20:01:50.970Z 2020-07-02T20:01:50.970Z 2020-07-02T20:01:50.970Z 2020-07-02T20:01:50.970Z 2020-07-02T20:01:50.970Z 2020-07-02T20:01:50.971Z 2020-07-02T20:01:50.971Z 2020-07-02T20:01:50.973Z 2020-07-02T20:01:50.972Z 2020-07-02T20:01:50.973Z 2020-07-02T20:01:50.973Z INFO Configuration loaded {“Location”: “/app/config/config.yaml”}
DEBUG Anonymized tracing disabled
INFO Operator email {“Address”: “myemail@gmail.com”}
INFO Operator wallet {“Address”: “0x…”}
DEBUG Version info {“Version”: “1.6.4”, “Commit Hash”: "5e495f4b3bee91d6e6ac2fa43fc50341921$
DEBUG version Allowed minimum version from control server. {“Minimum Version”: “1.3.0”}
DEBUG version Running on allowed version. {“Version”: “1.6.4”}
INFO Telemetry enabled
DEBUG Initialized batcher {“ID”: “…”}
INFO db.migration.40 Add unknown_audit_reputation_score field to satellites db
INFO db.migration.41 Make satellite_id foreign key in satellite_exit_progress table
INFO db.migration.42 Drop used serials table
INFO db.migration Database Version {“version”: 42}
DEBUG trust Fetched URLs from source; updating cache {“source”: "https://tardigrade.i$
DEBUG trust Satellite is trusted {“id”: "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdp$
DEBUG trust Satellite is trusted {“id”: "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcN$
DEBUG trust Satellite is trusted {“id”: "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vz$
DEBUG trust Satellite is trusted {“id”: "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvv$
DEBUG trust Satellite is trusted {“id”: "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69t$
DEBUG trust Satellite is trusted {“id”: "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuaw$
INFO preflight:localtime start checking local system clock with trusted satellites’ syste$
INFO preflight:localtime local system clock is in sync with trusted satellites’ system cl$
DEBUG servers started {“items”: [“debug”, “server”]}
DEBUG services started {“items”: [“version”, “trust”, “contact:chore”, “PieceDeleter”, INFO bandwidth Performing bandwidth usage rollups INFO trust Scheduling next refresh {"after": "4h58m8.200695359s"} INFO Node started WARN piecestore:monitor Disk space is less than requested. Allocating space {"bytes"
INFO Public server started on [::]:28967
INFO Private server started on 127.0.0.1:7778
DEBUG contact:chore Starting cycle {“Satellite ID”: "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJe$
DEBUG contact:chore Starting cycle {“Satellite ID”: "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpS$
DEBUG pieces:trash starting emptying trash

Alexey · July 18, 2020, 10:58am

Very rare. The service/container is usually restarting if it have problems with storage - either wrong path or corrupted structure.
In rare cases (antivirus or some aggressive firewall) the network infrastructure could block the needed traffic to contact satellites and node will fail on preflight check.

If you have a port problem your node will just simply being offline. The service will not restart.

So, since there is no evidence to have an aggressive firewall and node crash even before the preflight check, then I can assume that this node have a problem with storage.

Please, stop your storagenode and check your filesystem for errors with checkdisk
Then, check all sqlite databases and fix them, if they are corrupted:

After that try to start the storagenode.

BigR · July 23, 2020, 3:07pm

I am having the same issues.

Did a chkdsk and found nothing worng.

Any help will be appreciated.

ethan · July 23, 2020, 6:37pm

Please run storagenode run --config-dir "<your config dir>" --log.level debug --log.output stdout and post the output.

Depending on where it fails, it will help show which DB it is failing to open (if your issue is the same as the original post).

The theory is one of the sqlite DBs are corrupt or has permission issues.

BrightSilence · July 23, 2020, 7:45pm

Your command had curly quotes. Should be

storagenode run --config-dir "<your config dir>" --log.level debug --log.output stdout

BigR · July 24, 2020, 12:55pm

2020-07-24T20:48:41.442+0800 INFO Configuration loaded {“Location”: “C:\Program Files\Storj\Storage Node\config.yaml”}
2020-07-24T20:48:41.487+0800 DEBUG Anonymized tracing disabled
2020-07-24T20:48:41.499+0800 INFO Operator email {“Address”: “”}
2020-07-24T20:48:41.499+0800 INFO Operator wallet {“Address”: “”}
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x28 pc=0xd6b904]

goroutine 1 [running]:
github com/spacemonkeygo/monkit/v3.newSpan.func1(0xc0003df110)
/go/pkg/mod/github.com/spacemonkeygo/monkit/v3@v3.0.7-0.20200515175308-072401d8c752/ctx.go:147 +0x3af
panic(0x116a9a0, 0x103c200)
/usr/local/go/src/runtime/panic.go:679 +0x1c0
storj io/storj/storagenode/storagenodedb.(*DB).closeDatabase(0xc00044a0f0, 0x12e7084, 0xa, 0x103c7e0, 0x3)
/go/src/storj io/storj/storagenode/storagenodedb/database.go:395 +0x84
storj io/storj/storagenode/storagenodedb.(*DB).closeDatabases(0xc00044a0f0, 0x12e2df3, 0x6)
/go/src/storj io/storj/storagenode/storagenodedb/database.go:384 +0xb5
storj io/storj/storagenode/storagenodedb.(*DB).openDatabases(0xc00044a0f0, 0xc00044a0f0, 0x12e43d3)
/go/src/storj io/storj/storagenode/storagenodedb/database.go:197 +0x87e
storj io/storj/storagenode/storagenodedb.New(0xc00011c540, 0xc00043d740, 0x16, 0xc00052e180, 0x23, 0xc0005582e0, 0x1d, 0x0, 0x0, 0xc00043d740, …)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:172 +0x860
main.cmdRun(0x1048260, 0xc000161b00, 0x0, 0x6, 0x0, 0x0)
/go/src/storj io/storj/cmd/storagenode/main.go:147 +0x5cd
storj io/private/process.cleanup.func1.4(0x1485b00, 0xc0004490e0)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:359 +0x142
storj io/private/process.cleanup.func1(0x1048260, 0xc000161b00, 0x0, 0x6, 0x0, 0x0)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:377 +0x21c9
github com/spf13/cobra.(*Command).execute(0x1048260, 0xc000161a40, 0x6, 0x6, 0x1048260, 0xc000161a40)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:840 +0x467
github com/spf13/cobra.(*Command).ExecuteC(0x1047fc0, 0xc00006c000, 0x1336268, 0x0)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:945 +0x31e
github com/spf13/cobra.(*Command).Execute(…)
/go/pkg/mod/github.com/spf13/cobra@v0.0.6/command.go:885
storj io/private/process.ExecWithCustomConfig(0x1047fc0, 0x0, 0x1336268)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:88 +0x196
storj io/private/process.ExecCustomDebug(…)
/go/pkg/mod/storj.io/private@v0.0.0-20200504130741-565a173f6d33/process/exec_conf.go:70
main.main()
/go/src/storj.io/storj/cmd/storagenode/main.go:320 +0x45

ethan · July 24, 2020, 4:53pm

Can you check the permissions on C:\Program Files\Storj\Storage Node\storage\orders.db to make sure the file is writable for the storage node process user.

Next you can run the following to verify the DB is not corrupt.
sqlite3 pieceinfo.db "PRAGMA integrity_check;"
If it is, please see https://support.storj.io/hc/en-us/articles/360029309111-How-to-fix-a-database-disk-image-is-malformed-?_ga=2.246141572.1035966471.1595438903-1386301597.1583787199

BigR · July 25, 2020, 5:06am

C:\Program Files\Storj\Storage Node>sqlite3 pieceinfo.db “PRAGMA integrity_check;”
ok