Jormungandr: Logging

[prographo]

Is your feature request related to a problem/context ? Please describe if applicable.

This feature request is related to the node failing to start.

Describe the solution you'd like

I would like more logging - either errors, or periodic descriptions of what the node is doing.

Additional context

The node is configured and started exactly as describe in the documentation

Oct 07 20:13:57.027 INFO Starting jormungandr 0.5.6 (HEAD-7ab929e+, release, linux [x86_64]) - [rustc 1.38.0 (625451e37 2019-09-23)], task: init
[...]
ct 07 20:14:38.272 INFO connecting to initial gossip peer, peer_addr: 3.115.57.216:3000, task: network
Oct 07 20:14:38.272 INFO connecting to initial gossip peer, peer_addr: 52.57.157.167:3000, task: network
Oct 07 20:14:38.272 INFO connecting to initial gossip peer, peer_addr: 18.139.40.4:3000, task: network
Oct 07 20:14:38.273 INFO connecting to initial gossip peer, peer_addr: 3.123.177.192:3000, task: network
Oct 07 20:14:38.273 INFO connecting to initial gossip peer, peer_addr: 3.123.155.47:3000, task: network
Oct 07 20:14:38.273 INFO connecting to initial gossip peer, peer_addr: 18.140.134.230:3000, task: network
Oct 07 20:14:38.274 INFO Starting server on 127.0.0.1:3101, scope: global

~/Cardano$ jcli rest v0 node stats get --host "http://localhost:3101/api"
---
blockRecvCnt: 0
lastBlockDate: "227.22192"
lastBlockFees: 0
lastBlockHash: 4115f5990dcb72901aa08d98795363cb65fc852283655bb5eff6326bf174f422
lastBlockHeight: "68058"
lastBlockSum: 0
lastBlockTime: ~
lastBlockTx: 0
txRecvCnt: 0
uptime: 1204

No blocks are ever received. It just sits there exactly like this (3rd attempt)

I could probably fix this myself, if there was some kind of error.

I see 3100 and 3101 are open. Probably I should be opening ports on my firewall? For example, if it is waiting for a reply from a server on a port, maybe say that. Internet connections take seconds, maybe a timeout?

But how to know? If it is in-fact doing something, perhaps it could say what it is doing.
"downloaded 50 bytes from X" or something, anything really.

Maybe that jcli thing could say what it's doing / what it's waiting for... anyway, without any info, i'm guessing.

Also, it starts the status server (3101) after it does a bunch of stuff - wrong way round, isn't it?

[rgoerwit]

This is the same behavior I observed with jormungandr 0.5.5 (and 0.5.6). I've compiled both from scratch.

[HM999]

Broken for me too. I'm on AWS.

[rgoerwit]

