Re: ./luaScriptResource hangs on thingworx.handler... - Page 2

sservices · ‎Feb 28, 2018

I have spent a a couple days trying to get a raspberry to talk to Thingworx using the tutorial. I am able to get connected to the websocket and everything, and I can see that the value for isConnected on the PiThing Properties tab change to true. My issue is that I can't get the luaScriptResources to finish the connection process and send any of the variables over to Thingworx to bind them. Here is the output from both ./wsems and ./luaScriptResources. If any of you see anything that sticks out or know of something else I can try please let me know.
$: sudo ./wsems
[FORCE] 2018-02-28 21:49:34,205 ./wsems: Initializing EMS ....
[FORCE] 2018-02-28 21:49:34,205 main: Using config file /home/pi/microserver/etc/config.json
[INFO ] 2018-02-28 21:49:34,205 ./wsems: Creating the WsEms proxy.
[INFO ] 2018-02-28 21:49:34,205 ./wsems: Starting HTTP Server.
[INFO ] 2018-02-28 21:49:34,206 Main: Using custom certificate and private key for HTTP Server
[WARN ] 2018-02-28 21:49:34,206 Main: Encryption is disabled on HTTP Server.
[WARN ] 2018-02-28 21:49:34,206 Main: Authentication is disabled on the HTTP Server.
[INFO ] 2018-02-28 21:49:34,206 ./wsems: Initializing the ThingWorx REST interface.
[FORCE] 2018-02-28 21:49:34,206 httpServer: starting http server port=8080
[INFO ] 2018-02-28 21:49:34,207 wsEmsProxy::initialize: FIPS is disabled.
[INFO ] 2018-02-28 21:49:34,207 wsEmsProxy::initialize: Encryption is disabled on Web Socket connection.
[DEBUG] 2018-02-28 21:49:34,207 httpServer: http server bound to port=8080.
[WARN ] 2018-02-28 21:49:34,208 SDK: SDK Version: 2.0.4
[WARN ] 2018-02-28 21:49:34,208 SDK: TLS Library: OpenSSL
[WARN ] 2018-02-28 21:49:34,208 SDK: TLS Library Version: 1.0.2l
[WARN ] 2018-02-28 21:49:34,208 SDK: FIPS Capable
[DEBUG] 2018-02-28 21:49:34,208 SDK: twWs_Create: Initializing Websocket Client for 192.168.93.24:80//Thingworx/WS
[DEBUG] 2018-02-28 21:49:34,208 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-02-28 21:49:34,217 SDK: twApi_Initialize: Websocket Established after 0 tries
[DEBUG] 2018-02-28 21:49:34,217 SDK: subscribedPropsMgr_Initialize: Initializing subscribed properties manager
[INFO ] 2018-02-28 21:49:34,217 WsProxy::initialize: EMS Version 5.4.0.114
[INFO ] 2018-02-28 21:49:34,217 WsProxy::initialize: twApi singleton initialized
[WARN ] 2018-02-28 21:49:34,217 WsProxy::initialize: Certificate validation is disabled.
[WARN ] 2018-02-28 21:49:34,217 WsProxy::initialize: Self signed certificates are enabled.
[DEBUG] 2018-02-28 21:49:34,217 jsonConfigurator::getJsonEntity: Key validation_criteria not found
[DEBUG] 2018-02-28 21:49:34,217 jsonConfigurator::getJsonEntity: Parent file not found
[DEBUG] 2018-02-28 21:49:34,218 SDK: twTunnelManager_Create: Tunnel Manager singleton already exists
[ERROR] 2018-02-28 21:49:34,218 SDK: twMap_Add: parse function returned null.
[DEBUG] 2018-02-28 21:49:34,217 WsEmsProxy::bindThing: Host specified as 'localhost'. Testing IPV6/IPV4 connectivity
[WARN ] 2018-02-28 21:49:34,219 WsEmsProxy::bindThing: Exception connecting to localhost:8001. Err: Connection refused [localhost:8001]
[WARN ] 2018-02-28 21:49:34,219 WsEmsProxy::bindThing: Changing host from 'localhost' to '127.0.0.1'
[DEBUG] 2018-02-28 21:49:34,220 SDK: added PiThing to boundList
[DEBUG] 2018-02-28 21:49:34,220 SDK: twApi_BindThings: not currently connected, only binding things to api
[DEBUG] 2018-02-28 21:49:34,220 SDK: twMessage_Delete: Deleting BIND Message: 1
[DEBUG] 2018-02-28 21:49:34,219 jsonConfigurator::getJsonEntity: Parent file not found
[INFO ] 2018-02-28 21:49:34,219 wsEmsProxy::initialize: Initialization complete!
[INFO ] 2018-02-28 21:49:34,220 ./wsems: Starting the connection.

