Connection to node -1 could not be established. Broker may not be available.

[hpwxf]

trafficstars

This issue follows discussion: https://discuss.lightbend.com/t/error-running-the-reference-hello-lagom-application-for-scala/265

Sometimes, after a crash of the application, a restart using sbt runAll produces the following error:

[warn] org.apache.kafka.clients.NetworkClient [] - Connection to node -1 could not be established. Broker may not be available.

which appears continually on logging console.

The first time I saw this error was with online-auction-scala example; my new code based on it produces this error very often (at least once a day). I don't have yet a trivial reproducer (the most similar procedure seems to be to run this example and to stop it with something like Ctrl-C to emulate an application crash and then restart the application).

At the runAllstartup, Kafka crashes:

[info] Starting Kafka
[info] Starting Cassandra
..........
[info] Cassandra server running at 127.0.0.1:4000
Kafka Server closed unexpectedly.

If I inspect logs in the directory you suggest, I can see in server.log (from target/lagom-dynamic-projects/lagom-internal-meta-project-kafka/target/log4j_outputdirectory``` -- full log as attached file)

[2018-03-26 14:07:07,953] INFO Creating /brokers/ids/0 (is it secure? false) (kafka.utils.ZKCheckedEphemeral)
[2018-03-26 14:07:07,957] INFO Got user-level KeeperException when processing sessionid:0x16262346bea0000 type:create cxid:0x24 zxid:0xbe txntype:-1 reqpath:n/a Error Path:/brokers Error:KeeperErrorCode = NodeExists for /brokers (org.apache.zookeeper.server.PrepRequestProcessor)
[2018-03-26 14:07:07,957] INFO Got user-level KeeperException when processing sessionid:0x16262346bea0000 type:create cxid:0x25 zxid:0xbf txntype:-1 reqpath:n/a Error Path:/brokers/ids Error:KeeperErrorCode = NodeExists for /brokers/ids (org.apache.zookeeper.server.PrepRequestProcessor)
[2018-03-26 14:07:07,957] INFO Got user-level KeeperException when processing sessionid:0x16262346bea0000 type:create cxid:0x26 zxid:0xc0 txntype:-1 reqpath:n/a Error Path:/brokers/ids/0 Error:KeeperErrorCode = NodeExists for /brokers/ids/0 (org.apache.zookeeper.server.PrepRequestProcessor)
[2018-03-26 14:07:07,960] INFO Result of znode creation is: NODEEXISTS (kafka.utils.ZKCheckedEphemeral)
[2018-03-26 14:07:07,961] FATAL [Kafka Server 0], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
java.lang.RuntimeException: A broker is already registered on the path /brokers/ids/0. This probably indicates that you either have configured a brokerid that is already in use, or else you have shutdown this broker and restarted it faster than the zookeeper timeout so it appears to be re-registering.
[server.log](https://github.com/lagom/lagom/files/1848163/server.log)

Deleting target/lagom-dynamic-projects/lagom-internal-meta-project-kafka/target/zookeeper_data directory seems to help to clean embedded Kafka data and to restart without this error.

If this error is related to a corruption of Zookeeper data, is there a way to to prevent this corruption or to automacally repair the embedded Kafka while using runAll sbt command ?

NB: My configuration is:

• Scala environment
• Lagom 1.4.1
• Java 1.8.0.144
• macOS High Sierra 10.13.3

[hpwxf]

The complete server.log file. server.log

[ignasi35]

From a log message highlighted in the discuss thread: (added NEW_LINES for readability

java.lang.RuntimeException: A broker is already registered on the path 
/brokers/ids/0. This probably indicates that you either have configured 
a brokerid that is already in use, or else you have shutdown this broker 
and restarted it faster than the zookeeper timeout so it appears to be 
re-registering.

I wonder If we could lower that value and/or control ZK's restart (if that's the actual source of this issue).

[SattaiLanfear]

I've found when I've had to kill SBT in the middle of runAll a lot of things can go wrong.

I've had cassandra corrupt its database apparently. I've had kafka continue running as though forked. (Had to manually find and kill it).

In either case once I've removed all the relevant processes and run a clean things usually came back, though of course any test state had to be reestablished.

[arnaud-deprez]

Hi,

I have similar behaviour with https://github.com/lagom/online-auction-scala even after having deleted all the target directory:

[info] Loading settings from build.sbt ...
[info] Set current project to online-auction-scala (in build file:/Users/arnaud/Development/public/lagom/online-auction-scala/)
[info] Updating lagom-internal-meta-project-kafka...
[info] Done updating.
[info] Starting Kafka
[info] Updating lagom-internal-meta-project-cassandra...
[info] Done updating.
[info] Starting Cassandra
.WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by javassist.ClassPool (file:/Users/arnaud/.ivy2/cache/org.javassist/javassist/bundles/javassist-3.21.0-GA.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int)
WARNING: Please consider reporting this to the maintainers of javassist.ClassPool
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by io.netty.util.internal.PlatformDependent0$1 (file:/Users/arnaud/.ivy2/cache/io.netty/netty-common/jars/netty-common-4.0.44.Final.jar) to field java.nio.Buffer.address
WARNING: Please consider reporting this to the maintainers of io.netty.util.internal.PlatformDependent0$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
Exception (java.lang.ExceptionInInitializerError) encountered during startup: null
java.lang.ExceptionInInitializerError
        at org.github.jamm.MemoryMeter.measure(MemoryMeter.java:178)
        at org.apache.cassandra.utils.ObjectSizes.measure(ObjectSizes.java:163)
        at org.apache.cassandra.utils.ObjectSizes.<clinit>(ObjectSizes.java:39)
        at org.apache.cassandra.dht.Murmur3Partitioner.<clinit>(Murmur3Partitioner.java:46)
        at java.base/java.lang.Class.forName0(Native Method)
        at java.base/java.lang.Class.forName(Class.java:315)
        at org.apache.cassandra.utils.FBUtilities.classForName(FBUtilities.java:464)
        at org.apache.cassandra.utils.FBUtilities.instanceOrConstruct(FBUtilities.java:480)
        at org.apache.cassandra.utils.FBUtilities.newPartitioner(FBUtilities.java:430)
        at org.apache.cassandra.utils.FBUtilities.newPartitioner(FBUtilities.java:416)
        at org.apache.cassandra.config.DatabaseDescriptor.applyPartitioner(DatabaseDescriptor.java:992)
        at org.apache.cassandra.config.DatabaseDescriptor.applyAll(DatabaseDescriptor.java:312)
        at org.apache.cassandra.config.DatabaseDescriptor.daemonInitialization(DatabaseDescriptor.java:142)
        at org.apache.cassandra.service.CassandraDaemon.applyConfig(CassandraDaemon.java:647)
        at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:582)
        at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:691)
Caused by: java.lang.StringIndexOutOfBoundsException: begin 0, end -1, length 5
        at java.base/java.lang.String.checkBoundsBeginEnd(String.java:3319)
        at java.base/java.lang.String.substring(String.java:1874)
        at org.github.jamm.MemoryLayoutSpecification.getEffectiveMemoryLayoutSpecification(MemoryLayoutSpecification.java:190)
        at org.github.jamm.MemoryLayoutSpecification.<clinit>(MemoryLayoutSpecification.java:31)
        ... 16 more
10/04 10:49:04 ERROR[main] o.a.c.s.CassandraDaemon - Exception encountered during startup
java.lang.ExceptionInInitializerError: null
        at org.github.jamm.MemoryMeter.measure(MemoryMeter.java:178) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.utils.ObjectSizes.measure(ObjectSizes.java:163) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.utils.ObjectSizes.<clinit>(ObjectSizes.java:39) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.dht.Murmur3Partitioner.<clinit>(Murmur3Partitioner.java:46) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at java.base/java.lang.Class.forName0(Native Method) ~[na:na]
        at java.base/java.lang.Class.forName(Class.java:315) ~[na:na]
        at org.apache.cassandra.utils.FBUtilities.classForName(FBUtilities.java:464) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.utils.FBUtilities.instanceOrConstruct(FBUtilities.java:480) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.utils.FBUtilities.newPartitioner(FBUtilities.java:430) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.utils.FBUtilities.newPartitioner(FBUtilities.java:416) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.config.DatabaseDescriptor.applyPartitioner(DatabaseDescriptor.java:992) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.config.DatabaseDescriptor.applyAll(DatabaseDescriptor.java:312) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.config.DatabaseDescriptor.daemonInitialization(DatabaseDescriptor.java:142) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.service.CassandraDaemon.applyConfig(CassandraDaemon.java:647) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:582) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:691) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
Caused by: java.lang.StringIndexOutOfBoundsException: begin 0, end -1, length 5
        at java.base/java.lang.String.checkBoundsBeginEnd(String.java:3319) ~[na:na]
        at java.base/java.lang.String.substring(String.java:1874) ~[na:na]
        at org.github.jamm.MemoryLayoutSpecification.getEffectiveMemoryLayoutSpecification(MemoryLayoutSpecification.java:190) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        at org.github.jamm.MemoryLayoutSpecification.<clinit>(MemoryLayoutSpecification.java:31) ~[cassandra-bundle.jar:0.59-SNAPSHOT]
        ... 16 common frames omitted
.Kafka Server closed unexpectedly.

The only difference from the README file is that I start elasticsearch in a docker container with docker run --rm -p 9200:9200 -p 9300:9300 -e "discovery.type=single-node" docker.elastic.co/elasticsearch/elasticsearch:5.5.3 and I'm using java 11.

Switching back to java 8 works as expected once I have removed every target directory and recompile everything.

[TimMoore]

@arnaud-deprez this is unrelated to the original issue reported here. Cassandra is not compatible with Java versions newer than 8.

[arnaud-deprez]

Yep sorry, just realised that. Anyway might be useful to keep the comment here in case other people forgot that they move they default path to java 11 and have this behaviour like me :-S

[alarmdev]

try moving your version-x directory from your zookeeper data path and restart both zk and kafak server. this should clear your error. make sure you have your version data.

[deepakmehra10]

This issue still persists, I am getting this warning log continuously on the console 2019-01-19T14:22:13.633Z [warn] org.apache.kafka.clients.NetworkClient [] - Connection to node -1 could not be established. Broker may not be available.

I am failed to understand why is this happening @TimMoore . Any idea.

[TimMoore]

@deepakmehra10 this usually happens because Kafka cannot start up, which could happen for various reasons. Please review the Kafka logs for the reason.

[deepakmehra10]

Hi @TimMoore ,

Thank you for the reply, will take a look.

[nithincp]

@deepakmehra10 Could you resolve that issue?

[deepakmehra10]

Yes

On Mon 26 Aug, 2019, 11:06 AM Nithin Chandran P, [email protected] wrote:

@deepakmehra10 https://github.com/deepakmehra10 Could you resolve that issue?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/lagom/lagom/issues/1285?email_source=notifications&email_token=AEDGK6JOYQSS3I7SOM5KYFTQGNTXRA5CNFSM4EXM2M72YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5DKCEA#issuecomment-524722448, or mute the thread https://github.com/notifications/unsubscribe-auth/AEDGK6PQGGICC7IGN4TUQ53QGNTXRANCNFSM4EXM2M7Q .

[nithincp]

@deepakmehra10 Could you please help me in resolving that issue I got that error when i was doing it through the command prompt,now I tried setting everything up in Pycharm and created 2 files consumer.py and producer.py

consumer.py

`from kafka import KafkaConsumer

consumer = KafkaConsumer('test', bootstrap_servers=['localhost:9092'], api_version=(0, 10, 1),
                         auto_offset_reset='earliest')
print("Consuming messages")
for msg in consumer:
    print(msg)
`

producer.py

from kafka import KafkaProducer

producer = KafkaProducer(bootstrap_servers=['localhost:9092'], retries=5, api_version=(0, 10, 1),
                         )
for _ in range(100):
    ack = producer.send('test', b'HELLO NITHIN chandran')

Output for consumer.py Consuming messages

Output for producer.py "Failed to update metadata after %.1f secs." % (max_wait,)) kafka.errors.KafkaTimeoutError: KafkaTimeoutError: Failed to update metadata after 60.0 secs.

[nithincp]

Can anyone please help on the above issue?

[TimMoore]

@nithincp this isn't the best place to ask for general Kafka help. Try Stack Overflow or the Kafka Users mailing list.

[nithincp]

@TimMoore Okay sorry. I will try on Stackoverflow.

[dcguim]

This issue normally appears when listeners or advertised.listeners on config/server.properties are not appropriately configured or used. More, info