Oct 7 21:46:34 instance-1 jormungandr[27268]: Starting jormungandr 0.5.6+lock (master-3c613ee, release, linux [x86_64]) - [rustc 1.38.0 (625451e37 2019-09-23)], task: init
Oct 7 21:46:34 instance-1 jormungandr[27268]: Node started without path to the stored secret keys (not a stake pool or a BFT leader), task: init
Oct 7 21:46:34 instance-1 jormungandr[27268]: storing blockchain in '"/usr/local/cardano/blockchain/blocks.sqlite"', task: init
Oct 7 21:47:23 instance-1 jormungandr[27268]: connecting to bootstrap peer 3.123.155.47:3000, peer_addr: 3.123.155.47:3000, task: bootstrap
Oct 7 21:47:24 instance-1 jormungandr[27268]: initial bootstrap completed, peer_addr: 3.123.155.47:3000, task: bootstrap
Oct 7 21:47:24 instance-1 jormungandr[27268]: Starting 1 workers, scope: global
Oct 7 21:47:24 instance-1 jormungandr[27268]: starting task, task: client-query
Oct 7 21:47:24 instance-1 jormungandr[27268]: starting task, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: adding P2P Topology module: trusted-peers, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: start listening and accepting gRPC connections on 0.0.0.0:3100, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: Starting server on 127.0.0.1:3101, scope: global
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 3.112.185.217:3000, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 3.115.57.216:3000, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 52.57.157.167:3000, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 18.139.40.4:3000, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 3.123.177.192:3000, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 3.123.155.47:3000, task: network
Oct 7 21:47:24 instance-1 jormungandr[27268]: connecting to initial gossip peer, peer_addr: 18.140.134.230:3000, task: network
Oct 7 21:47:29 instance-1 jormungandr[27268]: incoming P2P connection on 10.128.0.2:3100, peer_addr: 138.201.181.94:47138, task: network
Oct 7 21:47:34 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: [2001:19f0:ac01:20::200]:3100, task: network, reason: Network is unreachable (os error 101)
Oct 7 21:47:34 instance-1 jormungandr[27268]: client P2P connection closed, node_id: 10127517464646818779, peer_addr: [2001:19f0:ac01:20::200]:3100, task: network
Oct 7 21:47:34 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: 176.31.122.83:3100, task: network, reason: Connection refused (os error 111)
Oct 7 21:47:34 instance-1 jormungandr[27268]: client P2P connection closed, node_id: 2419909587550422536, peer_addr: 176.31.122.83:3100, task: network
Oct 7 21:47:34 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: 188.193.116.232:3000, task: network, reason: Connection refused (os error 111)
Oct 7 21:47:34 instance-1 jormungandr[27268]: client P2P connection closed, node_id: 5229285601346881136, peer_addr: 188.193.116.232:3000, task: network
Oct 7 21:47:44 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: [2001:19f0:ac01:20::200]:3100, task: network, reason: Network is unreachable (os error 101)
Oct 7 21:47:44 instance-1 jormungandr[27268]: client P2P connection closed, node_id: 10127517464646818779, peer_addr: [2001:19f0:ac01:20::200]:3100, task: network
Oct 7 21:47:44 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: 176.31.122.83:3100, task: network, reason: Connection refused (os error 111)
Oct 7 21:47:44 instance-1 jormungandr[27268]: client P2P connection closed, node_id: 2419909587550422536, peer_addr: 176.31.122.83:3100, task: network
Oct 7 21:47:44 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: 188.193.116.232:3000, task: network, reason: Connection refused (os error 111)
Oct 7 21:47:44 instance-1 jormungandr[27268]: client P2P connection closed, node_id: 5229285601346881136, peer_addr: 188.193.116.232:3000, task: network
Oct 7 21:47:54 instance-1 jormungandr[27268]: error connecting to peer, peer_addr: [2001:19f0:ac01:20::200]:3100, task: network, reason: Network is unreachable (os error 101)

[rgoerwit]

log:
format: "plain"
level: "info"
output: "syslog"
p2p:
listen_address: "/ip4/0.0.0.0/tcp/3100"
public_address: "/ip4/my-ip-address-external/tcp/3100"
topics_of_interest:
blocks: "high"
messages: "high"
trusted_peers:
- "/ip4/3.123.177.192/tcp/3000"
- "/ip4/3.123.155.47/tcp/3000"
- "/ip4/52.57.157.167/tcp/3000"
- "/ip4/3.112.185.217/tcp/3000"
- "/ip4/18.140.134.230/tcp/3000"
- "/ip4/18.139.40.4/tcp/3000"
- "/ip4/3.115.57.216/tcp/3000"
rest:
listen: "127.0.0.1:3101"
storage: "/usr/local/cardano/blockchain"

[mzabaluev]

FYI, log level "debug" provides very detailed information on network-related activities of the node.

[prographo]

Is this making progress or nah?

I have no idea.

jcli says blockRecvCnt: 0

Been running 1 hour...