192.168.93.24:80-->[DEBUG] 2018-02-28 21:49:34,221 SDK: twTlsClient_Reconnect: Re-establishing SSL context
[DEBUG] 2018-02-28 21:49:34,221 SDK: twTlsClient_Connect: Connecting to server
[DEBUG] 2018-02-28 21:49:34,224 SDK: ws_on_headers_complete: Websocket connected!
[INFO ] 2018-02-28 21:49:34,224 SDK: twWs_Connect: Websocket connected!
[DEBUG] 2018-02-28 21:49:34,224 SDK: twWs_SendMessage: Sent 60 bytes using 1 frames.
[DEBUG] 2018-02-28 21:49:34,266 SDK: twMessage_Delete: Deleting RESPONSE Message: 2
[DEBUG] 2018-02-28 21:49:34,266 SDK: twMessage_Delete: Deleting AUTH Message: 2
[WARN ] 2018-02-28 21:49:34,267 SDK: twBindBody_Delete: NULL body or stream pointer
[DEBUG] 2018-02-28 21:49:34,267 SDK: twMessage_Delete: Deleting BIND Message: 3
[DEBUG] 2018-02-28 21:49:34,267 SDK: twWs_SendMessage: Sent 26 bytes using 1 frames.
[DEBUG] 2018-02-28 21:49:34,269 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 21:49:34
[INFO ] 2018-02-28 21:49:34,271 Main: Succesfully connected. Saving .booted config file
[DEBUG] 2018-02-28 21:49:34,309 SDK: twMessage_Delete: Deleting RESPONSE Message: 3
[DEBUG] 2018-02-28 21:49:34,309 SDK: twMessage_Delete: Deleting BIND Message: 3
[DEBUG] 2018-02-28 21:49:35,315 SDK: twTlsClient_Create: Initializing TLS Client

$: sudo ./luaScriptResources
[INFO ] 2018-02-28 21:59:38,413 ./luaScriptResource: Using config file: /home/pi/microserver/etc/config.lua
[FORCE] 2018-02-28 21:59:38,413 ./luaScriptResource: Starting up ....

