Re: Unable to read the properties from JAVA SDK in...

bargo · ‎Apr 19, 2017

Hi,

I am using Java SDK to push data into thingworx. I created a thing in Core with the name same as that of thing in JAVA SDK. When I start my SDK , the connection between Core and SDK is established and I see that isConnected property of remote thing is set to true. After few seconds the connection drops/closed and I am unable to do manage bindings for remote thing which is required to capture values from SDK. Below are the logs. Can anyone help me to whats wrong I have done here.

NOTE : I am using trial version of thingworx foundation server that is on remote machine.

15:55:39.431 [main] INFO c.s.v.s.MasterClientConfigurator - Reading from file

15:55:39.435 [main] INFO c.s.v.s.MasterClientConfigurator - Thingworx webservice url isws://13.113.122.50:80/Thingworx/WS

15:55:39.514 [main] INFO c.t.c.c.p.ClientMessageProcessor - Created new ClientMessageProcessor [minPoolSize: 4, maxPoolSize: 10, maxThreadLife: 10000, maxQueueSize: 1000]

URL: ws://13.113.122.50:80/Thingworx/WS

AppKey: 261c61e2-10c7-4635-97d4-6d367771bd1d

15:55:39.576 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework

15:55:39.579 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 4

15:55:39.588 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available

15:55:39.588 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available

15:55:39.589 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available

15:55:39.589 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: true

15:55:39.589 [main] DEBUG i.n.util.internal.PlatformDependent - Platform: Windows

15:55:39.589 [main] DEBUG i.n.util.internal.PlatformDependent - Java version: 8

15:55:39.590 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noUnsafe: false

15:55:39.590 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available

15:55:39.590 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noJavassist: false

15:55:39.591 [main] DEBUG i.n.util.internal.PlatformDependent - Javassist: unavailable

15:55:39.591 [main] DEBUG i.n.util.internal.PlatformDependent - You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes. Please check the configuration for better performance.

15:55:39.591 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: C:\Users\EE209924\AppData\Local\Temp (java.io.tmpdir)

15:55:39.592 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)

15:55:39.592 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false

15:55:39.614 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false

15:55:39.615 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512

15:55:39.902 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 2

15:55:39.903 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 2

15:55:39.903 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192

15:55:39.903 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11

15:55:39.903 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216

15:55:39.904 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512

15:55:39.904 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256

15:55:39.904 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64

15:55:39.904 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768

15:55:39.904 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192

15:55:39.912 [main] DEBUG c.t.c.c.e.m.CommunicationEndpointMonitorTask - Initializing CommunicationEndpoint Connection Monitor...

15:55:39.913 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.m.CommunicationEndpointMonitorTask - CommunicationEndpoint Monitor - checking for disconnected endpoints

15:55:39.913 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointMonitorTask - Endpoint not connected [name: EP_0, id: 0]. Attempting [re]connect...

15:55:39.913 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.ClientCommunicationEndpoint - Clearing endpoint authentication data [id: 0]

15:55:39.913 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Needed to refill connections on client endpoint [id: 0] : [active: 0, max: 1]

15:55:39.938 [Client-EndpointMonitor-1] DEBUG i.n.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0xce958c169b1305ea (took 6 ms)

15:55:39.956 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled

15:55:39.957 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536

