Voucher request denied. Vetting process not yet complete

Node Operators FAQ
1

I have restarted my node today because I did not see any activity in the logs, nor errors. But when I restart it I have the following message:

2019-07-22T17:17:15.382Z INFO running on version v0.15.3
2019-07-22T17:17:16.705Z INFO db.migration Latest Version {“version”: 13}
2019-07-22T17:17:16.706Z INFO vouchers Checking vouchers
2019-07-22T17:17:16.707Z INFO Node 1HJzmgjrzd7dyCDYxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxr started
2019-07-22T17:17:16.707Z INFO Public server started on [::]:28967
2019-07-22T17:17:16.708Z INFO Private server started on 127.0.0.1:7778
2019-07-22T17:17:16.712Z INFO vouchers Requesting voucher {“satellite”: “12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs”}
2019-07-22T17:17:16.720Z INFO vouchers Requesting voucher {“satellite”: “12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S”}
2019-07-22T17:17:16.721Z INFO vouchers Requesting voucher {“satellite”: “118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW”}
2019-07-22T17:17:16.722Z INFO vouchers Requesting voucher {“satellite”: “121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6”}
2019-07-22T17:17:16.749Z INFO piecestore:monitor Remaining Bandwidth {“bytes”: 4885598543104}
2019-07-22T17:17:16.869Z INFO running on version v0.15.3
2019-07-22T17:17:32.775Z INFO vouchers Voucher request denied. Vetting process not yet complete
2019-07-22T17:17:34.864Z INFO vouchers Voucher request denied. Vetting process not yet complete
2019-07-22T17:17:39.554Z INFO vouchers Voucher request denied. Vetting process not yet complete
2019-07-22T17:17:44.175Z INFO vouchers Voucher request denied. Vetting process not yet complete

2

more debug info

