search

hyperledger-labs / Scorex

Scorex 2.0 Core
Apache License 2.0
544 stars 115 forks source link

Warning and error messages in Twinscoin logs to fix #152

Open terjokhin opened 6 years ago

terjokhin commented 6 years ago

Found some strange behaviour between two running nodes. It looks like for each sync request we get 2 answers from 1 node. That is the reason for warnings like [2-Hop-akka.actor.default-dispatcher-2] >> [WARN ] examples.hybrid.HybridNodeViewHolder >> 16:21:48.003 Received modifier 99aQPCZfUYc68nrvQtEH7PJ5RVv28abBWECaMce2bttL that is already in history

Full log

[2-Hop-akka.actor.default-dispatcher-10] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.985 Send message MessageSpec(22: RequestModifier) to localhost/127.0.0.1:54378
[2-Hop-akka.actor.default-dispatcher-12] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.986 Send message MessageSpec(22: RequestModifier) to localhost/127.0.0.1:9084
[2-Hop-akka.actor.default-dispatcher-4] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.987 Received message MessageSpec(33: Modifier) from localhost/127.0.0.1:9084
[2-Hop-akka.actor.default-dispatcher-4] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:47.988 Got modifiers of type 3 with ids Pojoe34B1cxMSXR2GZNAURNv3csphAQ2DY6ddnHQ3zm
[2-Hop-akka.actor.default-dispatcher-4] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:47.988 From remote connected peer: ConnectedPeer(localhost/127.0.0.1:9084)
[2-Hop-akka.actor.default-dispatcher-12] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.987 Received message MessageSpec(33: Modifier) from localhost/127.0.0.1:54378
[2-Hop-akka.actor.default-dispatcher-6] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:47.992 Got modifiers of type 3 with ids Pojoe34B1cxMSXR2GZNAURNv3csphAQ2DY6ddnHQ3zm
[2-Hop-akka.actor.default-dispatcher-6] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:47.992 From remote connected peer: ConnectedPeer(localhost/127.0.0.1:54378)
[2-Hop-akka.actor.default-dispatcher-13] >> [WARN ] examples.hybrid.HybridNodeViewHolder >> 16:21:47.992 Received modifier Pojoe34B1cxMSXR2GZNAURNv3csphAQ2DY6ddnHQ3zm that is already in history
[2-Hop-akka.actor.default-dispatcher-13] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.996 Received message MessageSpec(55: Inv) from localhost/127.0.0.1:54378
[2-Hop-akka.actor.default-dispatcher-6] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.996 Received message MessageSpec(55: Inv) from localhost/127.0.0.1:9084
[2-Hop-akka.actor.default-dispatcher-12] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.996 Send message MessageSpec(22: RequestModifier) to localhost/127.0.0.1:54378
[2-Hop-akka.actor.default-dispatcher-2] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.997 Send message MessageSpec(22: RequestModifier) to localhost/127.0.0.1:9084
[2-Hop-akka.actor.default-dispatcher-12] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.999 Received message MessageSpec(33: Modifier) from localhost/127.0.0.1:54378
[2-Hop-akka.actor.default-dispatcher-8] >> [INFO ] s.core.network.PeerConnectionHandler >> 16:21:47.999 Received message MessageSpec(33: Modifier) from localhost/127.0.0.1:9084
[2-Hop-akka.actor.default-dispatcher-2] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:47.999 Got modifiers of type 4 with ids 99aQPCZfUYc68nrvQtEH7PJ5RVv28abBWECaMce2bttL
[2-Hop-akka.actor.default-dispatcher-2] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:47.999 From remote connected peer: ConnectedPeer(localhost/127.0.0.1:54378)
[2-Hop-akka.actor.default-dispatcher-2] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:48.000 Got modifiers of type 4 with ids 99aQPCZfUYc68nrvQtEH7PJ5RVv28abBWECaMce2bttL
[2-Hop-akka.actor.default-dispatcher-2] >> [INFO ] s.core.network.NodeViewSynchronizer >> 16:21:48.000 From remote connected peer: ConnectedPeer(localhost/127.0.0.1:9084)
[2-Hop-akka.actor.default-dispatcher-2] >> [WARN ] examples.hybrid.HybridNodeViewHolder >> 16:21:48.003 Received modifier 99aQPCZfUYc68nrvQtEH7PJ5RVv28abBWECaMce2bttL that is already in history
terjokhin commented 6 years ago

