search

nervosnetwork / fiber

19 stars 10 forks source link

The log at startup is confusing when meet InvalidParameter error #231

Open ahonn opened 2 weeks ago

ahonn commented 2 weeks ago

After running fnn as per the README instructions, I noticed that a lot of logs were generated, with the last few containing some InvalidParameter("Node announcement message signature verification failed: NodeAnnouncement...) errors. The error logs are quite confusing. Although I can see a log entry like INFO fnn: Starting rpc, but I'm not sure whether it started successfully.

This situation leads me to believe that the error logs represent the issues encountered during startup. If the InvalidParameter error occurs but doesn't affect the functionality, should we consider changing its log level to warn?

  2024-10-15T04:43:19.268249Z  INFO fnn: Starting fiber
    at src/main.rs:106
    in fnn::node with node: ""

  2024-10-15T04:43:19.270177Z  INFO fnn::fiber::network: Started listening tentacle on "/ip4/127.0.0.1/tcp/8228/p2p/QmeTaPHLAGJakm5sGGrFFCanD3QWcwDt7BXtZxuuLJR1Y3", peer id PeerId(QmeTaPHLAGJakm5sGGrFFCanD3QWcwDt7BXtZxuuLJR1Y3), announced addresses ["/ip4/127.0.0.1/tcp/8228/p2p/QmeTaPHLAGJakm5sGGrFFCanD3QWcwDt7BXtZxuuLJR1Y3"]
    at src/fiber/network.rs:3279
    in ractor::actor::Actor with id: "0.2", name: "Network QmeTaPHLAGJakm5sGGrFFCanD3QWcwDt7BXtZxuuLJR1Y3"
    in fnn::node with node: ""

  2024-10-15T04:43:19.740572Z  WARN fnn::ckb::config: Your secret file's permission is not less than 0o600, path: "./ckb/key". Please fix it as soon as possible
    at src/ckb/config.rs:75
    in ractor::actor::Actor with id: "0.3", name: "watchtower"
    in fnn::node with node: ""

  2024-10-15T04:43:19.741063Z  INFO fnn: Starting rpc
    at src/main.rs:227
    in fnn::node with node: ""

  2024-10-15T04:43:20.562574Z  INFO fnn::fiber::network: proto id [ProtocolId(42)] open on session [SessionId(1)], address: [/ip4/54.179.226.154/tcp/8228/p2p/Qmes1EBD4yNo9Ywkfe6eRw9tG1nVNGLDmMud1xJMsoYFKy], type: [Outbound], version: 0.0.1
    at src/fiber/network.rs:3489

  2024-10-15T04:43:20.564037Z  INFO fnn::fiber::network: proto id [ProtocolId(42)] open on session [SessionId(2)], address: [/ip4/54.179.226.154/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV], type: [Outbound], version: 0.0.1
    at src/fiber/network.rs:3489

  2024-10-15T04:43:20.997028Z  INFO fnn::ckb::actor: [ckb] trace transaction Byte32(0x25cb76dfaed974cd6844b2ea53c472efb04ce7ea750e70b20d5ee43ec40aadab) with 1 confs
    at src/ckb/actor.rs:172
    in ractor::actor::Actor with id: "0.1", name: "ckb"

  2024-10-15T04:43:21.699782Z  INFO fnn::ckb::actor: [ckb] trace transaction Byte32(0x25cb76dfaed974cd6844b2ea53c472efb04ce7ea750e70b20d5ee43ec40aadab) with 1 confs
    at src/ckb/actor.rs:172
    in ractor::actor::Actor with id: "0.1", name: "ckb"

  2024-10-15T04:43:22.660656Z ERROR fnn::fiber::network: Failed to process broadcasted message: InvalidParameter("Node announcement message signature verification failed: NodeAnnouncement { signature: Some(EcdsaSignature(3045022100f7c5049ba5b32e4eac0a7f33b92ccdeede4a4706c4ee31104768e6a8ae60400402206f8eae115142881b8a2a521b657369d68b5f93977614ce843ebd12ed38158b13)), features: 0, version: 1728966977389, node_id: Pubkey(PublicKey(8f10cb3b7d65a037d94dd259f5fdcb4dc42d2256ea783a471b1b7118cff9dc13cfd6da3344cefaf30a236728ecc1e21b084a235231977323f89733147a7b6f87)), alias: AnnouncedNodeName(), addresses: [\"/ip4/0.0.0.0/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\", \"/ip4/54.179.226.154/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\"], chain_hash: Hash256(0x0000000000000000000000000000000000000000000000000000000000000000), auto_accept_min_ckb_funding_amount: 16200000000, udt_cfg_infos: UdtCfgInfos([]) }")
    at src/fiber/network.rs:654
    in ractor::actor::Actor with id: "0.2", name: "Network QmeTaPHLAGJakm5sGGrFFCanD3QWcwDt7BXtZxuuLJR1Y3"

  2024-10-15T04:43:22.660936Z ERROR fnn::fiber::network: Failed to handle ckb network event: Invalid peer message: Failed to process broadcasted message: InvalidParameter("Node announcement message signature verification failed: NodeAnnouncement { signature: Some(EcdsaSignature(3045022100f7c5049ba5b32e4eac0a7f33b92ccdeede4a4706c4ee31104768e6a8ae60400402206f8eae115142881b8a2a521b657369d68b5f93977614ce843ebd12ed38158b13)), features: 0, version: 1728966977389, node_id: Pubkey(PublicKey(8f10cb3b7d65a037d94dd259f5fdcb4dc42d2256ea783a471b1b7118cff9dc13cfd6da3344cefaf30a236728ecc1e21b084a235231977323f89733147a7b6f87)), alias: AnnouncedNodeName(), addresses: [\"/ip4/0.0.0.0/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\", \"/ip4/54.179.226.154/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\"], chain_hash: Hash256(0x0000000000000000000000000000000000000000000000000000000000000000), auto_accept_min_ckb_funding_amount: 16200000000, udt_cfg_infos: UdtCfgInfos([]) }")
    at src/fiber/network.rs:3399
    in ractor::actor::Actor with id: "0.2", name: "Network QmeTaPHLAGJakm5sGGrFFCanD3QWcwDt7BXtZxuuLJR1Y3"

  2024-10-15T04:43:22.660977Z ERROR fnn::fiber::graph_syncer: Failed to get broadcast messages from peer: InvalidParameter("Node announcement message signature verification failed: NodeAnnouncement { signature: Some(EcdsaSignature(3045022100f7c5049ba5b32e4eac0a7f33b92ccdeede4a4706c4ee31104768e6a8ae60400402206f8eae115142881b8a2a521b657369d68b5f93977614ce843ebd12ed38158b13)), features: 0, version: 1728966977389, node_id: Pubkey(PublicKey(8f10cb3b7d65a037d94dd259f5fdcb4dc42d2256ea783a471b1b7118cff9dc13cfd6da3344cefaf30a236728ecc1e21b084a235231977323f89733147a7b6f87)), alias: AnnouncedNodeName(), addresses: [\"/ip4/0.0.0.0/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\", \"/ip4/54.179.226.154/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\"], chain_hash: Hash256(0x0000000000000000000000000000000000000000000000000000000000000000), auto_accept_min_ckb_funding_amount: 16200000000, udt_cfg_infos: UdtCfgInfos([]) }")
    at src/fiber/graph_syncer.rs:185
    in ractor::actor::Actor with id: "0.5", name: "Graph syncer to QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV"
contrun commented 2 weeks ago

This is indeed confusing, but I am wondering if there is another bug here. There shouldn't be errors like Node announcement message signature verification failed normal operation scenario. How did you get this error? Can you still reproduce the problem here? If you can, can you run the node after export RUST_BACKTRACE=full RUST_LOG=debug and then post the full message to a pastebin? I will fix the confusing error message once I find there is no other bug.

chenyukang commented 2 weeks ago

@contrun I think these message should also be warn:

connect self:

ERROR fnn::fiber::network: Dialer error: "/ip4/127.0.0.1/tcp/8345/p2p/QmSRcPqUn4aQrKHXyCDjGn2qBVf43tWBDS2Wj9QDUZXtZp" -> HandshakeError(SecioError(ConnectSelf))

repeated connect:

ERROR fnn::fiber::network: Dialer error: "/ip4/127.0.0.1/tcp/8345/p2p/QmSRcPqUn4aQrKHXyCDjGn2qBVf43tWBDS2Wj9QDUZXtZp" -> RepeatedConnection(SessionId(3))
contrun commented 1 week ago

The error message 2024-10-15T04:43:22.660656Z ERROR fnn::fiber::network: Failed to process broadcasted message: InvalidParameter("Node announcement message signature verification failed: NodeAnnouncement { signature: Some(EcdsaSignature(3045022100f7c5049ba5b32e4eac0a7f33b92ccdeede4a4706c4ee31104768e6a8ae60400402206f8eae115142881b8a2a521b657369d68b5f93977614ce843ebd12ed38158b13)), features: 0, version: 1728966977389, node_id: Pubkey(PublicKey(8f10cb3b7d65a037d94dd259f5fdcb4dc42d2256ea783a471b1b7118cff9dc13cfd6da3344cefaf30a236728ecc1e21b084a235231977323f89733147a7b6f87)), alias: AnnouncedNodeName(), addresses: [\"/ip4/0.0.0.0/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\", \"/ip4/54.179.226.154/tcp/18228/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV/p2p/QmdyQWjPtbK4NWWsvy8s69NGJaQULwgeQDT5ZpNDrTNaeV\"], chain_hash: Hash256(0x0000000000000000000000000000000000000000000000000000000000000000), auto_accept_min_ckb_funding_amount: 16200000000, udt_cfg_infos: UdtCfgInfos([]) }") is indeed problematic. It seems we introduce a breaking change in https://github.com/contrun/fiber/commit/66a9fd8d947cac99ee2224c818608aed3e50f88f , in which we added an extra field to the NodeAnnouncement message. This makes the calculation of the message to sign/verify signatures different on different versions of fiber node program.

ahonn commented 1 week ago

This is indeed confusing, but I am wondering if there is another bug here. There shouldn't be errors like Node announcement message signature verification failed normal operation scenario. How did you get this error? Can you still reproduce the problem here? If you can, can you run the node after export RUST_BACKTRACE=full RUST_LOG=debug and then post the full message to a pastebin? I will fix the confusing error message once I find there is no other bug.

How did you get this error?

I just run RUST_LOG=info ./fnn -c config.yml -d . according to the command in README

Here is the log when running the node after export RUST_BACKTRACE=full RUST_LOG=debug: https://pastebin.com/SQJinFHM