[INFO ] 2018-02-28 21:59:38,419 luaScriptResource:main: Encryption is disabled on the RAP connection.
[INFO ] 2018-02-28 21:59:38,420 luaScriptResource:main: FIPS is disabled.
[INFO ] 2018-02-28 21:59:38,424 ./luaScriptResource: New path is /home/pi/microserver/etc/thingworx/clibs:/home/pi/microserver/etc/custom/clibs:/home/pi/microserver/etc/community/clibs:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
[WARN ] 2018-02-28 21:59:38,427 ScriptResource::initialize: Encryption is disabled on HTTP Server.
[WARN ] 2018-02-28 21:59:38,427 ScriptResource::initialize: Authentication is disabled on the HTTP Server.
[INFO ] 2018-02-28 21:59:38,481 thingworx.shape: Creating a new shape.
[INFO ] 2018-02-28 21:59:38,482 PiThing: -- Configuration -------------------------------
[INFO ] 2018-02-28 21:59:38,482 PiThing: scanRate: 1000
[INFO ] 2018-02-28 21:59:38,482 PiThing: scanRateResolution: 500
[INFO ] 2018-02-28 21:59:38,483 PiThing: taskRate: 30000
[INFO ] 2018-02-28 21:59:38,484 PiThing: keepAliveRate: 60000
[INFO ] 2018-02-28 21:59:38,484 PiThing: requestTimeout: 15000
[INFO ] 2018-02-28 21:59:38,484 PiThing: registerRate: 43200000
[INFO ] 2018-02-28 21:59:38,484 PiThing: register: true
[INFO ] 2018-02-28 21:59:38,484 PiThing: getPropertySubscriptionOnReconnect: false
[INFO ] 2018-02-28 21:59:38,484 PiThing: maxConcurrentPropertyUpdates: 100
[INFO ] 2018-02-28 21:59:38,485 PiThing: defaultPushType: VALUE
[INFO ] 2018-02-28 21:59:38,488 PiThing: useShapes: true
[INFO ] 2018-02-28 21:59:38,488 PiThing: identifier: Not Specififed
[INFO ] 2018-02-28 21:59:38,488 PiThing: ------------------------------------------------
[FORCE] 2018-02-28 21:59:38,489 httpServer: starting http server port=8001
[INFO ] 2018-02-28 21:59:38,490 thingworx.template: Adding shape 'shapes.metadata' to template 'thingworx.template'
[INFO ] 2018-02-28 21:59:38,492 thingworx.template: Adding shape 'shapes.propsubscribe' to template 'thingworx.template'
[INFO ] 2018-02-28 21:59:38,493 thingworx.template: Creating new templates.PiTemplate named 'PiThing'
[INFO ] 2018-02-28 21:59:38,493 PiThing: -- Initializing properties ---------------------
[INFO ] 2018-02-28 21:59:38,493 PiThing: Initialized property upToDate [baseType: BOOLEAN, pushType: NEVER, handler: nil, value: true]
[INFO ] 2018-02-28 21:59:38,494 PiThing: Initialized property cpu_volt [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-02-28 21:59:38,494 PiThing: Initialized property cpu_temperature [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-02-28 21:59:38,494 PiThing: Initialized property cpu_freq [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-02-28 21:59:38,494 PiThing: ------------------------------------------------
[ERROR] 2018-02-28 21:59:38,495 httpserver: Server socket error: Address already in use [127.0.0.1:8001]
[ERROR] 2018-02-28 21:59:38,495 httpServer: unable to bind http server to port=8001, trying next port.
[ERROR] 2018-02-28 21:59:38,495 httpServer: unable to bind http server to any port from 8001 to 8001.
[INFO ] 2018-02-28 21:59:40,464 PiThing: -- Starting script --------------------------
[INFO ] 2018-02-28 21:59:40,465 PiThing: Registering core callback handler
[INFO ] 2018-02-28 21:59:40,465 PiThing: Starting main loop
[INFO ] 2018-02-28 21:59:40,465 PiThing: Calling lifecycle start listeners.
[INFO ] 2018-02-28 21:59:40,465 shapes.propsubscribe: Initialized
[INFO ] 2018-02-28 21:59:40,466 thingworx.handler: Creating a new handler.

It just hangs at this point and doesn't go on. If I change setting to some other ports i.e. 80 I will get this from ./luaScriptResources, which I feel is due to incorrect port choice so I think what is above is the correct configuration but I thought I would include this for completeness.
$: sudo ./luaScriptResources
[INFO ] 2018-02-28 22:02:20,802 ./luaScriptResource: Using config file: /home/pi/microserver/etc/config.lua
[FORCE] 2018-02-28 22:02:20,802 ./luaScriptResource: Starting up ....

[INFO ] 2018-02-28 22:02:20,805 luaScriptResource:main: Encryption is disabled on the RAP connection.
[INFO ] 2018-02-28 22:02:20,805 luaScriptResource:main: FIPS is disabled.
[INFO ] 2018-02-28 22:02:20,807 ./luaScriptResource: New path is /home/pi/microserver/etc/thingworx/clibs:/home/pi/microserver/etc/custom/clibs:/home/pi/microserver/etc/community/clibs:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
[WARN ] 2018-02-28 22:02:20,808 ScriptResource::initialize: Encryption is disabled on HTTP Server.
[WARN ] 2018-02-28 22:02:20,808 ScriptResource::initialize: Authentication is disabled on the HTTP Server.
[FORCE] 2018-02-28 22:02:20,831 httpServer: starting http server port=8001
[ERROR] 2018-02-28 22:02:20,834 httpserver: Server socket error: Address already in use [127.0.0.1:8001]
[ERROR] 2018-02-28 22:02:20,834 httpServer: unable to bind http server to port=8001, trying next port.
[ERROR] 2018-02-28 22:02:20,836 httpServer: unable to bind http server to any port from 8001 to 8001.
[INFO ] 2018-02-28 22:02:20,858 thingworx.shape: Creating a new shape.
[INFO ] 2018-02-28 22:02:20,859 PiThing: -- Configuration -------------------------------
[INFO ] 2018-02-28 22:02:20,859 PiThing: scanRate: 1000
[INFO ] 2018-02-28 22:02:20,859 PiThing: scanRateResolution: 500
[INFO ] 2018-02-28 22:02:20,859 PiThing: taskRate: 30000
[INFO ] 2018-02-28 22:02:20,859 PiThing: keepAliveRate: 60000
[INFO ] 2018-02-28 22:02:20,860 PiThing: requestTimeout: 15000
[INFO ] 2018-02-28 22:02:20,860 PiThing: registerRate: 43200000
[INFO ] 2018-02-28 22:02:20,860 PiThing: register: true
[INFO ] 2018-02-28 22:02:20,860 PiThing: getPropertySubscriptionOnReconnect: false
[INFO ] 2018-02-28 22:02:20,860 PiThing: maxConcurrentPropertyUpdates: 100
[INFO ] 2018-02-28 22:02:20,860 PiThing: defaultPushType: VALUE
[INFO ] 2018-02-28 22:02:20,860 PiThing: useShapes: true
[INFO ] 2018-02-28 22:02:20,861 PiThing: identifier: Not Specififed
[INFO ] 2018-02-28 22:02:20,861 PiThing: ------------------------------------------------
[INFO ] 2018-02-28 22:02:20,862 thingworx.template: Adding shape 'shapes.metadata' to template 'thingworx.template'
[INFO ] 2018-02-28 22:02:20,862 thingworx.template: Adding shape 'shapes.propsubscribe' to template 'thingworx.template'
[INFO ] 2018-02-28 22:02:20,862 thingworx.template: Creating new templates.PiTemplate named 'PiThing'
[INFO ] 2018-02-28 22:02:20,862 PiThing: -- Initializing properties ---------------------
[INFO ] 2018-02-28 22:02:20,863 PiThing: Initialized property upToDate [baseType: BOOLEAN, pushType: NEVER, handler: nil, value: true]
[INFO ] 2018-02-28 22:02:20,863 PiThing: Initialized property cpu_volt [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-02-28 22:02:20,863 PiThing: Initialized property cpu_temperature [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-02-28 22:02:20,863 PiThing: Initialized property cpu_freq [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-02-28 22:02:20,863 PiThing: ------------------------------------------------
[INFO ] 2018-02-28 22:02:22,833 PiThing: -- Starting script --------------------------
[INFO ] 2018-02-28 22:02:22,833 PiThing: Registering core callback handler
[INFO ] 2018-02-28 22:02:22,833 PiThing: Starting main loop
[INFO ] 2018-02-28 22:02:22,833 PiThing: Calling lifecycle start listeners.
[INFO ] 2018-02-28 22:02:22,834 shapes.propsubscribe: Initialized
[INFO ] 2018-02-28 22:02:22,834 thingworx.handler: Creating a new handler.
[ERROR] 2018-02-28 22:02:22,846 UnencryptedClientStream::doopen: Error opening socket. Error: 111
[ERROR] 2018-02-28 22:02:22,847 HttpClient::initialize: Exception while opening connection request to 127.0.0.1. Error: Error opening non-TLS socket [127.0.0.1:80]
[ERROR] 2018-02-28 22:02:22,847 luaBindings::httpPost: Error POSTing to HTTP Server at 127.0.0.1/Thingworx/Things/LocalEms/Services/AddEdgeThing
[INFO ] 2018-02-28 22:02:22,848 PiThing: Error occured while accessing EMS. Checking isConnected.
[ERROR] 2018-02-28 22:02:22,849 UnencryptedClientStream::doopen: Error opening socket. Error: 111
[ERROR] 2018-02-28 22:02:22,849 HttpClient::initialize: Exception while opening connection request to 127.0.0.1. Error: Error opening non-TLS socket [127.0.0.1:80]
[ERROR] 2018-02-28 22:02:22,850 luaBindings::httpGet: Error GETing from HTTP server at 127.0.0.1/Thingworx/Things/LocalEms/Properties/isConnected
[INFO ] 2018-02-28 22:02:22,850 PiThing: EMS is available: false, online: false

Thanks in advance for any help you can give!

jdass · ‎Apr 09, 2018

If

-EMS and LSR are executed on a Linux env

-TLS is disabled

-a connection has established to ThingWorx platform using WSEMS

-there are no Errors logged in WSEMS and LSR logs,

-but the LSR hangs and the last fewlines of LSR look like this -

[TRACE] 2018-04-05 19:38:11,615 luaBindings:newRapClient: Found RAP at 10.0.2.15:8000
[TRACE] 2018-04-05 19:38:11,615 luaBindings: Got RAP timeout: 0
[TRACE] 2018-04-05 19:38:11,615 luaRapBindings: Self Signed certificates are enabled for the RAP conneciton.
[TRACE] 2018-04-05 19:38:11,615 luaRapBindings: Certificate validation is enabled for the RAP conneciton
[DEBUG] 2018-04-05 15:38:11,616 SDK: twTlsClient_Create: Initializing TLS Client

then it could be the bug reported with EMS 5.4.0. when run on Debian 9(stretch)/Ubuntu.

Workaround is to configure EMS and LSR to use TLS or to use a EMS version 5.3.4.

wcui · ‎May 14, 2018

I installed EMS 5.4.0 on Linux Centos7 and met the same problem, ssl is false in <http_server> segment.

- wsems started successfully

- lua started and hanged with below as last output, apparently it hanged...

-------------------------<Lua log>-----------------------

[INFO ] 2018-05-15 02:15:06,465 Edge540Thing: ------------------------------------------------
[INFO ] 2018-05-15 02:15:08,435 Edge540Thing: -- Starting script --------------------------
[INFO ] 2018-05-15 02:15:08,435 Edge540Thing: Registering core callback handler
[INFO ] 2018-05-15 02:15:08,435 Edge540Thing: Starting main loop
[INFO ] 2018-05-15 02:15:08,435 Edge540Thing: Calling lifecycle start listeners.
[INFO ] 2018-05-15 02:15:08,435 handlers.http: Opened
[INFO ] 2018-05-15 02:15:08,435 handlers.script: Opened
[INFO ] 2018-05-15 02:15:08,435 handlers.generator: Opened
[INFO ] 2018-05-15 02:15:08,435 shapes.propsubscribe: Initialized
[INFO ] 2018-05-15 02:15:08,436 thingworx.handler: Creating a new handler.

Then I changed ssl to true in <http_server> segmen as below.Good news is that lua started successfully.

Bad news is that lua failed to connect with ems server thus no property update could be seen on Thingworx side.

And in lua log, I noticed there is a Http code 503 error.

-------------------------config.json-----------------------

"http_server" : {
       "host": "localhost",
       "port": 8000,
       "ssl" : true,
       "authenticate" : true,
       "user": "cui",
       "password": "ptc",
       "use_default_certificate" : true
   },

-------------------------config.lua-----------------------

scripts.rap_host = "localhost"
scripts.rap_port = "8000"
scripts.rap_ssl = true
scripts.rap_server_authenticate = true
scripts.rap_validate = false
scripts.rap_deny_selfsigned = false
scripts.rap_userid = "cui"
scripts.rap_password = "ptc"

-------------------------partial lua log-----------------------

[ERROR] 2018-05-15 01:59:44,144 HttpClient::processReq: Timeout while waiting for response from localhost.
[ERROR] 2018-05-15 01:59:44,144 luaBindings::httpPost★: Error POSTing to HTTP Server at localhost/Thingworx/Things/LocalEms/Services/AddEdgeThing
[INFO ] 2018-05-15 01:59:44,145 Edge540Thing: Error occured while accessing EMS. Checking isConnected.

[ERROR] 2018-05-15 02:00:14,153 HttpClient::processReq: Timeout while waiting for response from localhost.
[ERROR] 2018-05-15 02:00:14,153 luaBindings::httpGet★: Error GETing from HTTP server at localhost/Thingworx/Things/LocalEms/Properties/isConnected
[INFO ] 2018-05-15 02:00:14,153 Edge540Thing: EMS is available: false, online: false
[WARN ] 2018-05-15 02:00:14,153 Edge540Thing: Could not register with the MicroServer. ★code: 503, msg: Error attempting HTTP POST

Still not clear on below issues. Anyone has any clue??

1. why lua fails to start when not using SSL connection with ems server.

2. why lua fails to connect with ems server when using SSL connection.

wcui · ‎May 17, 2018

Below are personal testing result.

For Linux, ems<->lua and lua<->device must be set with SSL to work normally. While for windows, non SSL settting can work well.

・http_server／scripts.rap_xxx
・scripts.script_xx　　

Seems to be a bug and will report to RnD later.

stefant · ‎Jun 14, 2018

Hi,

Can you please post your files. I would try to get my system also running.

MenaGabara · ‎Jun 14, 2018

could you please give me the link for ems 5.3.4, i can't find it anywhere.

AkshayKumar · ‎Jul 05, 2018

Please Share link for MED-61060-CD-053_SP5_Microserver-5-3-4-2383-Linux-ARM-HWFPU.zip

./luaScriptResource hangs on thingworx.handler: Creating a new handler.

./luaScriptResource hangs on thingworx.handler: Creating a new handler.