Another suspicious messages, they appeared only on second node with settings2.conf

[2-Hop-akka.actor.default-dispatcher-40] >> [WARN ] e.hybrid.history.HybridHistory >> 16:29:32.003 Found chain without ids form remote
[2-Hop-akka.actor.default-dispatcher-40] >> [WARN ] e.hybrid.history.HybridHistory >> 16:29:32.003 CompareNonsense: List(9QtaztQpSXtVE25yKDiBkH72FafrKqydDREU4DAHxRi, 8o9fQU2Vncv7hCZ18qkJKuWu1aokrheXh2Xiqf2j5wd, 14byW9KrZ7h6QBoiC2xRBc3Dh1MmBH99dpSMCVsAamL4, FbKBT5mEKoHSBo6pZu19A7aY8dCow79X5hwbtwbQ7RG, LsCjArFUkqTDpbmrGiSPzideM51KJNuvichkjxxE7Qf, XvBLUBycnCV1RskQsWqQ91WFcUfUUZ5zYg512ovXRkp, KFJZoNWFGMPDqPAq3k36cRjK7u2mD6Bouru4vEVQUAv, X5F7sass1egDBrocTop3a9cZnjZPUsW8GrCnn7vLqqh, JidjTnawK73ruE5qpEbETBF2jm3UheFSvEEBZnqiM17, 9Ef9KCd5uQc3JVJJbLaS5DC1Ev9RiwZfyfDmitx9xoK, ULjgnfPBzQsm7CMWFnZdkb9FsvKhqf6hmuDumMZ1WbJ, DpPARRuNQKduTdaH7sRZC2JV7GjT5cRRyc9GH1ybnRG, PFFbuwKfKDCDWbwJkxsiqMJ4QiYjv48Si77dfvKj5CU, Bw8pqY1rh7juaCX3WHsfzu4eXszEQJmUsFAjYtdg65s, PyMix3jpY6F866xMkTmuSs7BoVEszBa6yMzYmTipjRk, 7vMfT6Qr93tQGKYPUFGMmAPTxmYXSPKpFrKQ4HX5chU, 95GRrE5wxbp74CdEDAL7NR4CKbdZWKj5HHDabZGdYfS, DMfeJNPA1jnF412a13BE3UaqVaBihoRKF9ysfCjEipr, 17MpqsMyYhGLE2g5kwdqxfEQFASwoDgsLf8Znjv1urj, EusEazEAP1Ry42mhgfDP72czAd9eGaNs3rCjRkPGMjf, 7jS7nuBZ4aUg12umGjLnibyL4U8tsKNmGJv2qegs6aw, 6XC8hksydunAsu8hgbeYfK1sKVbeDqKQ88U5zzfBxpy, 6cS5HecMa3n2cpZG8oySYczGv5sHWASDbzDzNDDEKpS, 5H2gG7aBrYWYzEcjbLVB1MRTW2dk7T4UawdrWsJs3R6, 13JfcaRcbPVLJemqb8t7NMtxFq2YgKLDBNu5sGCxcVgg, CMCnqFntdwH7R6AxC51LDvqjSxRrCacHFffp1aT85kW, 519ij1rKwGpvxx56qXAQL5oyC8FLJjWwLq71r285SpF, B98jYjwanJt169bQAxpfuUqXtzRxjq4P5pHmwBhXdMp, 1ohwtfcjkqXwZFbDjpUkfdAfSvgsnGeUWMdgSDrZSeM, ACwwGsQm9TjUevEguAmqBb2hBYy3rj2yPPNpMEAdzSN, 1Zz6jBW2M6jfhwL1ebiX5nvMXe48d2iwAjN4wAUTQhw, 14YwEUqE3qSeULHcakifVPb41w1kW4D2DaeyatdzaTfn, DSxdQPgvneUPXcL1pEAKkSJbYmKFkuggm4GQz9AWzZJ, AWyccKQy8AUBA398RMocp6RASSR31cGAgKKjiP2Dhnp, 5EQw4dMsYmae8oWMNkZhqWLPAj7pgXwt1J4XAQSMCHA, 57frahhMayqMj2UtbqSGvW4kaWfEu24vjzHoGF4wA6E, 5EBGCPAE51nKEhwyQpNfBPPnfeMP5GGCLoE2ne2mNHz, 1scXnnnKJA8rerDay27nRoe83YWHRQShhLxzRMoZ9Y3, 8MNCZ3PsXPikvu5jJ2Kt6wQ7NWQMx3DLHiiZQ4sdyzz, 7EtWeKiSK8G955nukgz9yjKthmgE4oU8K95S8dBsWRE, 7ZRVtFiWKEZrHZa8a6wCsMCvyn6DrheSEKNVW12bZLh, 7RGe6Yve6L5di1VWHGwbc778g4Nu2mE8mVN5PTT3sYn, 1bfiUHGktaGDQRLQWg3mWK5UMkpzdLr4eYSVMvrVCHE, 14HnkU8nMxz1L6zUWe7YovFikDvcaBp7FrKZ8BMKRpfx, 7txJ5DtP1brZ9i6rBn6K4ZU92sx3XrCsBhkpNgDjyUF, 123vfHPg5QdRDAwyxyvdfqVDEt2tL1igQXLRQTSr1zJy, 1Ciay3YTsNUDLCQNsAHAxGfRG49CPcAVCwQk2ScozLH, 5LwfBiQcYnPP5ugSBtma2CzsefERQJ36mjnQxEJuz1x, 134U2bXQqYfsMB5AqtLFB3K94puTPeArWGkJ8DotrQAQ, 13ffWirXsfPYsNA44YzbsokL7nE6MYX99fhW6dZXWNx7) at height 2}
[2-Hop-akka.actor.default-dispatcher-40] >> [WARN ] s.core.network.NodeViewSynchronizer >> 16:29:32.004 Got nonsense
kushti commented 6 years ago

