Re: Error 500. Could not set properties on server.

Martin11 · ‎Dec 05, 2018

Hello,

I am on a 30 day trial account and following this guide. We are trying to connect a raspberry pi with the hosted ThingWorx server. The raspberry pi is running the edge microserver and the lua script. The problem we are facing is that the Lua Script Resource is failing to communicate with the Edge Microserver. The EMS(edge microserver) was working, but the LSR(Lua Script Resource) hanged with the quickstart guide's files. Adding minimal security to both of the config files seemed to fix this issue. Now the issue seems to be that the LSR is unable to communicate - get or set properties on the server.

Running the LSR yields the following output:

pi@raspberrypi:~/Project/microserver $ sudo ./luaScriptResource
[INFO ] 2018-12-05 12:01:57,180 ./luaScriptResource: Using config file: /home/pi/Project/microserver/etc/config.lua
[FORCE] 2018-12-05 12:01:57,180 ./luaScriptResource: Starting up ....

[INFO ] 2018-12-05 12:01:57,185 luaScriptResource:main: Encryption is enabled on the RAP connection.
[INFO ] 2018-12-05 12:01:57,185 luaScriptResource:main: FIPS is disabled.
[INFO ] 2018-12-05 12:01:57,188 ./luaScriptResource: New path is (null)
[WARN ] 2018-12-05 12:01:57,194 ScriptResource::initialize: Authentication is disabled on the HTTP Server.
[FORCE] 2018-12-05 12:01:57,217 httpServer: starting http server port=8010
[INFO ] 2018-12-05 12:01:57,310 thingworx.shape: Creating a new shape.
[INFO ] 2018-12-05 12:01:57,311 EdgeThing: -- Configuration -------------------------------
[INFO ] 2018-12-05 12:01:57,311 EdgeThing: scanRate: 1000
[INFO ] 2018-12-05 12:01:57,311 EdgeThing: scanRateResolution: 500
[INFO ] 2018-12-05 12:01:57,311 EdgeThing: taskRate: 30000
[INFO ] 2018-12-05 12:01:57,311 EdgeThing: keepAliveRate: 60000
[INFO ] 2018-12-05 12:01:57,311 EdgeThing: requestTimeout: 15000
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: registerRate: 43200000
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: register: true
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: getPropertySubscriptionOnReconnect: false
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: maxConcurrentPropertyUpdates: 100
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: defaultPushType: VALUE
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: useShapes: true
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: identifier: PiThing
[INFO ] 2018-12-05 12:01:57,312 EdgeThing: ------------------------------------------------
[INFO ] 2018-12-05 12:01:57,315 thingworx.template: Adding shape 'shapes.metadata' to template 'thingworx.template'
[INFO ] 2018-12-05 12:01:57,315 thingworx.template: Adding shape 'shapes.propsubscribe' to template 'thingworx.template'
[INFO ] 2018-12-05 12:01:57,315 thingworx.template: Creating new templates.PiTemplate named 'EdgeThing'
[INFO ] 2018-12-05 12:01:57,315 EdgeThing: -- Initializing properties ---------------------
[INFO ] 2018-12-05 12:01:57,316 EdgeThing: Initialized property upToDate [baseType: BOOLEAN, pushType: NEVER, handler: nil, value: true]
[INFO ] 2018-12-05 12:01:57,316 EdgeThing: Initialized property cpu_volt [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-12-05 12:01:57,316 EdgeThing: Initialized property cpu_temperature [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-12-05 12:01:57,317 EdgeThing: Initialized property cpu_freq [baseType: NUMBER, pushType: ALWAYS, handler: nil, value: 0]
[INFO ] 2018-12-05 12:01:57,317 EdgeThing: ------------------------------------------------
[INFO ] 2018-12-05 12:01:57,317 Thingworx: Registering identifier *PiThing for thing EdgeThing
[INFO ] 2018-12-05 12:01:58,317 EdgeThing: Identifier *PiThing registered with main Thingworx script for for Thing EdgeThing
[INFO ] 2018-12-05 12:02:00,288 EdgeThing: -- Starting script --------------------------
[INFO ] 2018-12-05 12:02:00,288 EdgeThing: Registering core callback handler
[INFO ] 2018-12-05 12:02:00,288 EdgeThing: Starting main loop
[INFO ] 2018-12-05 12:02:00,288 EdgeThing: Calling lifecycle start listeners.
[INFO ] 2018-12-05 12:02:00,288 shapes.propsubscribe: Initialized
[INFO ] 2018-12-05 12:02:00,293 thingworx.handler: Creating a new handler.
[ERROR] 2018-12-05 14:02:49,881 SDK: TW_SSL_ACCEPT: SSL handshake error. Error: error:00000000:lib(0):func(0):reason(0).
[ERROR] 2018-12-05 12:02:49,881 TlsServerStream::doopen: ssl_read returned an error: -1
[ERROR] 2018-12-05 12:02:49,881 httpserver: Server socket error: SSL Handshake Failed [*:34528]
[INFO ] 2018-12-05 12:02:50,394 EdgeThing: MicroServer is now available.
[INFO ] 2018-12-05 12:02:50,394 EdgeThing: MicroServer is online.
[INFO ] 2018-12-05 12:02:50,394 EdgeThing: Successfully registered EdgeThing with MicroServer.
[INFO ] 2018-12-05 12:02:50,896 EdgeThing: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-12-05 12:02:50,937 EdgeThing: EMS is available: true, online: true
[INFO ] 2018-12-05 12:02:50,938 EdgeThing: Attempting to GetPropertySubscriptions from server failed. code: 500, result: 
[INFO ] 2018-12-05 12:02:51,510 EdgeThing: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-12-05 12:02:51,528 EdgeThing: EMS is available: true, online: true
[INFO ] 2018-12-05 12:02:51,528 EdgeThing: Attempting to GetPropertySubscriptions from server failed. code: 500, result: 
[INFO ] 2018-12-05 12:02:52,639 EdgeThing: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-12-05 12:02:52,681 EdgeThing: EMS is available: true, online: true
[WARN ] 2018-12-05 12:02:52,681 thingworx.server: Could not set properties on server. code: 500, resp: 
[INFO ] 2018-12-05 12:02:54,825 EdgeThing: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-12-05 12:02:54,866 EdgeThing: EMS is available: true, online: true
[WARN ] 2018-12-05 12:02:54,866 thingworx.server: Could not set properties on server. code: 500, resp: 
[INFO ] 2018-12-05 12:02:57,140 EdgeThing: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-12-05 12:02:57,161 EdgeThing: EMS is available: true, online: true
[WARN ] 2018-12-05 12:02:57,161 thingworx.server: Could not set properties on server. code: 500, resp: 
[INFO ] 2018-12-05 12:02:58,908 EdgeThing: Error occured while accessing EMS. Checking isConnected.
[INFO ] 2018-12-05 12:02:58,946 EdgeThing: EMS is available: true, online: true
[WARN ] 2018-12-05 12:02:58,947 thingworx.server: Could not set properties on server. code: 500, resp:

Output when running the EMS:

pi@raspberrypi:~/Project/microserver $ sudo ./wsems
[FORCE] 2018-12-05 12:01:04,48 ./wsems: Initializing EMS ....
[FORCE] 2018-12-05 12:01:04,48 main: Using config file /home/pi/Project/microserver/etc/config.json
[INFO ] 2018-12-05 12:01:04,48 ./wsems: Creating the WsEms proxy.
[INFO ] 2018-12-05 12:01:04,48 ./wsems: Starting HTTP Server.
[INFO ] 2018-12-05 12:01:04,48 Main: Using built-in certificate for HTTP Server
[INFO ] 2018-12-05 12:01:04,48 Main: Encryption is enabled on HTTP Server.
[WARN ] 2018-12-05 12:01:04,48 Main: Authentication is disabled on the HTTP Server.
[FORCE] 2018-12-05 12:01:04,49 httpServer: starting http server port=8001
[INFO ] 2018-12-05 12:01:04,49 ./wsems: Initializing the ThingWorx REST interface.
[INFO ] 2018-12-05 12:01:04,49 wsEmsProxy::initialize: FIPS is disabled.
[INFO ] 2018-12-05 12:01:04,49 wsEmsProxy::initialize: Encryption is enabled on Web Socket connection.
[WARN ] 2018-12-05 14:01:04,51 SDK: SDK Version: 2.0.4
[WARN ] 2018-12-05 14:01:04,51 SDK: TLS Library: OpenSSL
[WARN ] 2018-12-05 14:01:04,51 SDK: TLS Library Version: 1.0.2l
[WARN ] 2018-12-05 14:01:04,51 SDK: FIPS Capable
[DEBUG] 2018-12-05 14:01:04,51 SDK: twWs_Create: Initializing Websocket Client for pp-1812031303SF.devportal.ptc.io:443//Thingworx/WS
[DEBUG] 2018-12-05 14:01:04,51 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 12:01:04,51 httpServer: http server bound to port=8001.
[DEBUG] 2018-12-05 14:01:04,75 SDK: twApi_Initialize: Websocket Established after 0 tries
[DEBUG] 2018-12-05 14:01:04,75 SDK: subscribedPropsMgr_Initialize: Initializing subscribed properties manager
[INFO ] 2018-12-05 12:01:04,75 WsProxy::initialize: EMS Version 5.4.0.114
[INFO ] 2018-12-05 12:01:04,75 WsProxy::initialize: twApi singleton initialized
[WARN ] 2018-12-05 12:01:04,75 WsProxy::initialize: Certificate validation is disabled.
[WARN ] 2018-12-05 12:01:04,76 WsProxy::initialize: Self signed certificates are enabled.
[DEBUG] 2018-12-05 12:01:04,76 jsonConfigurator::getJsonEntity: Key validation_criteria not found
[DEBUG] 2018-12-05 12:01:04,77 jsonConfigurator::getJsonEntity: Parent file not found
[DEBUG] 2018-12-05 14:01:04,78 SDK: twTunnelManager_Create: Tunnel Manager singleton already exists
[ERROR] 2018-12-05 14:01:04,78 SDK: twMap_Add: parse function returned null.
[DEBUG] 2018-12-05 12:01:04,78 WsEmsProxy::bindThing: Host specified as 'localhost'.  Testing IPV6/IPV4 connectivity
[DEBUG] 2018-12-05 14:01:04,80 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 14:01:04,80 SDK: added PiThing to boundList
[DEBUG] 2018-12-05 14:01:04,80 SDK: twApi_BindThings: not currently connected, only binding things to api
[DEBUG] 2018-12-05 14:01:04,80 SDK: twMessage_Delete:  Deleting BIND Message: 1
[DEBUG] 2018-12-05 12:01:04,80 jsonConfigurator::getJsonEntity: Parent file not found
[INFO ] 2018-12-05 12:01:04,80 wsEmsProxy::initialize: Initialization complete!
[DEBUG] 2018-12-05 12:01:04,81 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:01:04,82 SDK: twTlsServer_Create: Connecting to server
[INFO ] 2018-12-05 12:01:04,82 ./wsems: Starting the connection.

pp-1812031303SF.devportal.ptc.io:443-->[DEBUG] 2018-12-05 14:01:04,83 SDK: twTlsServer_Create: TLS server socket established
[DEBUG] 2018-12-05 14:01:04,83 SDK: twTlsServer_Accept: Client Handshake in progress
[ERROR] 2018-12-05 14:01:04,84 SDK: TW_SSL_ACCEPT: SSL handshake error. Error: error:00000000:lib(0):func(0):reason(0).
[ERROR] 2018-12-05 12:01:04,83 TlsServerStream::doopen: ssl_read returned an error: -1
[DEBUG] 2018-12-05 14:01:04,84 SDK: twTlsClient_Reconnect: Re-establishing SSL context
[ERROR] 2018-12-05 12:01:04,84 httpserver: Server socket error: SSL Handshake Failed [*:56090]
[DEBUG] 2018-12-05 14:01:04,106 SDK: twTlsClient_Connect: Connecting to server
[DEBUG] 2018-12-05 14:01:04,671 SDK: twTlsClient_Connect: TLS connection established
[DEBUG] 2018-12-05 14:01:04,854 SDK: ws_on_headers_complete: Websocket connected!
[INFO ] 2018-12-05 14:01:04,854 SDK: twWs_Connect: Websocket connected!
[DEBUG] 2018-12-05 14:01:04,854 SDK: twWs_SendMessage: Sent 60 bytes using 1 frames.
[DEBUG] 2018-12-05 14:01:05,353 SDK: twMessage_Delete:  Deleting RESPONSE Message: 2
[DEBUG] 2018-12-05 14:01:05,353 SDK: twMessage_Delete:  Deleting AUTH Message: 2
[WARN ] 2018-12-05 14:01:05,353 SDK: twBindBody_Delete: NULL body or stream pointer
[DEBUG] 2018-12-05 14:01:05,353 SDK: twMessage_Delete:  Deleting BIND Message: 3
[DEBUG] 2018-12-05 14:01:05,353 SDK: twWs_SendMessage: Sent 26 bytes using 1 frames.
[DEBUG] 2018-12-05 14:01:05,354 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 12:01:05
[INFO ] 2018-12-05 12:01:05,386 Main: Succesfully connected.  Saving .booted config file
[DEBUG] 2018-12-05 14:01:05,753 SDK: twMessage_Delete:  Deleting RESPONSE Message: 3
[DEBUG] 2018-12-05 14:01:05,753 SDK: twMessage_Delete:  Deleting BIND Message: 3
[DEBUG] 2018-12-05 14:01:06,756 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 14:01:06,758 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 12:01:06,758 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:01:06,758 SDK: twTlsServer_Create: Connecting to server
[DEBUG] 2018-12-05 14:01:06,759 SDK: twTlsServer_Create: TLS server socket established
[DEBUG] 2018-12-05 14:01:06,759 SDK: twTlsServer_Accept: Client Handshake in progress

pp-1812031303SF.devportal.ptc.io:443++>[DEBUG] 2018-12-05 14:02:00,444 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 12:02:00
[ERROR] 2018-12-05 14:02:49,806 SDK: TW_SSL_ACCEPT: SSL handshake error. Error: error:00000000:lib(0):func(0):reason(0).
[ERROR] 2018-12-05 12:02:49,806 TlsServerStream::doopen: ssl_read returned an error: -1
[ERROR] 2018-12-05 12:02:49,806 httpserver: Server socket error: SSL Handshake Failed [*:56094]
[DEBUG] 2018-12-05 14:02:49,807 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 12:02:49,808 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:02:49,808 SDK: twTlsServer_Create: Connecting to server
[DEBUG] 2018-12-05 14:02:49,809 SDK: twTlsServer_Create: TLS server socket established
[DEBUG] 2018-12-05 14:02:49,809 SDK: twTlsServer_Accept: Client Handshake in progress
[DEBUG] 2018-12-05 12:02:49,876 RestThingworx::callback: Handling request
[DEBUG] 2018-12-05 14:02:49,876 SDK: twInfoTable_CreateFromJson: Non-infotable format passed in.  Using single entry '_content_'
[DEBUG] 2018-12-05 12:02:49,876 RestThingworx: Executing request AddEdgeThing
[DEBUG] 2018-12-05 12:02:49,877 WsEmsProxy::bindThing: Host specified as 'localhost'.  Testing IPV6/IPV4 connectivity
[DEBUG] 2018-12-05 14:02:49,879 SDK: added *PiThing to boundList
[WARN ] 2018-12-05 14:02:49,879 SDK: twBindBody_Delete: NULL body or stream pointer
[DEBUG] 2018-12-05 14:02:49,879 SDK: twMessage_Delete:  Deleting BIND Message: 4
[DEBUG] 2018-12-05 14:02:49,896 SDK: twWs_SendMessage: Sent 27 bytes using 1 frames.
[DEBUG] 2018-12-05 14:02:50,296 SDK: twMessage_Delete:  Deleting RESPONSE Message: 4
[DEBUG] 2018-12-05 14:02:50,393 SDK: twMessage_Delete:  Deleting BIND Message: 4
[DEBUG] 2018-12-05 12:02:50,393 jsonConfigurator::getJsonEntity: Parent file not found
[DEBUG] 2018-12-05 12:02:50,393 TlsStream::doclose: Disconeccting socket
[DEBUG] 2018-12-05 14:02:50,394 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:02:50,394 SDK: twTlsClient_Close: Deleting SSL session
[DEBUG] 05/Dec/2018:14:02:50 [+0200] HTTP Server: 0.0.0.0 - SeqId 2 - "POST /Thingworx/Things/LocalEms/Services/AddEdgeThing HTTP/1.1" 200 0 "-"

[DEBUG] 2018-12-05 14:02:50,394 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:02:50,396 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 12:02:50,397 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:02:50,397 SDK: twTlsServer_Create: Connecting to server
[DEBUG] 2018-12-05 14:02:50,398 SDK: twTlsServer_Create: TLS server socket established
[DEBUG] 2018-12-05 14:02:50,398 SDK: twTlsServer_Accept: Client Handshake in progress
[DEBUG] 2018-12-05 12:02:50,456 RestThingworx::callback: Handling request
[DEBUG] 2018-12-05 14:02:50,456 SDK: twInfoTable_CreateFromJson: Non-infotable format passed in.  Using single entry '_content_'
[DEBUG] 2018-12-05 12:02:50,456 RestThingworx: Executing request GetPropertySubscriptions
[DEBUG] 2018-12-05 14:02:50,457 SDK: twMessage_Delete:  Deleting REQUEST Message: 5
[DEBUG] 2018-12-05 14:02:50,494 SDK: twWs_SendMessage: Sent 77 bytes using 1 frames.
[ERROR] 2018-12-05 14:02:50,895 SDK: twMessaging::handleMessage: Response ID 5 has code 160: Entity *PiThing does not exist or is not yet associated with a Thing
[DEBUG] 2018-12-05 14:02:50,895 SDK: twMessage_Delete:  Deleting RESPONSE Message: 5
[DEBUG] 2018-12-05 14:02:50,895 SDK: twMessage_Delete:  Deleting REQUEST Message: 5
[DEBUG] 2018-12-05 12:02:50,895 TlsStream::doclose: Disconeccting socket
[DEBUG] 2018-12-05 14:02:50,896 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:02:50,896 SDK: twTlsClient_Close: Deleting SSL session
[DEBUG] 05/Dec/2018:14:02:50 [+0200] HTTP Server: 0.0.0.0 - SeqId 4 - "POST /Thingworx/Things/*PiThing/Services/GetPropertySubscriptions HTTP/1.1" 500 0 "-"


...



[DEBUG] 2018-12-05 14:03:08,558 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:03:08,559 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 12:03:08,560 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:03:08,560 SDK: twTlsServer_Create: Connecting to server
[DEBUG] 2018-12-05 14:03:08,561 SDK: twTlsServer_Create: TLS server socket established
[DEBUG] 2018-12-05 14:03:08,561 SDK: twTlsServer_Accept: Client Handshake in progress
[DEBUG] 2018-12-05 12:03:08,572 RestThingworx::callback: Handling request
[DEBUG] 2018-12-05 12:03:08,572 RestThingworx: Executing request isConnected
[DEBUG] 2018-12-05 12:03:08,572 TlsStream::doclose: Disconeccting socket
[DEBUG] 2018-12-05 14:03:08,573 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:03:08,573 SDK: twTlsClient_Close: Deleting SSL session
[DEBUG] 05/Dec/2018:14:03:08 [+0200] HTTP Server: 0.0.0.0 - SeqId 48 - "GET /Thingworx/Things/LocalEms/Properties/isConnected HTTP/1.1" 200 154 "-"

[DEBUG] 2018-12-05 14:03:08,573 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:03:10,81 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 12:03:10,82 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:03:10,82 SDK: twTlsServer_Create: Connecting to server
[DEBUG] 2018-12-05 14:03:10,83 SDK: twTlsServer_Create: TLS server socket established
[DEBUG] 2018-12-05 14:03:10,83 SDK: twTlsServer_Accept: Client Handshake in progress
[DEBUG] 2018-12-05 12:03:10,156 RestThingworx::callback: Handling request
[DEBUG] 2018-12-05 14:03:10,157 SDK: twInfoTable_CreateFromJson: Non-infotable format passed in.  Using single entry '_content_'
[DEBUG] 2018-12-05 12:03:10,156 RestThingworx: Executing request RemoveEdgeThing
[DEBUG] 2018-12-05 12:03:10,157 RemoveResourceService: Executing service.
[DEBUG] 2018-12-05 12:03:10,157 WsProxy::unbindThing: Removing Entity *PiThing from binding list
[WARN ] 2018-12-05 14:03:10,158 SDK: twBindBody_Delete: NULL body or stream pointer
[DEBUG] 2018-12-05 14:03:10,158 SDK: twMessage_Delete:  Deleting BIND Message: 16
[DEBUG] 2018-12-05 14:03:10,240 SDK: twWs_SendMessage: Sent 27 bytes using 1 frames.
[DEBUG] 2018-12-05 14:03:10,642 SDK: twMessage_Delete:  Deleting RESPONSE Message: 16
[DEBUG] 2018-12-05 14:03:10,643 SDK: twMessage_Delete:  Deleting BIND Message: 16
[DEBUG] 2018-12-05 12:03:10,642 RemoveResourceService::executeImpl: Checking if binding *PiThing is persisted
[INFO ] 2018-12-05 12:03:10,643 RemoveResourceService: The Edge Thing *PiThing has been removed.
[DEBUG] 2018-12-05 12:03:10,643 TlsStream::doclose: Disconeccting socket
[DEBUG] 2018-12-05 14:03:10,644 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 2018-12-05 14:03:10,644 SDK: twTlsClient_Close: Deleting SSL session
[DEBUG] 05/Dec/2018:14:03:10 [+0200] HTTP Server: 0.0.0.0 - SeqId 50 - "POST /Thingworx/Things/LocalEms/Services/RemoveEdgeThing HTTP/1.1" 200 0 "-"

[DEBUG] 2018-12-05 14:03:10,644 SDK: twTlsClient_Close: Disconnecting from server

A portion of the terminal output was omitted due to character limit, the error was simply repeated until the microserver was shut down. Any help would be appreciated.

Kind regards,

Martin

Rick-Stanley · ‎Dec 05, 2018

Are you using the EMS and LSR downloaded from the guide?

https://developer.thingworx.com/en/resources/guides/thingworx-raspberry-pi-quickstart/install-ems

There have been changes to the default behaviour of the latest EMS

Your config file has entries "myhost" and "mykey" I am assuming those are valid in the config file you are testing

Martin11 · ‎Dec 05, 2018

Hi

I downloaded the EMS file specified in Step 2. of the guide which includes the EMS and LSR files. I am assuming these are latest files unless you can direct me to a different version.

I am indeed using valid entries for the host address and key for the Thingworx server, these are simply placeholders for the file I posted online.

Rick-Stanley · ‎Dec 05, 2018

I was able to connect to free trial instance and send data using these file

config.lua

scripts.log_level = "WARN"

scripts.script_resource_ssl = false
scripts.script_resource_authenticate = false

scripts.rap_host = "127.0.0.1"
scripts.rap_port = 8000

scripts.PiThing = {
 file = "thing.lua",
 template = "PiTemplate",
}

scripts.sample = {
 file = "sample.lua"
}

config.json

{
 "ws_servers": [{
 "host": "pp-18095555451j.portal.ptc.io",
 "port": 443
 }],
 
 
 "appKey": "dda1e0e1-4444-5555-970f-022be713c973",

 "logger": {
 "level":"DEBUG"
 },
 

 "ws_connection": {
 "encryption": "ssl", 
 "verbose": true
 },
 
 "http_server": {

 "ssl": false,
 "authenticate": false
 },
 
 "certificates": {
 "validate": false,
 "allow_self_signed": true
 }

}

Martin11 · ‎Dec 05, 2018

I attempted using your files (replacing the host and appkey values with my own) and I got this response in the terminal.

EMS:

pi@raspberrypi:~/Project/microserver $ sudo ./wsems
[FORCE] 2018-12-05 14:41:20,41 ./wsems: Initializing EMS ....
[FORCE] 2018-12-05 14:41:20,41 main: Using config file /home/pi/Project/microserver/etc/config.json
[INFO ] 2018-12-05 14:41:20,41 ./wsems: Creating the WsEms proxy.
[INFO ] 2018-12-05 14:41:20,41 ./wsems: Starting HTTP Server.
[INFO ] 2018-12-05 14:41:20,42 Main: Using custom certificate and private key for HTTP Server
[WARN ] 2018-12-05 14:41:20,42 Main: Encryption is disabled on HTTP Server.
[WARN ] 2018-12-05 14:41:20,42 Main: Authentication is disabled on the HTTP Server.
[FORCE] 2018-12-05 14:41:20,43 httpServer: starting http server port=8000
[INFO ] 2018-12-05 14:41:20,43 ./wsems: Initializing the ThingWorx REST interface.
[INFO ] 2018-12-05 14:41:20,43 wsEmsProxy::initialize: FIPS is disabled.
[INFO ] 2018-12-05 14:41:20,43 wsEmsProxy::initialize: Encryption is enabled on Web Socket connection.
[WARN ] 2018-12-05 16:41:20,45 SDK: SDK Version: 2.0.4
[WARN ] 2018-12-05 16:41:20,45 SDK: TLS Library: OpenSSL
[WARN ] 2018-12-05 16:41:20,45 SDK: TLS Library Version: 1.0.2l
[WARN ] 2018-12-05 16:41:20,45 SDK: FIPS Capable
[DEBUG] 2018-12-05 16:41:20,45 SDK: twWs_Create: Initializing Websocket Client for pp-1812031303SF.devportal.ptc.io:443//Thingworx/WS
[DEBUG] 2018-12-05 16:41:20,45 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 14:41:20,46 httpServer: http server bound to port=8000.
[DEBUG] 2018-12-05 16:41:20,71 SDK: twApi_Initialize: Websocket Established after 0 tries
[DEBUG] 2018-12-05 16:41:20,71 SDK: subscribedPropsMgr_Initialize: Initializing subscribed properties manager
[INFO ] 2018-12-05 14:41:20,71 WsProxy::initialize: EMS Version 5.4.0.114
[INFO ] 2018-12-05 14:41:20,71 WsProxy::initialize: twApi singleton initialized
[WARN ] 2018-12-05 14:41:20,71 WsProxy::initialize: Certificate validation is disabled.
[WARN ] 2018-12-05 14:41:20,71 WsProxy::initialize: Self signed certificates are enabled.
[DEBUG] 2018-12-05 14:41:20,71 jsonConfigurator::getJsonEntity: Key validation_criteria not found
[DEBUG] 2018-12-05 14:41:20,72 jsonConfigurator::getJsonEntity: Parent file not found
[DEBUG] 2018-12-05 16:41:20,73 SDK: twTunnelManager_Create: Tunnel Manager singleton already exists
[ERROR] 2018-12-05 16:41:20,73 SDK: twMap_Add: parse function returned null.
[DEBUG] 2018-12-05 14:41:20,73 jsonConfigurator::getJsonEntity: Key auto_bind not found
[INFO ] 2018-12-05 14:41:20,73 wsEmsProxy::initialize: Initialization complete!
[INFO ] 2018-12-05 14:41:20,75 ./wsems: Starting the connection.

pp-1812031303SF.devportal.ptc.io:443-->[DEBUG] 2018-12-05 16:41:20,78 SDK: twTlsClient_Reconnect: Re-establishing SSL context
[DEBUG] 2018-12-05 16:41:20,81 SDK: twTlsClient_Connect: Connecting to server
[DEBUG] 2018-12-05 16:41:20,648 SDK: twTlsClient_Connect: TLS connection established
[DEBUG] 2018-12-05 16:41:20,827 SDK: ws_on_headers_complete: Websocket connected!
[INFO ] 2018-12-05 16:41:20,828 SDK: twWs_Connect: Websocket connected!
[DEBUG] 2018-12-05 16:41:20,828 SDK: twWs_SendMessage: Sent 60 bytes using 1 frames.
[DEBUG] 2018-12-05 16:41:21,325 SDK: twMessage_Delete:  Deleting RESPONSE Message: 1
[DEBUG] 2018-12-05 16:41:21,325 SDK: twMessage_Delete:  Deleting AUTH Message: 1
[DEBUG] 2018-12-05 16:41:21,329 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 14:41:21
[INFO ] 2018-12-05 14:41:21,334 Main: Succesfully connected.  Saving .booted config file
[DEBUG] 2018-12-05 16:42:16,370 SDK: sendCtlFrame: >>>>> Sending Ping. Msg: 14:42:16
[DEBUG] 2018-12-05 16:42:39,706 SDK: twTlsClient_Create: Initializing TLS Client
[DEBUG] 2018-12-05 14:42:39,708 TlsServerStream:: doopen: Setting SO_RCVTIMEO
[DEBUG] 2018-12-05 14:42:59,726 TlsStream::doclose: Disconeccting socket
[DEBUG] 2018-12-05 16:42:59,726 SDK: twTlsClient_Close: Disconnecting from server
[DEBUG] 05/Dec/2018:16:42:59 [+0200] HTTP Server: 1.0.0.127 - SeqId 2 - "" 400 375 "-"

[DEBUG] 2018-12-05 16:42:59,727 SDK: twTlsClient_Close: Disconnecting from server

The microserver does seem to successfully connect to the ThingWorx server but I strangely cannot see any unbound devices in the web interface. Afterwards I ran the LSR and had the following output.

The Lua script had the following output:

pi@raspberrypi:~/Project/microserver $ sudo ./luaScriptResource
[INFO ] 2018-12-05 14:42:37,614 ./luaScriptResource: Using config file: /home/pi/Project/microserver/etc/config.lua
[FORCE] 2018-12-05 14:42:37,615 ./luaScriptResource: Starting up ....

[WARN ] 2018-12-05 14:42:37,625 ScriptResource::initialize: Encryption is disabled on HTTP Server.
[WARN ] 2018-12-05 14:42:37,625 ScriptResource::initialize: Authentication is disabled on the HTTP Server.
[FORCE] 2018-12-05 14:42:37,705 httpServer: starting http server port=8001

I'm unsure if this is the expected output. Am I perhaps making some sort of fundamental mistake with my setup? Thank you for your help thus far, unfortunately I will only be back online tomorrow due to timezone differences.

Kind Regards

Martin

wposner-2 · ‎Dec 05, 2018

I've had similar errors when dealing with remote properties. I'm not sure if this is your issue, but In TWX 8.3 there seems to be a bug with changing the name of a remote property. I don't know how to replicate it, and whether it's specific to remote properties declared on a thing shape vs directly on the thing template. But you'll know if you've been bitten by the bug if

1) you have changed the name of a remote property

2) you start getting 500 errors when your EMS calls GePropertySubscriptions

The fix is to export your thing template, find the remote property section and then find the XML elements containing your old AND new remote property names. Delete the old instance of your remote property, save, and re-import.

For some reason, when making a change to a remote property name, the change is getting saved to the template but not removing the old instance of the remote property name. This causes a bunch of errors to appear in the Application log and will also cause the 500 error when GetPropertySubscriptions runs.

Martin11 · ‎Dec 06, 2018

I deleted the thing I created before. The problem I am facing at the moment is to get an unbounded remote thing to show up when I start up the EMS.

Are you referring to the RemoteThing template?

KedarK · ‎Mar 21, 2019

Hello Martin,

Which user you have selected while creating Application Key.

Select Administrator as a user. It worked for me.

Though it is not recommended to set Administrator as a user, you may set it for testing purpose.

For further details about the user for application key, you can check the documentation.

Also, check properties are bind correctly.

Please check and mark this reply as a solution if worked.

Regards,

Kedar K.