15:55:39.995 [NettyClient-NIO-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetectionLevel: simple

15:55:40.141 [NettyClient-NIO-1] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHandler - WebSocket Channel is connected [is open: true]

15:55:40.146 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocketClientHandshaker13 - WebSocket version 13 client handshake key: 6Ky2JOcK4dsL0SGBOhTbBQ==, expected response: 02QmLnbUro0DCSQ9dI2vIJoCu4E=

15:55:40.154 [NettyClient-NIO-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacity.default: 262144

15:55:40.335 [NettyClient-NIO-1] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHandler - [ClientHandler: 458191046] Client websocket handshake is complete

15:55:40.338 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Preparing new Connection Authentication Request: DispatchingClientEndpoint [id: 0, isConnected: false, open connections: 0, max connections: 1]

15:55:40.339 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending connection authentication message, waiting for response [message: AuthRequestMessage [requestId: 1, endpointId: -1, sessionId: -1, method: AUTHREQUEST]]

15:55:40.345 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=60

15:55:40.476 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:55:40.476 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=17

15:55:40.496 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 157] ResponseMessage [requestId: 1, endpointId: 30, sessionId: 30, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:55:40.497 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Authentication Request was SUCCESSFUL [tworx session id: 30, connection group id: 30]

15:55:40.498 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - [Endpoint id: 0, connection id: 0-0] added Connection

15:55:40.500 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Successfully reconnected client endpoint [id: 0] : [active: 1, max: 1]

15:55:40.501 [Client-EndpointMonitor-1] INFO c.t.c.client.ConnectedThingClient - Communications Endpoint Opened

15:55:40.506 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: BindRequestMessage [requestId: 2, method: BINDREQUEST, names: [EP_0, RemoteRollingStock, EP_0]]]

15:55:40.508 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=63

15:55:40.644 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:55:40.644 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=17

15:55:40.914 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 408] ResponseMessage [requestId: 2, endpointId: -1, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:55:40.914 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointMonitorTask - Endpoint reconnected [name: EP_0, id: 0]

15:55:41.640 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:55:41.640 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=45

15:55:41.642 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:55:41.644 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=45

15:55:41.651 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - API REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 89, endpointId: -1, sessionId: -1, method: POST, entityName: EP_0, characteristic: Unknown, target: ]

15:55:41.655 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:55:41.657 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=59

15:55:41.662 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - API REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 87, endpointId: -1, sessionId: -1, method: POST, entityName: EP_0, characteristic: Unknown, target: ]

15:55:41.663 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - API REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 88, endpointId: -1, sessionId: -1, method: POST, entityName: RemoteRollingStock, characteristic: Unknown, target: ]

15:55:41.657 [ClientProcessor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: APIRequestMessage [requestId: 3, endpointId: 0, sessionId: 30, method: POST, entityName: EP_0, characteristic: Services, target: GetPropertySubscriptions]]

15:55:41.667 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=49

15:55:41.667 [ClientProcessor-2] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: APIRequestMessage [requestId: 4, endpointId: 0, sessionId: 30, method: POST, entityName: EP_0, characteristic: Services, target: GetPropertySubscriptions]]

15:55:41.670 [ClientProcessor-3] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: APIRequestMessage [requestId: 5, endpointId: 0, sessionId: 30, method: POST, entityName: RemoteRollingStock, characteristic: Services, target: GetPropertySubscriptions

]]

15:55:41.671 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=49

15:55:41.677 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=63

15:55:41.802 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:55:41.803 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=223

15:56:00.905 [NettyClient-NIO-1] INFO c.t.c.c.c.n.NettyClientConnection - [websocket id: 0-0] Closing underlying websocket channel

15:56:00.906 [NettyClient-NIO-1] INFO c.t.c.c.c.n.NettyClientConnection - [websocket id: 0-0] Unregistering NettyClientConnection from ClientEndpoint

15:56:00.906 [NettyClient-NIO-1] DEBUG c.t.c.c.e.CommunicationEndpoint - [Endpoint id: 0, connection id: 0-0] removed Connection

15:56:00.908 [NettyClient-NIO-1] INFO c.t.c.c.e.CommunicationEndpoint - All Connections are closed [endpoint id: 0]

15:56:00.909 [NettyClient-NIO-1] INFO c.t.c.client.ConnectedThingClient - Communications Endpoint Closed

15:56:40.917 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.m.CommunicationEndpointMonitorTask - CommunicationEndpoint Monitor - checking for disconnected endpoints

15:56:40.917 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointMonitorTask - Endpoint not connected [name: EP_0, id: 0]. Attempting [re]connect...

15:56:40.917 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.ClientCommunicationEndpoint - Clearing endpoint authentication data [id: 0]

15:56:40.917 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Needed to refill connections on client endpoint [id: 0] : [active: 0, max: 1]

15:56:41.052 [NettyClient-NIO-2] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHandler - WebSocket Channel is connected [is open: true]