[root@storj storj]# docker logs -f storagenode
2019-07-22T18:57:49.461Z INFO Configuration loaded from: /app/config/config.yaml
2019-07-22T18:57:49.461Z DEBUG debug server listening on 127.0.0.1:40932
2019-07-22T18:57:49.484Z INFO Operator email: xxxxxxx@gmail.com
2019-07-22T18:57:49.484Z INFO Operator wallet: 0x4928808cF3Ca6f9Ea19Ac5xxxxxxxxxx
2019-07-22T18:57:49.528Z DEBUG Binary Version: v0.15.3 with CommitHash 6217d9690fd7363d1ae35eefc12135ed6286a89f, built at 2019-07-17 18:42:01 +0000 UTC as Release true
2019-07-22T18:57:50.246Z DEBUG allowed minimum version from control server is: v0.15.1
2019-07-22T18:57:50.247Z INFO running on version v0.15.3
2019-07-22T18:57:50.247Z DEBUG Initialized telemetry batcher with id = “1HJzmgjrzd7dyCDYyN1NpkcmUF2CaFZpo3mREyXgjXZVNH3Hpr”
2019-07-22T18:57:51.734Z INFO db.migration Latest Version {“version”: 13}
2019-07-22T18:57:51.736Z INFO vouchers Checking vouchers
2019-07-22T18:57:51.739Z INFO Node 1HJzmgjrzd7dyCDYyN1NpkcmUF2CaFZpo3mREyXgjXZVNH3Hpr started
2019-07-22T18:57:51.739Z INFO Public server started on [::]:28967
2019-07-22T18:57:51.739Z INFO Private server started on 127.0.0.1:7778
2019-07-22T18:57:51.745Z DEBUG piecestore:orderssender sending
2019-07-22T18:57:51.750Z INFO vouchers Requesting voucher {“satellite”: “121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6”}
2019-07-22T18:57:51.754Z INFO vouchers Requesting voucher {“satellite”: “12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs”}
2019-07-22T18:57:51.756Z INFO vouchers Requesting voucher {“satellite”: “12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S”}
2019-07-22T18:57:51.756Z INFO vouchers Requesting voucher {“satellite”: “118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW”}
2019-07-22T18:57:51.787Z DEBUG piecestore:orderssender no orders to send
2019-07-22T18:57:51.795Z INFO piecestore:monitor Remaining Bandwidth {“bytes”: 4885598543104}
2019-07-22T18:57:51.898Z DEBUG allowed minimum version from control server is: v0.15.1
2019-07-22T18:57:51.898Z INFO running on version v0.15.3
2019-07-22T18:57:53.335Z DEBUG kademlia:endpoint Successfully connected with k3.bounceme.net:17130
2019-07-22T18:57:55.961Z DEBUG kademlia connecting to node failed {“target”: “1vZeXqGXuu4zZuMp3GpQHDuJggqwxjvQZJqRWsZo51ebEff6A”, “dial-node”: “12MTRXmdASvUJJBWy2ELRSvRevDLxfP3rYaKgad7g33D5bhjkm”, “dial-address”: “codebits-tplink.ddns.net:28967”, “error”: “transport error: connection error: desc = “transport: error while dialing: dial tcp: lookup codebits-tplink.ddns.net on 190.160.0.15:53: no such host””, “errorVerbose”: “transport error: connection error: desc = “transport: error while dialing: dial tcp: lookup codebits-tplink.ddns.net on 190.160.0.15:53: no such host”\n\tstorj.io/storj/pkg/transport.(*Transport).DialNode:108\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).dialNode:175\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).Lookup:71\n\tstorj.io/storj/pkg/kademlia.(*peerDiscovery).Run.func1:88”}
2019-07-22T18:57:57.883Z DEBUG kademlia connecting to node failed {“target”: “1HJzmgjrzd7dyCDYyN1NpkcmUF2CaFZpo3mREyXgjXZVNH3Hpr”, “dial-node”: “1JQ4fDfUDViEjUprEenGjEwXLNgsc7W8aVdfJgQzbrtTvrTmgq”, “dial-address”: “31.20.66.123:28967”, “error”: “transport error: connection error: desc = “transport: error while dialing: dial tcp 31.20.66.123:28967: connect: connection refused””, “errorVerbose”: “transport error: connection error: desc = “transport: error while dialing: dial tcp 31.20.66.123:28967: connect: connection refused”\n\tstorj.io/storj/pkg/transport.(*Transport).DialNode:108\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).dialNode:175\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).Lookup:71\n\tstorj.io/storj/pkg/kademlia.(*peerDiscovery).Run.func1:88”}
2019-07-22T18:57:59.342Z DEBUG kademlia connecting to node failed {“target”: “118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW”, “dial-node”: “12MTRXmdASvUJJBWy2ELRSvRevDLxfP3rYaKgad7g33D5bhjkm”, “dial-address”: “codebits-tplink.ddns.net:28967”, “error”: “transport error: connection error: desc = “transport: error while dialing: dial tcp: lookup codebits-tplink.ddns.net on 190.160.0.15:53: no such host””, “errorVerbose”: “transport error: connection error: desc = “transport: error while dialing: dial tcp: lookup codebits-tplink.ddns.net on 190.160.0.15:53: no such host”\n\tstorj.io/storj/pkg/transport.(*Transport).DialNode:108\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).dialNode:175\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).Lookup:71\n\tstorj.io/storj/pkg/kademlia.(*peerDiscovery).Run.func1:88”}
2019-07-22T18:58:03.046Z INFO vouchers Voucher request denied. Vetting process not yet complete
2019-07-22T18:58:03.480Z INFO vouchers Voucher request denied. Vetting process not yet complete
2019-07-22T18:58:05.429Z INFO vouchers Voucher request denied. Vetting process not yet complete
2019-07-22T18:58:33.031Z DEBUG kademlia connecting to node failed {“target”: “13GZQSPCHJjPLZJjXMPm9jLEehQHHHZ4ahVqCj1yPiB649Nxj3”, “dial-node”: “143BFywMhDey8ShCU1pAhpVF4FQKe6fbamnSjPQhfjCMYHTd6o”, “dial-address”: “vuli.ddns.net:28967”, “error”: “rpc error: code = Unavailable desc = transport is closing”}
2019-07-22T18:58:34.310Z DEBUG kademlia connecting to node failed {“target”: “13GZQSPCHJjPLZJjXMPm9jLEehQHHHZ4ahVqCj1yPiB649Nxj3”, “dial-node”: “13vgewCU9SwHHAPBvhbBahz1PpuXmHAu1mvo5fe57eByQSimqF”, “dial-address”: “nas.ryangrimes.com:28967”, “error”: “rpc error: code = Unavailable desc = transport is closing”}
2019-07-22T18:58:38.045Z DEBUG kademlia:endpoint connection to node failed {“error”: “node error: transport error: connection error: desc = “transport: authentication handshake failed: tls peer certificate verification error: not signed by any CA in the whitelist: CA cert””, “errorVerbose”: “node error: transport error: connection error: desc = “transport: authentication handshake failed: tls peer certificate verification error: not signed by any CA in the whitelist: CA cert”\n\tstorj.io/storj/pkg/transport.(*Transport).DialNode:108\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).dialNode:175\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).PingNode:95\n\tstorj.io/storj/pkg/kademlia.(*Kademlia).Ping:253\n\tstorj.io/storj/pkg/kademlia.(*Endpoint).pingback:57\n\tstorj.io/storj/pkg/kademlia.(*Endpoint).Query:42\n\tstorj.io/storj/pkg/pb._Nodes_Query_Handler.func1:535\n\tstorj.io/storj/pkg/server.logOnErrorUnaryInterceptor:39\n\tstorj.io/storj/pkg/pb._Nodes_Query_Handler:537\n\tgoogle.golang.org/grpc.(*Server).processUnaryRPC:998\n\tgoogle.golang.org/grpc.(*Server).handleStream:1278\n\tgoogle.golang.org/grpc.(*Server).serveStreams.func1.1:717”, “nodeID”: “12fwsPb8L9JccmaygvKLmn4RQNcNDgVBufDcsU6miPTKDpfnQSE”}
2019-07-22T18:58:41.678Z INFO vouchers Voucher request denied. Vetting process not yet complete

