Project

General

Profile

Bug #6875

Avatar?id=6023&size=22x22

Unable to create socket

Added by Daniel Wisnewski IoT 1 Cloud about 1 year ago. Updated about 1 year ago.

Status:
Closed
Priority:
Normal
Target version:
-
Start date:
Due date:
% Done:

0%

Estimated time:

Description

While running some demonstrations I accidentally shorted the board and forced a reset which essentially broke the DB and I needed to start fresh with new versions.

Running latest version of framework and hub results in a similar error to one we had previously. IoT hub performs as expected and seems to be unaffected.

2018-03-26 22:31:27.347 [pool-1-thread-1]  XmppService$JaxmppBean.lambda$scheduleReconnection$1()  WARNING: Can not connect client default
tigase.jaxmpp.core.client.exceptions.JaxmppException: tigase.jaxmpp.core.client.exceptions.JaxmppException: Cannot create socket.
    at tigase.jaxmpp.j2se.connectors.socket.SocketConnector.start(SocketConnector.java:1071)
    at tigase.jaxmpp.core.client.connector.ConnectorWrapper.start(ConnectorWrapper.java:96)
    at tigase.jaxmpp.j2se.Jaxmpp.login(Jaxmpp.java:412)
    at tigase.bot.runtime.XmppService$JaxmppBean.lambda$scheduleReconnection$1(XmppService.java:501)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: tigase.jaxmpp.core.client.exceptions.JaxmppException: Cannot create socket.
    at tigase.jaxmpp.j2se.connectors.socket.SocketConnector.start(SocketConnector.java:981)
    at tigase.jaxmpp.core.client.connector.ConnectorWrapper.start(ConnectorWrapper.java:96)
    at tigase.jaxmpp.j2se.Jaxmpp.login(Jaxmpp.java:412)
    at tigase.bot.runtime.XmppService$JaxmppBean.lambda$scheduleReconnection$1(XmppService.java:501)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Using an older build of framework yields the following result:

2018-03-26 22:41:24.188 [pool-4-thread-1]  PubSubNodesManager$DiscoverNodesTask$1.onError()  WARNING: at pubsub.tigase-iot-hub.local failed to get node null subnodes: policy_violation

2018-03-26 22:41:24.404 [pool-4-thread-1]  PubSubNodesManager$2.onEror()           WARNING:  at pubsub.tigase-iot-hub.local failed to create device node - policy_violation null

Is it possible that 22408144 is not included in b60?

Associated revisions

Revision 5d23e2d5 (diff)
Added by Andrzej Wójcik IoT 1 CloudTigaseTeam about 1 year ago

#6875: fixing issue with hanging connection when C2S connection was accepted before SM was initialized

Revision e82e0811 (diff)
Added by Andrzej Wójcik IoT 1 CloudTigaseTeam about 1 year ago

#6875: improved error reporting and provided suggestions for the user on how to fix errors

History

#1 Updated by Daniel Wisnewski IoT 1 Cloud about 1 year ago

Okay, looking further, some more errors pop up as this conitnues

2018-03-27 00:32:53.811 [pool-1-thread-4]  XmppService$JaxmppBean.lambda$scheduleReconnection$1()  WARNING: Can not connect client default
tigase.jaxmpp.core.client.exceptions.JaxmppException: java.net.ConnectException: Connection refused
    at tigase.jaxmpp.j2se.connectors.socket.SocketConnector.start(SocketConnector.java:1071)
    at tigase.jaxmpp.core.client.connector.ConnectorWrapper.start(ConnectorWrapper.java:96)
    at tigase.jaxmpp.j2se.Jaxmpp.login(Jaxmpp.java:412)
    at tigase.bot.runtime.XmppService$JaxmppBean.lambda$scheduleReconnection$1(XmppService.java:501)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.ConnectException: Connection refused
    at java.net.PlainSocketImpl.socketConnect(Native Method)
    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
    at java.net.Socket.connect(Socket.java:589)
    at java.net.Socket.connect(Socket.java:538)
    at tigase.jaxmpp.j2se.connectors.socket.SocketConnector.createSocket(SocketConnector.java:239)
    at tigase.jaxmpp.j2se.connectors.socket.SocketConnector.start(SocketConnector.java:973)
    at tigase.jaxmpp.core.client.connector.ConnectorWrapper.start(ConnectorWrapper.java:96)
    at tigase.jaxmpp.j2se.Jaxmpp.login(Jaxmpp.java:412)
    at tigase.bot.runtime.XmppService$JaxmppBean.lambda$scheduleReconnection$1(XmppService.java:501)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

This continues for about 20 seconds and then this error shows:

2018-03-27 00:33:13.799 [pool-1-thread-2]  XmppService$JaxmppBean.lambda$scheduleReconnection$1()  WARNING: Can not connect client default
tigase.jaxmpp.core.client.exceptions.JaxmppException: Connector is not in disconnected state
    at tigase.jaxmpp.j2se.Jaxmpp.login(Jaxmpp.java:373)
    at tigase.bot.runtime.XmppService$JaxmppBean.lambda$scheduleReconnection$1(XmppService.java:501)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Could this be a spam filter blocking traffic? I'm not sure here.