15:56:41.053 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocketClientHandshaker13 - WebSocket version 13 client handshake key: c9E+/s4LcAcBfMLm0DzBiQ==, expected response: RVLPbnBmQzh9YYblHNZGxjyDwzQ=

15:56:41.203 [NettyClient-NIO-2] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHandler - [ClientHandler: 1245348364] Client websocket handshake is complete

15:56:41.204 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Preparing new Connection Authentication Request: DispatchingClientEndpoint [id: 0, isConnected: false, open connections: 0, max connections: 1]

15:56:41.204 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending connection authentication message, waiting for response [message: AuthRequestMessage [requestId: 6, endpointId: -1, sessionId: -1, method: AUTHREQUEST]]

15:56:41.205 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=60

15:56:41.336 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:56:41.336 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=17

15:56:41.337 [NettyClient-NIO-2] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 133] ResponseMessage [requestId: 6, endpointId: 31, sessionId: 31, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:56:41.338 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Authentication Request was SUCCESSFUL [tworx session id: 31, connection group id: 31]

15:56:41.339 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - [Endpoint id: 0, connection id: 0-0] added Connection

15:56:41.339 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Successfully reconnected client endpoint [id: 0] : [active: 1, max: 1]

15:56:41.341 [Client-EndpointMonitor-1] INFO c.t.c.client.ConnectedThingClient - Communications Endpoint Opened

15:56:41.343 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: BindRequestMessage [requestId: 7, method: BINDREQUEST, names: [EP_0, RemoteRollingStock, EP_0]]]

15:56:41.345 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=63

15:56:41.480 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:56:41.480 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=17

15:56:41.482 [NettyClient-NIO-2] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 139] ResponseMessage [requestId: 7, endpointId: -1, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:56:41.482 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointMonitorTask - Endpoint reconnected [name: EP_0, id: 0]

15:56:41.669 [ClientProcessor-1] WARN c.t.c.client.things.VirtualThing - Unable to get property subscriptions. Timed out APIRequestMessage [requestId: 3, endpointId: 0, sessionId: 30, method: POST, entityName: EP_0, characteristic: Services, target: GetPropertySubscriptions]

15:56:41.669 [ClientProcessor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: APIRequestMessage [requestId: 8, endpointId: 0, sessionId: 31, method: POST, entityName: EP_0, characteristic: Services, target: GetEventSubscriptions]]

15:56:41.671 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=46

15:56:41.673 [ClientProcessor-2] WARN c.t.c.client.things.VirtualThing - Unable to get property subscriptions. Timed out APIRequestMessage [requestId: 4, endpointId: 0, sessionId: 30, method: POST, entityName: EP_0, characteristic: Services, target: GetPropertySubscriptions]

15:56:41.674 [ClientProcessor-2] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: APIRequestMessage [requestId: 9, endpointId: 0, sessionId: 31, method: POST, entityName: EP_0, characteristic: Services, target: GetEventSubscriptions]]

15:56:41.676 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=46

15:56:41.678 [ClientProcessor-3] WARN c.t.c.client.things.VirtualThing - Unable to get property subscriptions. Timed out APIRequestMessage [requestId: 5, endpointId: 0, sessionId: 30, method: POST, entityName: RemoteRollingStock, characteristic: Services, target: GetPropertySubscriptions]

15:56:41.679 [ClientProcessor-3] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending synchronous message, waiting for response [message: APIRequestMessage [requestId: 10, endpointId: 0, sessionId: 31, method: POST, entityName: RemoteRollingStock, characteristic: Services, target: GetEventSubscriptions]]

15:56:41.681 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=60

15:56:41.797 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:56:41.798 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=63