3

You need 100 audits to get vetted. This could take up to one month.

4

Sorry I asked, but I do not understand what happened. Everything worked very well for months, until I updated to the latest version.

Checking the logs, sometimes there are connections OK (DEBUG kademlia: endpoint Successfully connected with storj.ricoapp.com:28967 2700x times) but most of the time I have connection errors of 2 type

A) 2019-07-22T20:07:01.595Z DEBUG kademlia connecting to node failed {“target”: “132T4z4mFFHzk26Jupzc3Jtkgj6BoAiZM8rVR4x94Rn4z7Q7Qp”, “dial-node”: “13vgewCU9SwHHAPBvhbBahz1PpuXmHAu1mvo5fe57eByQSimqF”, “dial-address”: “nas.ryangrimes.com:28967”, “error”: “rpc error: code = Unavailable desc = transport is closing”}

B) 2019-07-22T20:08:14.315Z DEBUG kademlia:endpoint connection to node failed {“error”: “node error: transport error: connection error: desc = “transport: authentication handshake failed: tls peer certificate verification error: not signed by any CA in the whitelist: CA cert””, “errorVerbose”: “node error: transport error: connection error: desc = “transport: authentication handshake failed: tls peer certificate verification error: not signed by any CA in the whitelist: CA cert”\n\tstorj.io/storj/pkg/transport.(*Transport).DialNode:108\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).dialNode:175\n\tstorj.io/storj/pkg/kademlia/kademliaclient.(*Dialer).PingNode:95\n\tstorj.io/storj/pkg/kademlia.(*Kademlia).Ping:253\n\tstorj.io/storj/pkg/kademlia.(*Endpoint).pingback:57\n\tstorj.io/storj/pkg/kademlia.(*Endpoint).Query:42\n\tstorj.io/storj/pkg/pb._Nodes_Query_Handler.func1:535\n\tstorj.io/storj/pkg/server.logOnErrorUnaryInterceptor:39\n\tstorj.io/storj/pkg/pb._Nodes_Query_Handler:537\n\tgoogle.golang.org/grpc.(*Server).processUnaryRPC:998\n\tgoogle.golang.org/grpc.(*Server).handleStream:1278\n\tgoogle.golang.org/grpc.(*Server).serveStreams.func1.1:717”, “nodeID”: “18Un9mZhS6yjUdvibpfnD39EZG2XC86GrtjeBEoXYCiRdgzFiS”}

Why should I wait a month now to be ok again? :roll_eyes::roll_eyes:

5

There are 4 satellites, your node should be vetted on each satellite independently. To be vetted on exact satellite it should complete 100 audits for that satellite.

The quoted random error is not related to the vetting process and receiving vouchers :slight_smile:, it’s related to the SN misconfiguration one of your neighbor by kademlia

By the way, you don’t need to have a DEBUG level enabled.

6

ok, thanks, I’m going to deactivate the debug mode, I had it activated to see if something was happening, since I do not see any traffic at all, I thought there was something wrong with my node.
but in summary, would my node be working well then? I just have to leave it running and worry about the uptime

7

You node is paused on the Central Europe’s satellite. Please, fire a support ticket with your NodeID and current docker run command to ask for clearance to support@storj.io

1 Like
8

thanks! maill send with the info

9

Just to add to this, I have 170ish successful audits, but I still get vetting not yet complete:
docker logs storagenode 2>&1 | grep -iE “downloaded.*get_audit” |wc -l
171

Receiving/sending is working fine though.

10

You need 100 successful audits per satellite, so you need to hit that threshold on all satellites before the message disappears.

11

So why has my node not moved on to being vetted by another satellite at audit 100 in that case? Those 170 audits are all from the same satellite?

12

I can’t tell what satellite they are from, but most traffic comes from one satellite right now. However, it could well be that none of them has reached 100 yet. Just give it time, it’ll get there eventually for all 4 satellites.