topic Re: Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false in ThingWorx Developers

Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false

Gowresh_R — Fri, 24 Aug 2018 06:37:21 GMT

While I was trying to run

sudo ./luaScriptResource

in Raspberry Pi (Raspbian Jessie), I got the following error log:

[INFO ] 2018-08-24 06:15:35,737 ./luaScriptResource: Using config file: /home/pi/Downloads/microserver/etc/config.lua
[FORCE] 2018-08-24 06:15:35,737 ./luaScriptResource: Starting up ....

[INFO ] 2018-08-24 06:15:35,743 luaScriptResource:main: Encryption is disabled on the RAP connection.
[INFO ] 2018-08-24 06:15:35,743 luaScriptResource:main: FIPS is disabled.
[INFO ] 2018-08-24 06:15:35,746 ./luaScriptResource: New path is (null)
[WARN ] 2018-08-24 06:15:35,749 ScriptResource::initialize: Encryption is disabled on HTTP Server.
[WARN ] 2018-08-24 06:15:35,750 ScriptResource::initialize: Authentication is disabled on the HTTP Server.
[WARN ] 2018-08-24 06:15:35,754 :
[WARN ] 2018-08-24 06:15:35,790 :
[FORCE] 2018-08-24 06:15:35,820 httpServer: starting http server port=8080
[INFO ] 2018-08-24 06:15:35,834 thingworx.shape: Creating a new shape.
[INFO ] 2018-08-24 06:15:35,835 PiThing7: -- Configuration -------------------------------
[INFO ] 2018-08-24 06:15:35,835 PiThing7: scanRate: 501
[INFO ] 2018-08-24 06:15:35,835 PiThing7: scanRateResolution: 500
[INFO ] 2018-08-24 06:15:35,836 PiThing7: taskRate: 501
[INFO ] 2018-08-24 06:15:35,836 PiThing7: keepAliveRate: 60000
[INFO ] 2018-08-24 06:15:35,836 PiThing7: requestTimeout: 15000
[INFO ] 2018-08-24 06:15:35,836 PiThing7: registerRate: 43200000
[INFO ] 2018-08-24 06:15:35,836 PiThing7: register: true
[INFO ] 2018-08-24 06:15:35,837 PiThing7: getPropertySubscriptionOnReconnect: false
[INFO ] 2018-08-24 06:15:35,837 PiThing7: maxConcurrentPropertyUpdates: 100
[INFO ] 2018-08-24 06:15:35,837 PiThing7: defaultPushType: VALUE
[INFO ] 2018-08-24 06:15:35,837 PiThing7: useShapes: true
[INFO ] 2018-08-24 06:15:35,837 PiThing7: identifier: PiThing7
[INFO ] 2018-08-24 06:15:35,838 PiThing7: ------------------------------------------------
[INFO ] 2018-08-24 06:15:35,839 thingworx.template: Adding shape 'shapes.metadata' to template 'thingworx.template'
[INFO ] 2018-08-24 06:15:35,839 thingworx.template: Adding shape 'shapes.propsubscribe' to template 'thingworx.template'
[INFO ] 2018-08-24 06:15:35,840 thingworx.template: Creating new templates.PiTemplate named 'PiThing7'
[INFO ] 2018-08-24 06:15:35,840 PiThing7: -- Initializing properties ---------------------
[INFO ] 2018-08-24 06:15:35,840 PiThing7: Initialized property upToDate [baseType: BOOLEAN, pushType: NEVER, handler: nil, value: true]
[INFO ] 2018-08-24 06:15:35,840 PiThing7: Initialized property cpu_volt [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-08-24 06:15:35,841 PiThing7: Initialized property cpu_temperature [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-08-24 06:15:35,841 PiThing7: Initialized property cpu_freq [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-08-24 06:15:35,841 PiThing7: ------------------------------------------------
[INFO ] 2018-08-24 06:15:35,842 Thingworx: Registering identifier *PiThing7 for thing PiThing7
[INFO ] 2018-08-24 06:15:36,842 PiThing7: Identifier *PiThing7 registered with main Thingworx script for for Thing PiThing7
[INFO ] 2018-08-24 06:15:38,812 PiThing7: -- Starting script --------------------------
[INFO ] 2018-08-24 06:15:38,813 PiThing7: Registering core callback handler
[INFO ] 2018-08-24 06:15:38,813 PiThing7: Starting main loop
[INFO ] 2018-08-24 06:15:38,813 PiThing7: Calling lifecycle start listeners.
[INFO ] 2018-08-24 06:15:38,813 shapes.propsubscribe: Initialized
[INFO ] 2018-08-24 06:15:38,815 thingworx.handler: Creating a new handler.
[INFO ] 2018-08-24 06:15:38,841 PiThing7: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-08-24 06:15:38,850 PiThing7: MicroServer is now available.
[INFO ] 2018-08-24 06:15:38,851 PiThing7: EMS is available: true, online: false

When running sudo ./wsems I get the following:

[FORCE] 2018-08-24 06:22:10,791 ./wsems: Initializing EMS ....
[FORCE] 2018-08-24 06:22:10,791 main: Using config file /home/pi/Downloads/microserver/etc/config.json
[INFO ] 2018-08-24 06:22:10,791 ./wsems: Creating the WsEms proxy.
[INFO ] 2018-08-24 06:22:10,791 ./wsems: Starting HTTP Server.
[INFO ] 2018-08-24 06:22:10,791 Main: Using custom certificate and private key for HTTP Server
[WARN ] 2018-08-24 06:22:10,791 Main: Encryption is disabled on HTTP Server.
[WARN ] 2018-08-24 06:22:10,791 Main: Authentication is disabled on the HTTP Server.
[INFO ] 2018-08-24 06:22:10,792 ./wsems: Initializing the ThingWorx REST interface.
[FORCE] 2018-08-24 06:22:10,792 httpServer: starting http server port=8080
[INFO ] 2018-08-24 06:22:10,792 wsEmsProxy::initialize: FIPS is disabled.
[INFO ] 2018-08-24 06:22:10,792 wsEmsProxy::initialize: Encryption is disabled on Web Socket connection.
[WARN ] 2018-08-24 12:22:10,793 SDK: SDK Version: 2.1.2
[WARN ] 2018-08-24 12:22:10,793 SDK: TLS Library: OpenSSL
[WARN ] 2018-08-24 12:22:10,793 SDK: TLS Library Version: 1.0.2l-fips
[WARN ] 2018-08-24 12:22:10,793 SDK: FIPS Capable
[DEBUG] 2018-08-24 12:22:10,793 SDK: twWs_Create: Initializing Websocket Client for www.iotspace.io:80//Thingworx/WS
[DEBUG] 2018-08-24 12:22:10,793 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-08-24 06:22:10,793 httpServer: http server bound to port=8080.
[DEBUG] 2018-08-24 12:22:10,949 SDK: twApi_Initialize: Websocket Established after 0 tries
[DEBUG] 2018-08-24 12:22:10,949 SDK: subscribedPropsMgr_Initialize: Initializing subscribed properties manager
[INFO ] 2018-08-24 06:22:10,949 WsProxy::initialize: EMS Version 5.4.2.334
[INFO ] 2018-08-24 06:22:10,949 WsProxy::initialize: twApi singleton initialized
[WARN ] 2018-08-24 06:22:10,949 WsProxy::initialize: Certificate validation is disabled.
[WARN ] 2018-08-24 06:22:10,949 WsProxy::initialize: Self signed certificates are enabled.
[DEBUG] 2018-08-24 06:22:10,949 jsonConfigurator::getJsonEntity: Key validation_criteria not found
[DEBUG] 2018-08-24 06:22:10,950 jsonConfigurator::getJsonEntity: Parent file not found
[DEBUG] 2018-08-24 12:22:10,950 SDK: twTunnelManager_Create: Tunnel Manager singleton already exists
[ERROR] 2018-08-24 12:22:10,950 SDK: twMap_Add: parse function returned null.
[DEBUG] 2018-08-24 06:22:10,950 WsEmsProxy :: bindThing: Host specified as 'localhost'. Testing IPV6/IPV4 connectivity

www.iotspace.io:80-->[WARN ] 2018-08-24 06:22:10,960 WsEmsProxy :: bindThing: Exception connecting to localhost:8001. Err: Connection refused [localhost:8001]
[WARN ] 2018-08-24 06:22:10,960 WsEmsProxy::bindThing: Changing host from 'localhost' to '127.0.0.1'
[DEBUG] 2018-08-24 12:22:10,961 SDK: added PiThing7 to boundList
[DEBUG] 2018-08-24 12:22:10,961 SDK: twApi_BindThings: not currently connected, only binding things to api
[DEBUG] 2018-08-24 12:22:10,961 SDK: twMessage_Delete: Deleting BIND Message: 1
[DEBUG] 2018-08-24 06:22:10,961 jsonConfigurator::getJsonEntity: Parent file not found
[INFO ] 2018-08-24 06:22:10,961 wsEmsProxy::initialize: Initialization complete!
[INFO ] 2018-08-24 06:22:10,962 ./wsems: Starting the connection.
[ERROR] 2018-08-24 12:22:10,967 SDK: twStream_Delete: NULL Pointer passed in
[DEBUG] 2018-08-24 12:22:10,967 SDK: twTlsClient_Reconnect: Re-establishing SSL context
[DEBUG] 2018-08-24 12:22:11,244 SDK: twTlsClient_Connect: Connecting to server
[INFO ] 2018-08-24 12:22:11,451 SDK: Server supports websocket extensions: permessage-deflate
[DEBUG] 2018-08-24 12:22:11,451 SDK: ws_on_headers_complete: Websocket connected!
[INFO ] 2018-08-24 12:22:11,451 SDK: twWs_Connect: Websocket connected!
[DEBUG] 2018-08-24 12:22:11,452 SDK: twWs_SendMessage: Sent 60 bytes using 1 frames.
[DEBUG] 2018-08-24 12:22:11,714 SDK: twMessage_Delete: Deleting RESPONSE Message: 2
[DEBUG] 2018-08-24 12:22:11,714 SDK: twMessage_Delete: Deleting AUTH Message: 2
[WARN ] 2018-08-24 12:22:11,714 SDK: twBindBody_Delete: NULL body or stream pointer
[INFO ] 2018-08-24 06:22:11,714 Main: Succesfully connected. Saving .booted config file
[DEBUG] 2018-08-24 12:22:11,714 SDK: twMessage_Delete: Deleting BIND Message: 3
[DEBUG] 2018-08-24 12:22:11,714 SDK: twWs_SendMessage: Sent 27 bytes using 1 frames.
[DEBUG] 2018-08-24 12:22:11,717 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 06:22:11
[DEBUG] 2018-08-24 12:22:12,133 SDK: twMessage_Delete: Deleting RESPONSE Message: 3
[DEBUG] 2018-08-24 12:22:12,133 SDK: twMessage_Delete: Deleting BIND Message: 3
[INFO ] 2018-08-24 12:22:12,836 SDK: api_requesthandler: No handler found. Returning 404
[DEBUG] 2018-08-24 12:22:12,836 SDK: twMessage_Delete: Deleting RESPONSE Message: 5847
[DEBUG] 2018-08-24 12:22:12,836 SDK: twWs_SendMessage: Sent 17 bytes using 1 frames.
[DEBUG] 2018-08-24 12:22:12,836 SDK: twMessage_Delete: Deleting RESPONSE Message: 5847
[DEBUG] 2018-08-24 12:22:12,836 SDK: twMessage_Delete: Deleting REQUEST Message: 5847
[DEBUG] 2018-08-24 12:23:06,788 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 06:23:06

While running sudo ./wsems I was able to ping my Thingworx (I have attached the screenshot)

Can someone please help me solve this error? is it a problem with my port

Re: Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false

CRArko — Fri, 24 Aug 2018 16:00:15 GMT

Hello! Thanks for posting your question in our Community.

For the error:

www.iotspace.io:80-->[WARN ] 2018-08-24 06:22:10,960 WsEmsProxy :: bindThing: Exception connecting to localhost:8001. Err: Connection refused [localhost:8001]

That may indicated a problem with talking to port 8001, check to be sure there are no active firewall blockages on that port. Also, what version of the EMS are you running?

This other post shows similar errors, and looks like it's still a work in progress.

Thanks,

-- Craig A.

Re: Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false

Gowresh_R — Fri, 24 Aug 2018 16:29:20 GMT

That may indicated a problem with talking to port 8001, check to be sure there are no active firewall blockages on that port. Also, what version of the EMS are you running?

Hello Craig! Thanks for your reply.

Yes. You were right. I forgot that the default port value will be taken if not specified. I specified the port name under "auto_bind". Now that error was eliminated. This is the log I get now:

[FORCE] 2018-08-24 14:49:53,826 ./wsems: Initializing EMS ....
[FORCE] 2018-08-24 14:49:53,826 main: Using config file /home/pi/Downloads/microserver/etc/config.json
[INFO ] 2018-08-24 14:49:53,826 ./wsems: Creating the WsEms proxy.
[INFO ] 2018-08-24 14:49:53,826 ./wsems: Starting HTTP Server.
[INFO ] 2018-08-24 14:49:53,827 Main: Using custom certificate and private key for HTTP Server
[WARN ] 2018-08-24 14:49:53,827 Main: Encryption is disabled on HTTP Server.
[WARN ] 2018-08-24 14:49:53,827 Main: Authentication is disabled on the HTTP Server.
[FORCE] 2018-08-24 14:49:53,827 httpServer:
[INFO ] 2018-08-24 14:49:53,827 ./wsems: Initializing the ThingWorx REST interface.
[INFO ] 2018-08-24 14:49:53,828 wsEmsProxy::initialize: FIPS is disabled.
[INFO ] 2018-08-24 14:49:53,828 wsEmsProxy::initialize: Encryption is disabled on Web Socket connection.
[WARN ] 2018-08-24 20:49:53,829 SDK: SDK Version: 2.1.2
[WARN ] 2018-08-24 20:49:53,830 SDK: TLS Library: OpenSSL
[WARN ] 2018-08-24 20:49:53,830 SDK: TLS Library Version: 1.0.2l-fips
[WARN ] 2018-08-24 20:49:53,830 SDK: FIPS Capable
[DEBUG] 2018-08-24 20:49:53,830 SDK: twWs_Create: Initializing Websocket Client for www.iotspace.io:80//Thingworx/WS
[DEBUG] 2018-08-24 20:49:53,830 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-08-24 14:49:53,830 httpServer: http server bound to port=8080.
[DEBUG] 2018-08-24 20:49:54,866 SDK: twApi_Initialize: Websocket Established after 0 tries
[DEBUG] 2018-08-24 20:49:54,866 SDK: subscribedPropsMgr_Initialize: Initializing subscribed properties manager
[INFO ] 2018-08-24 14:49:54,866 WsProxy::initialize: EMS Version 5.4.2.334
[INFO ] 2018-08-24 14:49:54,866 WsProxy::initialize: twApi singleton initialized
[WARN ] 2018-08-24 14:49:54,866 WsProxy::initialize: Certificate validation is disabled.
[WARN ] 2018-08-24 14:49:54,866 WsProxy::initialize: Self signed certificates are enabled.
[DEBUG] 2018-08-24 14:49:54,866 jsonConfigurator::getJsonEntity: Key validation_criteria not found
[DEBUG] 2018-08-24 14:49:54,867 jsonConfigurator::getJsonEntity: Parent file not found
[DEBUG] 2018-08-24 20:49:54,868 SDK: twTunnelManager_Create: Tunnel Manager singleton already exists
[ERROR] 2018-08-24 20:49:54,868 SDK: twMap_Add: parse function returned null.
[DEBUG] 2018-08-24 14:49:54,867 WsEmsProxy::bindThing: Host specified as 'localhost'. Testing IPV6/IPV4 connectivity

www.iotspace.io:80-->[DEBUG] 2018-08-24 20:49:54,869 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-08-24 20:49:54,870 SDK: added PiThing7 to boundList
[DEBUG] 2018-08-24 20:49:54,870 SDK: twApi_BindThings: not currently connected, only binding things to api
[DEBUG] 2018-08-24 20:49:54,870 SDK: twMessage_Delete: Deleting BIND Message: 1
[DEBUG] 2018-08-24 14:49:54,869 jsonConfigurator::getJsonEntity: Parent file not found
[INFO ] 2018-08-24 14:49:54,870 wsEmsProxy::initialize: Initialization complete!
[INFO ] 2018-08-24 14:49:54,871 ./wsems: Starting the connection.
[ERROR] 2018-08-24 20:49:54,872 SDK: twStream_Delete: NULL Pointer passed in
[DEBUG] 2018-08-24 20:49:54,872 SDK: twTlsClient_Reconnect: Re-establishing SSL context
[DEBUG] 2018-08-24 14:49:54,872 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-08-24 14:49:54,873 TlsStream::doclose: Disconeccting socket
[DEBUG] 2018-08-24 20:49:54,874 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 24/Aug/2018:20:49:54 [+0600] HTTP Server: 0.0.0.0 - SeqId 2 - "" 400 375 "-"

[DEBUG] 2018-08-24 20:49:54,874 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-08-24 20:49:54,879 SDK: twTlsClient_Connect: Connecting to server
[INFO ] 2018-08-24 20:49:55,41 SDK: Server supports websocket extensions: permessage-deflate
[DEBUG] 2018-08-24 20:49:55,41 SDK: ws_on_headers_complete: Websocket connected!
[INFO ] 2018-08-24 20:49:55,41 SDK: twWs_Connect: Websocket connected!
[DEBUG] 2018-08-24 20:49:55,41 SDK: twWs_SendMessage: Sent 60 bytes using 1 frames.
[DEBUG] 2018-08-24 20:49:55,238 SDK: twMessage_Delete: Deleting RESPONSE Message: 2
[DEBUG] 2018-08-24 20:49:55,238 SDK: twMessage_Delete: Deleting AUTH Message: 2
[WARN ] 2018-08-24 20:49:55,239 SDK: twBindBody_Delete: NULL body or stream pointer
[DEBUG] 2018-08-24 20:49:55,239 SDK: twMessage_Delete: Deleting BIND Message: 3
[DEBUG] 2018-08-24 20:49:55,239 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 14:49:55
[DEBUG] 2018-08-24 20:49:55,239 SDK: twWs_SendMessage: Sent 27 bytes using 1 frames.
[INFO ] 2018-08-24 14:49:55,273 Main: Succesfully connected. Saving .booted config file
[DEBUG] 2018-08-24 20:49:55,405 SDK: twMessage_Delete: Deleting RESPONSE Message: 3
[DEBUG] 2018-08-24 20:49:55,405 SDK: twMessage_Delete: Deleting BIND Message: 3
[INFO ] 2018-08-24 20:49:56,695 SDK: api_requesthandler: No handler found. Returning 404
[DEBUG] 2018-08-24 20:49:56,696 SDK: twMessage_Delete: Deleting RESPONSE Message: 6453
[DEBUG] 2018-08-24 20:49:56,697 SDK: twWs_SendMessage: Sent 17 bytes using 1 frames.
[DEBUG] 2018-08-24 20:49:56,697 SDK: twMessage_Delete: Deleting RESPONSE Message: 6453
[DEBUG] 2018-08-24 20:49:56,697 SDK: twMessage_Delete: Deleting REQUEST Message: 6453

Also my EMS version is 5-4-0-114.

Re: Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false

Gowresh_R — Sat, 25 Aug 2018 07:01:29 GMT

Hello Craig! Thank you for your reply!

As you pointed out the port 8001 was an issue. Since I did not specify any port value for auto_binding, the default value of 8001 was taken. I changed it to another port and that error was solved.

However executing the luaResource still resulted in the same errors.

My version of EMS is 5.4.0. I tried the same with 5.4.2 but the results were the same. Somewhere in another post it was recommended to use version 5.3.2. But I was not able to get hold of that version. Could the latest version be causing these errors? With the same versions (5.4.0 and 5.4.2), I have seen people install microserver in a localhost (i.e ws_servers host as local ip address). But to my knowledge no one has installed it in a domain. Could you suggest where I will be able to get 5.3.4 version?

Thanks,

Gowresh

Re: Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false

Gowresh_R — Tue, 28 Aug 2018 13:29:42 GMT

My problem was solved. It was a small beginner's mistake. I failed to understand the concept that both the executable (wsems and luaResources) have to be run simultaneously. Running them fixed the issue.

Thank You.

Re: Error occured while accessing EMS. Checking isConnected. EMS is available: true, online: false

CRArko — Tue, 28 Aug 2018 20:39:57 GMT

You are very welcome. Glad to hear things are working.

-- Craig A.