I tried this on a fresh install of Debian and symptoms are the same.

#2 Updated by Daniel Wisnewski IoT 1 Cloud about 1 year ago

  • Estimated time deleted (2.50 h)

#3 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam about 1 year ago

  • Status changed from New to In Progress

#4 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam about 1 year ago

  • Status changed from In Progress to In QA
  • Assignee changed from Andrzej Wójcik to Daniel Wisnewski

I've found a few issues here:

  1. Connection was accepted by the server but it was hanged as SessionManager was not initialized yet (Tigase XMPP Server)
  2. Connection was scheduled for multiple reconnection attempts at the same time causing a reconnection attempt while the connection was already established. (JaXMPP Bot Framework)

So to fix this issue you will need new builds (next snapshot builds) of Tigase IoT Framework and Tigase IoT Hub created after new snapshot builds of Tigase XMPP Server and Jaxmpp Bot Framework are created (I did not start one). So it would be best to wait for Jenkins to generate this next snapshot builds before testing this issue.

As for logged errors:

  1. tigase.jaxmpp.core.client.exceptions.JaxmppException: Cannot create socket. means that DNS-SD/mDNS records for IoT hub are not published yet (ie. hub is inaccessible or stopped)
  2. java.net.ConnectException: Connection refused means that there are DNS-SD/mDNS records but Tigase IoT Hub is not accepting connections yet
  3. tigase.jaxmpp.core.client.exceptions.JaxmppException: Connector is not in disconnected state means that reconnection was scheduled but somehow another reconnection is in progress.

So error no. 1 is very common and it will repeat until connection to IoT hub is established.
Error no. 2 may happen a few times but it should stop appearing after connection to the hub will be established.
Error no. 3 should not happen at all, but in rare cases, it may appear once or twice during Tigase IoT Hub startup process if IoT Framework will be trying to connect.

Now, if it is connected successfully it should stop printing those errors.

If on the new build you will see policy_violation it means that your account (account of IoT Framework) is disabled at the IoT hub and you need to use the IoT client to allow this account to connect to the IoT hub. (related to feature IoT Hub account/device management).

#5 Avatar?id=6023&size=24x24 Updated by Artur Hefczyc TigaseTeam about 1 year ago

  • Status changed from In QA to Feedback
  • Assignee changed from Daniel Wisnewski to Andrzej Wójcik

Users who will try to use our software will experience all these errors, including policy_violation. If we do not provide meaningful error messages, right in the log file, we will be either overfilled with support requests or people will give up on our software. So, it is critical to modify these error messages to provide more clear explanation of what is going on and, direct users to a website (or better yet, specific page) where he can learn on how to resolve the issue.

#6 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam about 1 year ago

%kobit Those error messages were left there after testing Jaxmpp Bot Framework and IoT Framework. I'm not going to remove them, instead, I'll change their log level and provide better-suited error messages which will be visible for regular users.

#7 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam about 1 year ago

  • Status changed from Feedback to In QA
  • Assignee changed from Andrzej Wójcik to Daniel Wisnewski

%kobit I've modified Jaxmpp Bot Framework and Tigase IoT Framework to make errors presented to the user more user-friendly and give some suggestions on how to fix them.

Daniel, please review if after those changes it is ok or if you would like to change those error messages in any way.

#8 Updated by Daniel Wisnewski IoT 1 Cloud about 1 year ago

  • Status changed from In QA to Feedback
  • Assignee changed from Daniel Wisnewski to Artur Hefczyc
  • Priority changed from High to Normal

Bug is no longer present on local or remote devices. I like the messages printed under INFO, far more information is provided in plain English.

2018-03-30 15:17:28.143 [pool-2-thread-7]  ConnectionErrorReporter.handleDisconnected()  INFO: Disconnected from Tigase IoT Hub as fafcf2cd-a37c-45be-902c-c387ee459b1f
2018-03-30 15:17:36.050 [pool-2-thread-11]  ConnectionErrorReporter.handleConnected()  INFO: Connected to Tigase IoT Hub as fafcf2cd-a37c-45be-902c-c387ee459b1f
2018-03-30 15:17:36.203 [pool-2-thread-16]  ConnectionErrorReporter.handleAccountStateChanged()  WARNING: Account for this devices fafcf2cd-a37c-45be-902c-c387ee459b1f is awaiting acceptance. If you want to enable it please use your IoT client and enabled it in 'Manage devices'. Until then it will not be possible to use this device.

Connections can now be established, and ticket can be closed. Before however, Artur I have left some printed log results above let Andrzej know if you want changes to the printed information.

#9 Avatar?id=6023&size=24x24 Updated by Artur Hefczyc TigaseTeam about 1 year ago

  • Status changed from Feedback to Closed

Also available in: Atom PDF