Oct 12 17:19:04.213 DEBG sending gossip to node 14548023685822520157, task: network
Oct 12 17:19:04.213 DEBG selecting gossips for 4485365775303479996, task: network
Oct 12 17:19:04.213 DEBG sending gossip to node 4485365775303479996, task: network
Oct 12 17:19:04.213 DEBG selecting gossips for 15870000297337153516, task: network
Oct 12 17:19:04.214 DEBG sending gossip to node 15870000297337153516, task: network
Oct 12 17:19:04.214 DEBG scheduling Read for: 0, scope: global
Oct 12 17:19:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:04.214 DEBG scheduling Read for: 2, scope: global
Oct 12 17:19:04.214 DEBG scheduling Read for: 2, scope: global
Oct 12 17:19:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:04.214 DEBG scheduling Read for: 1, scope: global
Oct 12 17:19:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:04.214 DEBG scheduling Read for: 3, scope: global
Oct 12 17:19:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:04.214 DEBG scheduling Read for: 1, scope: global
Oct 12 17:19:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:14.211 DEBG scheduling Read for: 0, scope: global
Oct 12 17:19:14.212 DEBG selecting gossips for 7759025128004985606, task: network
Oct 12 17:19:14.212 DEBG sending gossip to node 7759025128004985606, task: network
Oct 12 17:19:14.212 DEBG selecting gossips for 15250992350008249921, task: network
Oct 12 17:19:14.212 DEBG sending gossip to node 15250992350008249921, task: network
Oct 12 17:19:14.212 DEBG selecting gossips for 16729047502099380808, task: network
Oct 12 17:19:14.212 DEBG sending gossip to node 16729047502099380808, task: network
Oct 12 17:19:14.212 DEBG selecting gossips for 14548023685822520157, task: network
Oct 12 17:19:14.212 DEBG sending gossip to node 14548023685822520157, task: network
Oct 12 17:19:14.212 DEBG selecting gossips for 4485365775303479996, task: network
Oct 12 17:19:14.212 DEBG sending gossip to node 4485365775303479996, task: network
Oct 12 17:19:14.212 DEBG selecting gossips for 15870000297337153516, task: network
Oct 12 17:19:14.212 DEBG sending gossip to node 15870000297337153516, task: network
Oct 12 17:19:14.212 DEBG scheduling Read for: 1, scope: global
Oct 12 17:19:14.212 DEBG scheduling Read for: 1, scope: global
Oct 12 17:19:14.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:14.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:14.212 DEBG scheduling Read for: 2, scope: global
Oct 12 17:19:14.213 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:14.213 DEBG scheduling Read for: 2, scope: global
Oct 12 17:19:14.213 DEBG scheduling Read for: 3, scope: global
Oct 12 17:19:14.213 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:14.213 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 17:19:14.213 DEBG scheduling Read for: 0, scope: global
Oct 12 17:19:14.213 DEBG send; frame=Data { stream_id: StreamId(

...

Oct 12 18:20:54.211 DEBG sending gossip to node 14548023685822520157, task: network
Oct 12 18:20:54.211 DEBG selecting gossips for 4485365775303479996, task: network
Oct 12 18:20:54.211 DEBG sending gossip to node 4485365775303479996, task: network
Oct 12 18:20:54.212 DEBG selecting gossips for 15870000297337153516, task: network
Oct 12 18:20:54.212 DEBG sending gossip to node 15870000297337153516, task: network
Oct 12 18:20:54.212 DEBG scheduling Read for: 1, scope: global
Oct 12 18:20:54.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:20:54.212 DEBG scheduling Read for: 2, scope: global
Oct 12 18:20:54.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:20:54.212 DEBG scheduling Read for: 1, scope: global
Oct 12 18:20:54.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:20:54.212 DEBG scheduling Read for: 3, scope: global
Oct 12 18:20:54.212 DEBG scheduling Read for: 2, scope: global
Oct 12 18:20:54.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:20:54.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:20:54.212 DEBG scheduling Read for: 0, scope: global
Oct 12 18:20:54.212 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:21:04.213 DEBG scheduling Read for: 0, scope: global
Oct 12 18:21:04.213 DEBG selecting gossips for 7759025128004985606, task: network
Oct 12 18:21:04.213 DEBG sending gossip to node 7759025128004985606, task: network
Oct 12 18:21:04.213 DEBG selecting gossips for 15250992350008249921, task: network
Oct 12 18:21:04.214 DEBG sending gossip to node 15250992350008249921, task: network
Oct 12 18:21:04.214 DEBG selecting gossips for 16729047502099380808, task: network
Oct 12 18:21:04.214 DEBG sending gossip to node 16729047502099380808, task: network
Oct 12 18:21:04.214 DEBG selecting gossips for 14548023685822520157, task: network
Oct 12 18:21:04.214 DEBG sending gossip to node 14548023685822520157, task: network
Oct 12 18:21:04.214 DEBG selecting gossips for 4485365775303479996, task: network
Oct 12 18:21:04.214 DEBG sending gossip to node 4485365775303479996, task: network
Oct 12 18:21:04.214 DEBG selecting gossips for 15870000297337153516, task: network
Oct 12 18:21:04.214 DEBG sending gossip to node 15870000297337153516, task: network
Oct 12 18:21:04.214 DEBG scheduling Read for: 1, scope: global
Oct 12 18:21:04.214 DEBG scheduling Read for: 0, scope: global
Oct 12 18:21:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:21:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:21:04.214 DEBG scheduling Read for: 2, scope: global
Oct 12 18:21:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:21:04.214 DEBG scheduling Read for: 2, scope: global
Oct 12 18:21:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:21:04.214 DEBG scheduling Read for: 1, scope: global
Oct 12 18:21:04.214 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global
Oct 12 18:21:04.214 DEBG scheduling Read for: 3, scope: global
Oct 12 18:21:04.215 DEBG send; frame=Data { stream_id: StreamId(7) }, scope: global

[prographo]

I was able to receive blocks by:

1) opening the listening port on my firewall (port 3100)
2) changing my node-config.yaml file to exactly this:

$ cat node-config.yaml 
log:
  format: "plain"
  level: "info"
  output: "stderr"
p2p:
  listen_address: "/ip4/0.0.0.0/tcp/3100"
  public_address: "/ip4/MY-PUBLIC-IP/tcp/3100"
  topics_of_interest:
    blocks: "normal"
    messages: "low"
  trusted_peers: [
     /ip4/3.123.177.192/tcp/3000,
     /ip4/3.123.155.47/tcp/3000,
     /ip4/52.57.157.167/tcp/3000,
     /ip4/3.112.185.217/tcp/3000,
     /ip4/18.140.134.230/tcp/3000,
     /ip4/18.139.40.4/tcp/3000,
     /ip4/3.115.57.216/tcp/3000,
     /ip4/68.183.155.37/tcp/3100,
     /ip4/76.184.240.151/tcp/3000,
     /ip4/108.174.195.124/tcp/3100
    ]
rest:
  listen: "127.0.0.1:3101"
storage: "/tmp/jormungandr"
explorer:
  enabled: true

There are 4 difference to the official documentation
a) public_address line, this is blank in the official documentation
b) explorer is enabled (last time)
c) trusted peers list is formatted different
d) topics_of_interest: priority of blocks and messages

I am not sure which change made this work, but I do not think it was public_address line only, as I tried that before.

Anyway, the official documentation should change if public_address line is required and the port needs to be opened - because these things are not mentioned.

[NicolasDP]

don't enable the explorer unless you actually want to do that. This is going to blow your memory through the roof top and to the mooooooooon.

This seems to be an overall duplicate of #857 which will provide more info relating to what's going on.

[rgoerwit]

@NicolasDP With respect to explorer - I think a lot of us enabled it, because we're supposed to be testing, and not all of us (it's just how this goes sometimes) were sure what the testing priorities are. I had trouble just putting together a working node config file and talking to the advertised peers. No criticism indended, though: Testing of jormungander is happening at the same time as major user-visible changes, like a change in the format of peers in the node config file that invalidates all current configs.

[prographo]

How much memory do I need to run the explorer?

[vincenthz]

at the moment, a lot and it's only increasing (which might appears like a leak, but it's not). you're obviously more than welcome to test it, but at the moment the whole thing live in memory, until we store the old things away in slower & plentiful storage.