Re: Error Processing Scan Request for [RemoteTruck...

cnguyen11 · ‎May 24, 2017

Dear people,

I have a similar issue with the wsjavatruckstart.bat.

The remote thing is connected but the zero value is always generated for Speed and Location.

Here is the message I got from batch logs :

Error Processing Scan Request for [RemoteTruck] : For input string: "54,46"
Error Processing Scan Request for [RemoteTruck] : For input string: "68,49"

My TrainingConfig.json :

{
    "ServerLocation": "127.0.0.1",
    "Port": 80,
    "AppKey": "1c6d618d-61a7-4b29-a565-9c8ac01d6208",
    "Security": false,
    "RemoteRepo": "/ThingworxRemoteRepository"
}

Thanks for your assist.

Chan

Message was edited by: Sushant Pandey : Branched from https://community.thingworx.com/message/58908#58908 , user referenced to the issue seen there

supandey · ‎May 24, 2017

Chan could you please share the full EMS log also you'll need to be careful since you are reading from Server cache so if the EDGE properties are not set correctly server may never get the values updated. And as it seem with the scan request it's not able to push the data.

Therefore please check for the detailed log from EMS and the ThingWorx's application log. Can you also share them here?

cnguyen11 · ‎May 24, 2017

Hi Sushant,

Here are EMS logs :

C:\MicroServer_Java>java -jar TruckSimulator.jar
16:44:24.739 [main] INFO c.t.c.c.p.ClientMessageProcessor - Created new ClientM
essageProcessor [minPoolSize: 4, maxPoolSize: 10, maxThreadLife: 10000, maxQueue
Size: 1000]
Starting the stuff
URL: ws://127.0.0.1:80/Thingworx/WS
AppKey: 1c6d618d-61a7-4b29-a565-9c8ac01d6208
16:44:24.839 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the d
efault logging framework
16:44:24.844 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoop
Threads: 8
16:44:24.863 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.nio.ch.Dire
ctBuffer.cleaner(): available
16:44:24.864 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer
.address: available
16:44:24.866 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe
.theUnsafe: available
16:44:24.867 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe
.copyMemory: available
16:44:24.869 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.u
naligned: true
16:44:24.870 [main] DEBUG i.n.util.internal.PlatformDependent - Platform: Window
s
16:44:24.871 [main] DEBUG i.n.util.internal.PlatformDependent - Java version: 8
16:44:24.871 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noUns
afe: false
16:44:24.872 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe:
available
16:44:24.873 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noJav
assist: false
16:44:24.875 [main] DEBUG i.n.util.internal.PlatformDependent - Javassist: unava
ilable
16:44:24.876 [main] DEBUG i.n.util.internal.PlatformDependent - You don't have J
avassist in your class path or you don't have enough permission to load dynamica
lly generated classes. Please check the configuration for better performance.
16:44:24.877 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdi
r: D:\Users\Chan_NGUYEN\AppData\Local\Temp (java.io.tmpdir)
16:44:24.878 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMo
de: 64 (sun.arch.data.model)
16:44:24.879 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPre
ferDirect: false
16:44:24.907 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySe
tOptimization: false
16:44:24.907 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selecto
rAutoRebuildThreshold: 512
16:44:25.013 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.numHeapArenas: 4
16:44:25.014 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.numDirectArenas: 4
16:44:25.014 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.pageSize: 8192
16:44:25.014 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.maxOrder: 11
16:44:25.015 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.chunkSize: 16777216
16:44:25.015 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.tinyCacheSize: 512
16:44:25.015 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.smallCacheSize: 256
16:44:25.016 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.normalCacheSize: 64
16:44:25.016 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.maxCachedBufferCapacity: 32768
16:44:25.016 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.cacheTrimInterval: 8192
16:44:25.017 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocat
or.cacheCleanupInterval: 5000 ms
16:44:25.024 [main] DEBUG c.t.c.c.e.m.CommunicationEndpointMonitorTask - Initial
izing CommunicationEndpoint Connection Monitor...
16:44:25.026 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.m.CommunicationEndpointM
onitorTask - CommunicationEndpoint Monitor - checking for disconnected endpoints
16:44:25.026 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointM
onitorTask - Endpoint not connected [name: EP_0, id: 0]. Attempting [re]connect.
..
16:44:25.027 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.ClientCommunicationEndpo
int - Clearing endpoint authentication data [id: 0]
16:44:25.028 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpo
int - Needed to refill connections on client endpoint [id: 0] : [active: 0, max:
1]
16:44:25.058 [Client-EndpointMonitor-1] DEBUG i.n.util.internal.ThreadLocalRando
m - -Dio.netty.initialSeedUniquifier: 0xab1d94db4296d80b
16:44:25.065 [Client-EndpointMonitor-1] DEBUG i.n.channel.ChannelOutboundBuffer
- -Dio.netty.threadLocalDirectBufferSize: 65536
16:44:25.066 [Client-EndpointMonitor-1] DEBUG io.netty.util.Recycler - -Dio.nett
y.recycler.maxCapacity.default: 262144
16:44:25.085 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio
.netty.allocator.type: unpooled
16:44:25.126 [NettyClient-NIO-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio
.netty.leakDetectionLevel: simple
16:44:25.141 [NettyClient-NIO-1] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHand
ler - WebSocket Channel is connected [is open: true]
16:44:25.144 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocketClientHandshaker13 -
WebSocket version 13 client handshake key: 6RtDR1sBfmt65/Te2MgjBQ==, expected r
esponse: UW2eQUJv3AcVbuV0oZz51jCVQFg=
16:44:25.183 [NettyClient-NIO-1] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHand
ler - [ClientHandler: 1695560218] Client websocket handshake is complete
16:44:25.186 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpo
int - Preparing new Connection Authentication Request: DispatchingClientEndpoint
[id: 0, isConnected: false, open connections: 0, max connections: 1]
16:44:25.188 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint -
Sending connection authentication message, waiting for response [message: AuthRe
questMessage [requestId: 1, endpointId: -1, sessionId: -1, method: AUTHREQUEST]]
16:44:25.193 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=60
16:44:25.196 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:25.196 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=17
16:44:25.210 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 22] ResponseMessage [requestId: 1, end
pointId: 27, sessionId: 27, code: STATUS_SUCCESS, multipart: false, packet #: 0,
total packets: 0]
16:44:25.210 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpo
int - Authentication Request was SUCCESSFUL [tworx session id: 27, connection gr
oup id: 27]
16:44:25.211 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.CommunicationEndpoint -
[Endpoint id: 0, connection id: 0-0] added Connection
16:44:25.212 [Client-EndpointMonitor-1] INFO c.t.c.c.e.ClientCommunicationEndpo
int - Successfully reconnected client endpoint [id: 0] : [active: 1, max: 1]
16:44:25.212 [Client-EndpointMonitor-1] INFO c.t.c.client.ConnectedThingClient
- Communications Endpoint Opened
16:44:25.214 [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, RemoteTruck, EP_0]]]
16:44:25.216 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=56
16:44:25.248 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:25.248 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=17
16:44:25.249 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 35] ResponseMessage [requestId: 2, end
pointId: -1, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0,
total packets: 0]
16:44:25.249 [Client-EndpointMonitor-1] INFO c.t.c.c.e.m.CommunicationEndpointM
onitorTask - Endpoint reconnected [name: EP_0, id: 0]
16:44:26.227 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.228 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=45
16:44:26.259 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.260 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=52
16:44:26.272 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - API
REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 226, endpointId
: -1, sessionId: -1, method: POST, entityName: EP_0, characteristic: Unknown, ta
rget: ]
16:44:26.278 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - API
REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 225, endpointId
: -1, sessionId: -1, method: POST, entityName: RemoteTruck, characteristic: Unkn
own, target: ]
16:44:26.279 [ClientProcessor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending
synchronous message, waiting for response [message: APIRequestMessage [requestI
d: 3, endpointId: 0, sessionId: 27, method: POST, entityName: EP_0, characterist
ic: Services, target: GetPropertySubscriptions]]
16:44:26.281 [ClientProcessor-2] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending
synchronous message, waiting for response [message: APIRequestMessage [requestI
d: 4, endpointId: 0, sessionId: 27, method: POST, entityName: RemoteTruck, chara
cteristic: Services, target: GetPropertySubscriptions]]
16:44:26.282 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=49
16:44:26.284 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=56
16:44:26.288 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.289 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=223
16:44:26.290 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 11] ResponseMessage [requestId: 3, end
pointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0,
total packets: 0]
16:44:26.292 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.292 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=278
16:44:26.293 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 12] ResponseMessage [requestId: 4, end
pointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0,
total packets: 0]
16:44:26.295 [ClientProcessor-1] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending
synchronous message, waiting for response [message: APIRequestMessage [requestI
d: 5, endpointId: 0, sessionId: 27, method: POST, entityName: EP_0, characterist
ic: Services, target: GetEventSubscriptions]]
16:44:26.297 [ClientProcessor-2] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending
synchronous message, waiting for response [message: APIRequestMessage [requestI
d: 6, endpointId: 0, sessionId: 27, method: POST, entityName: RemoteTruck, chara
cteristic: Services, target: GetEventSubscriptions]]
16:44:26.298 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=46
16:44:26.300 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=53
16:44:26.303 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.304 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=63
16:44:26.305 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 10] ResponseMessage [requestId: 5, end
pointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0,
total packets: 0]
16:44:26.307 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=17
16:44:26.311 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.311 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=45
16:44:26.312 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - API
REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 227, endpointId
: -1, sessionId: -1, method: POST, entityName: EP_0, characteristic: Unknown, ta
rget: ]
16:44:26.313 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.313 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=63
16:44:26.313 [ClientProcessor-3] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending
synchronous message, waiting for response [message: APIRequestMessage [requestI
d: 7, endpointId: 0, sessionId: 27, method: POST, entityName: EP_0, characterist
ic: Services, target: GetPropertySubscriptions]]
16:44:26.314 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 17] ResponseMessage [requestId: 6, end
pointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0,
total packets: 0]
16:44:26.315 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=17
16:44:26.316 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=49
16:44:26.317 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.317 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=223
16:44:26.318 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 5] ResponseMessage [requestId: 7, endp
ointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, t
otal packets: 0]
16:44:26.320 [ClientProcessor-3] DEBUG c.t.c.c.e.CommunicationEndpoint - Sending
synchronous message, waiting for response [message: APIRequestMessage [requestI
d: 8, endpointId: 0, sessionId: 27, method: POST, entityName: EP_0, characterist
ic: Services, target: GetEventSubscriptions]]
16:44:26.321 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=46
16:44:26.323 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=2
16:44:26.323 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=63
16:44:26.324 [NettyClient-NIO-1] DEBUG c.t.c.c.e.DispatchingClientEndpoint - RES
PONSE received [endpoint id: 0, duration: 4] ResponseMessage [requestId: 8, endp
ointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, t
otal packets: 0]
16:44:26.325 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=2 length=17
Error Processing Scan Request for [RemoteTruck] : For input string: "56,68"
16:45:10.478 [NettyClient-NIO-1] DEBUG c.t.c.c.c.n.ThingworxClientConnectionHand
ler - [ClientHandler: 1695560218] Client has been idle, sending websocket ping..
.
16:45:10.480 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameEncoder - Enc
oding WebSocket Frame opCode=9 length=0
16:45:10.483 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame opCode=10
16:45:10.486 [NettyClient-NIO-1] DEBUG i.n.h.c.h.w.WebSocket08FrameDecoder - Dec
oding WebSocket Frame length=0
Error Processing Scan Request for [RemoteTruck] : For input string: "65,7"
16:45:25.763 [Client-EndpointMonitor-1] DEBUG c.t.c.c.e.m.CommunicationEndpointM
onitorTask - CommunicationEndpoint Monitor - checking for disconnected endpoints

cnguyen11 · ‎May 29, 2017

Hi,

Do you have any advice to resolve this issue ?

Many thanks.

Chan

supandey · ‎May 29, 2017

Chan just to confirm is this custom code you have wrote to update the entries or is this also part of the training material? Are you gathering the sensor data with a lua script? Could you please also check by setting the logging to verbose mode on the WS to see if there's any additional information , this will be go into the config.json for your EMS installation

"ws_connection": {

"encryption": "none",

"verbose": true

},

cnguyen11 · ‎May 29, 2017

Hi Sushant,

I have only used the code provided by the training material (available at the following address https://precisionlms.ptc.com/)

There is an exercise called "Binding to a Remote Thing and Logging Its Values Challenge" where you have to launch the "wsjavatruckstart.bat" file to simulate truck speed and location.

However, as you can see in my previous post, it doesn't work as expected.

There is another file called "wsjavavmstart.bat" used to simulate the Vending Machines. This one works like a charm.

FYI, I did't change anything in the system configuration that has not mentionned in the training material.

Thank you for the assist.

Chan