hyperledger-labs
Warning and error messages in Twinscoin logs to fix
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
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
both issues are unlikely linked to the "sync-rework" PR, so I've changed the issue's title
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
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.
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.
After adding a fifth node, node 5 also issues "Got nonsense" warnings periodically, and node 3 starts to emit "Got nonsense" warnings too.
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.
@kushti, could you tell us whether this behaviour is normal? Is there something here that needs to be fixed?