15:56:41.800 [NettyClient-NIO-2] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 131] ResponseMessage [requestId: 8, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:56:41.807 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=17

15:56:41.809 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:56:41.812 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=63

15:56:41.813 [NettyClient-NIO-2] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 138] ResponseMessage [requestId: 9, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:56:41.814 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=17

15:56:41.819 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=2

15:56:41.821 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame length=63

15:56:41.822 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=8

15:56:41.823 [NettyClient-NIO-2] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RESPONSE received [endpoint id: 0, duration: 144] ResponseMessage [requestId: 10, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]

15:56:41.827 [NettyClient-NIO-2] INFO c.t.c.c.c.n.NettyClientConnection - [websocket id: 0-0] Closing underlying websocket channel

15:56:41.829 [NettyClient-NIO-2] INFO c.t.c.c.c.n.NettyClientConnection - [websocket id: 0-0] Unregistering NettyClientConnection from ClientEndpoint

15:56:41.830 [NettyClient-NIO-2] DEBUG c.t.c.c.e.CommunicationEndpoint - [Endpoint id: 0, connection id: 0-0] removed Connection

15:56:41.834 [NettyClient-NIO-2] INFO c.t.c.c.e.CommunicationEndpoint - All Connections are closed [endpoint id: 0]

15:56:41.835 [NettyClient-NIO-2] INFO c.t.c.client.ConnectedThingClient - Communications Endpoint Closed

15:56:41.837 [NettyClient-NIO-2] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=2 length=17

supandey · ‎Apr 19, 2017

Bob, is the clientConfiguration configured to attempt connections every n number of seconds/minutes? Could share your code or pseudo code how the property is being updated?

supandey · ‎Apr 19, 2017

If it helps, here's the sample code to initiate the connection and keep attempting it every few seconds i used in one of my project :

public class ClinetConfigurator {
  private static final Logger LOG = LoggerFactory.getLogger(ClientConfigurator.class);
  public static Random random = new Random();
  public static void main(String[] args) {
  try {
  // Setting the server URL and the appkey to enable this client to
  // connect to the ThingWorx platform
  //Applicaton server on TWX70
  String serverURL = "<serverAddress>/WS";
  String appKey = "<appKey>";
  // configure client
  ClientConfigurator config = new ClientConfigurator();
  config.setUri(serverURL);
  config.setAppKey(appKey);
  config.getSecurityClaims().addClaim(appKey, appKey);
  // connected to client
  ConnectedThingClient client = new ConnectedThingClient(config, null);
  // start the client
  client.start(); // Async - doesn't always mean that the client has
  // started immediately when the method is called
  //create and bind the virtual thing to the platform
  TractorVirtualThing tractorThing = new TractorVirtualThing("GreenCo.Tractor1", "A virtual thing", client);
  LOG.debug("Binding to " + serverURL + "to register thing" + tractorThing.getName());
  // binding happens just once with 1 connection
  client.bindThing(tractorThing);
  LOG.debug("Connecting to " + serverURL + "using key" + appKey);
  //
  while (true) {
  if(client.getEndpoint().isConnected()) {
  tractorThing.processScanRequest();
  Thread.sleep(random.nextInt(300));
  }
  Thread.sleep(6000); // cycle every miliseconds
  }
  } catch (Exception e) {
  // Catching the exception in case the connection or the binding fails
  LOG.error("An error occured", e);
  e.printStackTrace();
  }
  }
}

bargo · ‎Apr 19, 2017

Hi Sushant,

Thanks for sharing the above code. But this did not helped me. I am still facing the same issue.

bargo · ‎Apr 19, 2017

Hi Sushant,

There was one mistake in my code. I was not setting uri of actual thingworx core rather it was by default pointing to local. I made the changes as below

this.config = new ClientConfigurator();

this.config.setUri("ws://13.113.122.50:80/Thingworx/WS");

But after this I am getting another error. Please have a look at trace below.

18:57:21.478 [main] DEBUG c.t.c.c.e.m.CommunicationEndpointMonitorTask - Initializing CommunicationEndpoint Connection Monitor...

18:57:21.479 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.m.CommunicationEndpointMonitorTask - CommunicationEndpoint Monitor - checking for disconnected endpoints

18:57:21.479 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointMonitorTask - Endpoint not connected [name: EP_0, id: 0]. Attempting [re]connect...

18:57:21.479 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.ClientCommunicationEndpoint - Clearing endpoint authentication data [id: 0]

18:57:21.479 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpoint - Needed to refill connections on client endpoint [id: 0] : [active: 0, max: 1]

18:57:21.505 [Client-EndpointMonitor-1] DEBUG i.n.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0xa0d91cd57cf054e5 (took 2 ms)

18:57:21.535 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled

18:57:21.535 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536

18:57:21.598 [NettyClient-NIO-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetectionLevel: simple

18:57:31.553 [Client-EndpointMonitor-1] INFO c.t.c.c.c.n.NettyClientConnectionFactory - forcing underlying tcp channel closed [is open: true, is active: false]

18:57:31.554 [Client-EndpointMonitor-1] ERROR c.t.c.c.e.ClientCommunicationEndpoint - Refilling connections on [endpoint 0, uri: ws://13.113.122.50:80/Thingworx/WS] failed : timeout waiting for websocket handshake to complete

18:57:31.554 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointMonitorTask - Endpoint reconnection was unsuccessful [name: EP_0, id: 0]

Any idea?

Thanks

supandey · ‎Apr 19, 2017

Is the server already reachable for you? because I can't get to the authentication page for your server's IP. So you might want to hold on till the IP is reachable again and secondly I can't see that your server instance is defining port 80 so you test removing that once the server is responding again.

ankigupta · ‎Apr 19, 2017

bob argo,

Just to add if it's secured connection; in uri it would be wss instead of ws.

bargo · ‎Apr 19, 2017

Hi Sushant,

Below is the code for client and Virtual Thing

Client.

public class RollingStockClient extends ConnectedThingClient {

private static final Logger LOG = LoggerFactory.getLogger(RollingStockClient.class);

public RollingStockClient(ClientConfigurator config) throws Exception {

super(config);

// TODO Auto-generated constructor stub

}

public static void main(String[] args)

throws Exception

{

MasterClientConfigurator masterconfig = new MasterClientConfigurator(args);

int scanRate = 30000;

RollingStockClient client = new RollingStockClient(masterconfig.config);

RollingStockThing rollingStockThing = new RollingStockThing("RemoteRollingStock", "RollingStock", client);

client.bindThing(rollingStockThing);

try

{

System.out.println(masterconfig);

client.start();

}

catch (Exception eStart)

{

System.out.println("Initial Start Failed : " + eStart.getMessage());

}

while (!client.isShutdown())

{

if (client.getEndpoint().isConnected()) {

for (VirtualThing thing : client.getThings().values()) {

try

{

thing.processScanRequest();

}

catch (Exception eProcessing)

{

System.out.println("Error Processing Scan Request for [" + thing.getName() + "] : " + eProcessing.getMessage());

}

Thread.sleep(scanRate);

}

Vitual Thing

@ThingworxPropertyDefinitions(properties={@com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_TempSetPoint1", description="TempSetPoint of vending machine 1", baseType="NUMBER", aspects={"dataChangeType:NEVER", "dataChangeThreshold:0", "cacheTime:-1", "isPersistent:true", "isReadOnly:false", "pushType:NEVER", "defaultValue:35.34"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_TempSetPoint2", description="TempSetPoint of vending machine 2", baseType="NUMBER", aspects={"dataChangeType:NEVER", "dataChangeThreshold:0", "cacheTime:-1", "isPersistent:true", "isReadOnly:false", "pushType:NEVER", "defaultValue:35.78"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_HumSetPoint1", description="HumSetPoint of vending machine 1", baseType="NUMBER", aspects={"dataChangeType:NEVER", "dataChangeThreshold:0", "cacheTime:-1", "isPersistent:true", "isReadOnly:false", "pushType:NEVER", "defaultValue:70.23"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_HumSetPoint2", description="HumSetPoint of vending machine 2", baseType="NUMBER", aspects={"dataChangeType:NEVER", "dataChangeThreshold:0", "cacheTime:-1", "isPersistent:true", "isReadOnly:false", "pushType:NEVER", "defaultValue:70.93"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_Equipment1Temp", description="Current temperature of vending machine 1", baseType="NUMBER", aspects={"dataChangeType:ALWAYS", "dataChangeThreshold:0", "cacheTime:0", "isPersistent:FALSE", "isReadOnly:TRUE", "pushType:VALUE", "defaultValue:0"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_Equipment2Temp", description="Current temperature of vending machine 2", baseType="NUMBER", aspects={"dataChangeType:ALWAYS", "dataChangeThreshold:0", "cacheTime:0", "isPersistent:FALSE", "isReadOnly:TRUE", "pushType:VALUE", "defaultValue:0"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_Equipment1Hum", description="Current humidity of vending machine 1", baseType="NUMBER", aspects={"dataChangeType:ALWAYS", "dataChangeThreshold:0", "cacheTime:0", "isPersistent:FALSE", "isReadOnly:TRUE", "pushType:VALUE", "defaultValue:0"}), @com.thingworx.metadata.annotations.ThingworxPropertyDefinition(name="Prop_Equipment2Hum", description="Current humidity of vending machine 2", baseType="NUMBER", aspects={"dataChangeType:ALWAYS", "dataChangeThreshold:0", "cacheTime:0", "isPersistent:FALSE", "isReadOnly:TRUE", "pushType:VALUE", "defaultValue:0"})})

public class RollingStockThing extends VirtualThing {

/**

*

*/

private static final long serialVersionUID = -3419672881497640537L;

Random randomGenerator;

boolean ranScanOnce = false;

public RollingStockThing(String name, String description, ConnectedThingClient client)

{

super(name, description, client);

initializeFromAnnotations();

this.randomGenerator = new Random();

try

{

setProperty("Prop_TempSetPoint1", getProperty("Prop_TempSetPoint1").getPropertyDefinition().getDefaultValue().getValue());

setProperty("Prop_TempSetPoint2", getProperty("Prop_TempSetPoint2").getPropertyDefinition().getDefaultValue().getValue());

setProperty("Prop_HumSetPoint1", getProperty("Prop_HumSetPoint1").getPropertyDefinition().getDefaultValue().getValue());

setProperty("Prop_HumSetPoint2", getProperty("Prop_HumSetPoint2").getPropertyDefinition().getDefaultValue().getValue());

}

catch (Exception localException) {}

}

public void processScanRequest()

throws Exception

{

super.processScanRequest();

scanDevice();

}

public void scanDevice()

throws Exception

{

setProperty("Prop_Equipment1Temp", Double.valueOf(getRandomOscillation(((Double)getProperty("Prop_Equipment1Temp").getValue().getValue()).doubleValue(), ((Double)getProperty("Prop_TempSetPoint1").getValue().getValue()).doubleValue())));

setProperty("Prop_Equipment2Temp", Double.valueOf(getRandomOscillation(((Double)getProperty("Prop_Equipment2Temp").getValue().getValue()).doubleValue(), ((Double)getProperty("Prop_TempSetPoint2").getValue().getValue()).doubleValue())));

setProperty("Prop_Equipment1Hum", Double.valueOf(getRandomOscillation(((Double)getProperty("Prop_Equipment1Hum").getValue().getValue()).doubleValue(), ((Double)getProperty("Prop_HumSetPoint1").getValue().getValue()).doubleValue())));

setProperty("Prop_Equipment2Hum", Double.valueOf(getRandomOscillation(((Double)getProperty("Prop_Equipment2Hum").getValue().getValue()).doubleValue(), ((Double)getProperty("Prop_HumSetPoint2").getValue().getValue()).doubleValue())));

this.ranScanOnce = true;

Thread.sleep(1500);

updateSubscribedProperties(10000);

}

private double getRandomOscillation(double currentValue, double setPoint)

{

if (!this.ranScanOnce) {

currentValue = setPoint;

}

double offset = 0.0D;

if ((Math.abs(currentValue - setPoint) > 3.0D) && (currentValue < setPoint)) {

offset = this.randomGenerator.nextDouble() * 500.0D / 100.0D;

} else if ((Math.abs(currentValue - setPoint) > 3.0D) && (currentValue > setPoint)) {

offset = -(this.randomGenerator.nextDouble() * 500.0D / 100.0D);

} else if (Math.abs(currentValue - setPoint) <= 3.0D)

{

if (currentValue <= setPoint) {

offset = this.randomGenerator.nextDouble() * 200.0D / 100.0D;

} else if (currentValue > setPoint) {

offset = -(this.randomGenerator.nextDouble() * 200.0D / 100.0D);

}

else {

offset = this.randomGenerator.nextDouble();

}

return currentValue + offset;

}

Unable to read the properties from JAVA SDK into Core