both issues are unlikely linked to the "sync-rework" PR, so I've changed the issue's title

ceilican commented 6 years ago

When running a single node for a while, the following warning is eventually issued:

[info] [2-Hop-akka.actor.default-dispatcher-10] >> [INFO ] s.core.network.NetworkController >> 09:54:01.246 Connecting to: /127.0.0.2:9088
[info] [2-Hop-akka.actor.default-dispatcher-10] >> [INFO ] s.core.network.NetworkController >> 09:54:02.266 Failed to connect to : /127.0.0.2:9088
[info] [2-Hop-akka.actor.default-dispatcher-5] >> [WARN ] scorex.core.network.SyncTracker >> 09:51:37.262 Time to clear status for /127.0.0.2:9088, but it is not found
ceilican commented 6 years ago

And I was able to reproduce the warnings mentioned by @daron666 .

ceilican commented 6 years ago

After adding a third node, the second node continued issuing the "Got nonsense" warning from time to time. Strangely, only the second node does this. The first and and third node don't.

ceilican commented 6 years ago

After adding a fourth node, the first node eventually showed this warning:

[info] [2-Hop-akka.actor.default-dispatcher-24] >> [WARN ] e.hybrid.history.HybridHistory >> 10:29:09.913 Found chain without ids form remote
[info] [2-Hop-akka.actor.default-dispatcher-24] >> [WARN ] s.core.network.NodeViewSynchronizer >> 10:29:09.913 Extension is empty while comparison is younger
[info] [2-Hop-akka.actor.default-dispatcher-24] >> [WARN ] s.core.network.NodeViewSynchronizer >> 10:29:09.914 extOpt is empty for: ConnectedPeer(localhost/127.0.0.1:55491). Its status is: Younger.

Node 4, like Node 2, also issues "Got Nonsense" warnings periodically.

ceilican commented 6 years ago

After adding a fifth node, node 5 also issues "Got nonsense" warnings periodically, and node 3 starts to emit "Got nonsense" warnings too.

ceilican commented 6 years ago

It seems that, the more nodes I add, the more likely it is for a node N > 1 to emit "Got nonsense" warnings, and the more frequently node 1 emits "already in history" and "extOpt empty" warnings.

ceilican commented 6 years ago

@kushti, could you tell us whether this behaviour is normal? Is there something here that needs to be fixed?