[RaspberryPi Tutorial] Unable to connect LSR to EMS

[skämpfer]

Hi everybody,

I'm currently working my way into the ThingWorx ecosystem and I am currently stuck on the Raspberry Pi Quickstart Guide when trying to connect the Lua Script Ressource to the running Edge Micro Server (Step 10).

I am connecting to a ThingWorx Foundation Server from the Developer Portal which works just fine. But when I try to start the LSR I get connection errors. Guessing from the log entries the LSR works find but fails when trying to connect to the local EMS.

To not bloat this discussion I have attached a full trace log of WSEMS as well as LSR. Below you can find extracts of both logs which I found most useful for the problem at hand.

The most prominent lines from the WSEMS log are the following:

[TRACE] 2016-12-20 14:22:05,301 SDK: twWs_Receive: Received Pong

[TRACE] 2016-12-20 14:22:05,301 SDK: msgHandlerOnPong: Received Pong.  Data: 13:22:05

[DEBUG] 2016-12-20 14:22:35,525 SDK: twTlsClient_Create: Initializing TLS Client

[DEBUG] 2016-12-20 14:22:35,525 TlsStream:: doopen: Setting SO_RCVTIMEO

[TRACE] 2016-12-20 14:22:35,525 TlsStream:: doopen: Non-SSL server socket opened

[TRACE] 2016-12-20 14:22:35,525 httpServer: Allocating new client: 1

[TRACE] 2016-12-20 14:22:35,525 client_thread::execute: Starting request handler thread 2

[DEBUG] 2016-12-20 14:22:35,525 RestThingworx::callback: Handling request

[DEBUG] 2016-12-20 14:22:35,526 SDK: twInfoTable_CreateFromJson: Non-infotable format passed in.  Using single entry '_content_'

[DEBUG] 2016-12-20 14:22:35,526 RestThingworx: Executing request AddEdgeThing

[TRACE] 2016-12-20 14:22:35,526 jsonConfigurator::getString: Key = host, Parent = rest_interface

[TRACE] 2016-12-20 14:22:35,526 jsonConfigurator::getValueByType: Parent rest_interface not found

[DEBUG] 2016-12-20 14:22:35,526 WsEmsProxy::bindThing: Host specified as 'localhost'.  Testing IPV6/IPV4 connectivity

[TRACE] 2016-12-20 14:22:35,527 WsEmsProxy::bindThing: Adding Thing PiThing to binding list

[DEBUG] 2016-12-20 14:22:35,527 WsEmsProxy::bindThing: Entity PiThing already in Binding list.  Updating info.

[DEBUG] 2016-12-20 14:22:35,527 jsonConfigurator::getJsonEntity: Parent file not found

[TRACE] 2016-12-20 14:22:35,527 RestThingworx: Responding with content:

[DEBUG] 2016-12-20 14:22:35,527 TlsStream::doclose: Disconeccting socket

[DEBUG] 2016-12-20 14:22:35,528 SDK: twTlsClient_Close: Disconnecting from server

[DEBUG] 2016-12-20 14:22:35,528 [+0100] HTTP Server: 0.0.0.0 - SeqId 2 - "POST /Thingworx/Things/LocalEms/Services/AddEdgeThing HTTP/1.1" 200 0 "-"

[DEBUG] 2016-12-20 14:22:35,528 SDK: twTlsClient_Close: Disconnecting from server

[DEBUG] 2016-12-20 14:22:35,530 SDK: twTlsClient_Create: Initializing TLS Client

[DEBUG] 2016-12-20 14:22:35,530 TlsStream:: doopen: Setting SO_RCVTIMEO

[TRACE] 2016-12-20 14:22:35,530 TlsStream:: doopen: Non-SSL server socket opened

[TRACE] 2016-12-20 14:22:35,530 httpServer: Allocating new client: 3

[TRACE] 2016-12-20 14:22:35,531 client_thread::execute: Starting request handler thread 4

[DEBUG] 2016-12-20 14:22:35,531 RestThingworx::callback: Handling request

[DEBUG] 2016-12-20 14:22:35,531 SDK: twInfoTable_CreateFromJson: Non-infotable format passed in.  Using single entry '_content_'

[DEBUG] 2016-12-20 14:22:35,531 RestThingworx: Executing request GetPropertySubscriptions

[TRACE] 2016-12-20 14:22:35,531 SDK: Sending Msg >>>>>>>>>

Message Details:

Version: 1

Method/Code: 0x3 (POST)

RequestID: 3

EndpointID:0

SessionID: 11

Multipart: 0

EntityType: THING

EntityName: PiThing

CharacteristicType: SERVICES

CharateristicName: GetPropertySubscriptions

Parameter Type: INFOTABLE

DataShape:

   Name:        _content_ BaseType: JSON

Row 1:

   BaseType:      JSON Value: {} Length: 2

[DEBUG] 2016-12-20 14:22:35,600 SDK: twWs_SendMessage: Sent 76 bytes using 1 frames.

[TRACE] 2016-12-20 14:22:35,600 SDK: Sent Message >>>>

01 03 00 00 00 03 00 00 00 00 00 00 00 0B 00 0A 07 50 69 54 68 69 6E 67 02 18 47 65 74 50 72 6F 70 65 72 74 79 53 75 62 73 63 72 69 70 74 69 6F 6E 73 00 05 01 09 5F 63 6F 6E 74 65 6E 74 5F 00 08 00 00 00 01 00 01 08 02 7B 7D 00

[TRACE] 2016-12-20 14:22:35,600 SDK: twMessage_Send: Message with RequestId 3 sent successfully

[TRACE] 2016-12-20 14:22:35,716 SDK: twWs_Receive: Read 2 bytes into header buffer

[TRACE] 2016-12-20 14:22:35,716 SDK: twWs_Receive: Got Header: Body length = 85

[TRACE] 2016-12-20 14:22:35,716 SDK: twWs_Receive: Header Data:

82 55

[TRACE] 2016-12-20 14:22:35,716 SDK: twWs_Receive: Read 85 bytes into Frame buffer

[TRACE] 2016-12-20 14:22:35,717 SDK: twWs_Receive: Got Body:

01 A0 00 00 00 03 00 00 00 00 FF FF FF FF 00 01 43 45 6E 74 69 74 79 20 50 69 54 68 69 6E 67 20 64 6F 65 73 20 6E 6F 74 20 65 78 69 73 74 20 6F 72 20 69 73 20 6E 6F 74 20 79 65 74 20 61 73 73 6F 63 69 61 74 65 64 20 77 69 74 68 20 61 20 54 68 69 6E 67 FF

[TRACE] 2016-12-20 14:22:35,717 SDK: twWs_Receive: Received Binary Message in Single Frame

[TRACE] 2016-12-20 14:22:35,717 SDK: msgHandlerOnBinaryMessage: Rcvd Message <<<<

01 A0 00 00 00 03 00 00 00 00 FF FF FF FF 00 01 43 45 6E 74 69 74 79 20 50 69 54 68 69 6E 67 20 64 6F 65 73 20 6E 6F 74 20 65 78 69 73 74 20 6F 72 20 69 73 20 6E 6F 74 20 79 65 74 20 61 73 73 6F 63 69 61 74 65 64 20 77 69 74 68 20 61 20 54 68 69 6E 67 FF

[TRACE] 2016-12-20 14:22:35,717 SDK: msgHandlerOnBinaryMessage: Inserting message onto queue. ID: 3, Type: 2

[TRACE] 2016-12-20 14:22:35,721 SDK: twMessageHandler_msgHandlerTask: Received Binary Message ID: 3

[TRACE] 2016-12-20 14:22:35,721 SDK: Recv'd Msg <<<<<<<<<

Message Details:

Version: 1

Method/Code: 0xa0 (INTERNAL_SERVER_ERROR)

RequestID: 3

EndpointID:0

SessionID: -1

Multipart: 0

Reason: Entity PiThing does not exist or is not yet associated with a Thing

Result Type: UNKNOWN

The most prominent lines from the LSR log are the following:

[TRACE] 2016-12-20 14:22:51,393 HttpResponse::on_message_begin: Response started

[TRACE] 2016-12-20 14:22:51,393 HttpResponse::on_message_complete: Response complete.  Code: 200 Reason:

[DEBUG] 2016-12-20 14:22:51,393 TlsStream::doclose: Disconeccting socket

[DEBUG] 2016-12-20 14:22:51,393 SDK: twTlsClient_Close: Disconnecting from server

[TRACE] 2016-12-20 14:22:51,393 HttpClient::processReq: Response received. Response code = 200

[TRACE] 2016-12-20 14:22:51,393 HttpResponse::getBody: Attempting to read body as single string. m_contentLength: 154

[TRACE] 2016-12-20 14:22:51,393 HttpResponse::getBody: Read body as single string. m_body: {"rows":[{"isConnected":true}],"datashape":{"fieldDefinitions":{"isConnected":{"name":"isConnected","description":"","baseType":"BOOLEAN","aspects":{}}}}}

[DEBUG] 2016-12-20 14:22:51,393 SDK: twTlsClient_Close: Disconnecting from server

[INFO ] 2016-12-20 14:22:51,394 PiThing: EMS is available: true, online: true

[INFO ] 2016-12-20 14:22:51,394 PiThing: Attempting to GetPropertySubscriptions from server failed. code: 500, result:

[TRACE] 2016-12-20 14:22:51,394 PiThing: Attempting to set property upToDate

[TRACE] 2016-12-20 14:22:51,395 PiThing: Found handler inmemory

[DEBUG] 2016-12-20 14:22:51,395 PiThing: Wrote property: upToDate Updated updateTime to 4294967295

[TRACE] 2016-12-20 14:22:51,395 setProperty: Code: 200 Msg nil

[TRACE] 2016-12-20 14:22:51,395 GetPropertySubscriptions: Code: 500 Msg Attempting to GetPropertySubscriptions from server failed. code: 500, result:

Any help is appreciated!

Best regards,

Sebastian

[ttielebein]

It actually looks like the LSR is connected to the EMS here: [INFO ] 2016-12-20 14:22:51,394 PiThing: EMS is available: true, online: true

I don't know if connectivity is the problem. It seems there is some issue with GetPropertySubscriptions... there is no actual error here though. When you go to a remote thing within Composer and go to the properties tab, if you click "Manage Bindings" and then select the "Remote" tab, do you see properties appear there? Or is there an error?

[skämpfer]

Hi Tori,

you are right. I think I got distracted by the info message

[INFO ] 2016-12-20 14:22:51,389 PiThing: Error occured while accessing EMS. Checking isConnected.

which you can find in the full trace log.

It's not until tomorrow morning that I'll get my hands on the Pi to check for possible data transmission following your advice. Another question regarding this: Beside the possibility to check for remote property bindings in the properties tab of a remote thing as you suggested, should I also be able to see the data popping up in the ThingworxMonitor under the "Unbound" Remote Things tab?

[Aanjan]

Sebastian, going by your logs, I'm assuming your Remote Thing is called PiThing. Can you try adding an identifier in your config.lua, something on the lines of  identifier = "PiThing", within your PiTemplate section? With this, we can force an identifier for the lua to connect to.

So, the next time you run the wsems and luaScriptResource, you should be able to hit the 'browse' button in the 'General Information' section of your Remote Thing and select PiThing (forcing the LSR to bind to PiThing).

[ehalvordsson]

I had the same problem today. My RPi complained about "GetPropertySubscriptions" as well but in my case I had set up an application key that was not associated to a user with an administrator level. So basically my edge thing was not able to run a POST to execute the GetPropertySubscriptions and that is why it failed. The solution in this case was to make sure the application key had the right authority.

[berik]

I was seeing the same problem and , per your note, I changed to an admin level user on the app key and it worked. Thanks!

[skämpfer]

Hello Aanjan,

first of all thank you for your advice as well.

I have now set up a local Thingworx Foundation server to eliminate possible problems caused by the underlying network. So now I have got only the Foundation server and the Pi attached to a local router.

Tori Tielebein: I have followed your instructions, but without success. I have created a new thing based on the RemoteThing template. Under Properties when I click Manage Bindings and select Remote it gives me the message: "Loading... Error browsing properties. Be sure the remote device/server is connected and configured properly". Even though I see the PiThing in my Thingworx Monitor as a Unbound Thing.

Aanjan Ravi​: I have tried your advice which worked partially. My config.lua file looks like the following:

scripts.log_level = "TRACE"

scripts.PiThing = {

    file = "thing.lua",

    template = "PiTemplate",

    identifier = "PiThing",

    scanrate = 1000,

    taskrate = 30000

}

scripts.rap_host = "localhost"

scripts.rap_port = 8080

Running WSEMS and LRS with this configuration gives me different results. First of all now I see 2 PiThing​s in the Thingworx Monitor. One with the "Is Identifier" checkbox checked and one unchecked. The output of WSEMS and LSR (which i have attached as well) are slightly different, but still show the HTTP 500 error.

With this setup I can actually bind the properties of my PiThing (cpu_temperature, cpu_freq, cpu_volt) to a RemoteThing within Thingworx Composer via the Manage Bindings menu, but the values stay blank.

[Aanjan]

Can you post your config.json and config.lua (minus your server and appKey info)?

[skämpfer]

I have attached the files config.json, config.lua and PiTemplates. All of these should be exactly as stated in the tutorial except the connection data and app key of course.

[rwiseman]

Did you ever get to the bottom of this?  I'm having similar problems.

[Aanjan]

Just to isolate your issue from Richards', can you try typing PiThing on the Identifier section on your Remote Thing?

[skämpfer]

Hello Aanjan,

I already did, please see my post from December 22. I also explained the effects of this change, but it didn't help to solve the problem.

[Aanjan · Accepted solution]

Ah I meant actually typing out PiThing on the identifier section on your Thing, saving the Thing and then trying out Manage Bindings to rule out couple issues.

[skämpfer]

So, I have made some interesting but odd observations. Like you said, Aanjan, I created a Thing called "MyPiThing" in the Composer which is based on the RemoteThing template. In the Identifier text box I inserted 'PiThing'. Running this configuration did not provide any change with the problem.

Now comes the interesting part: In my lua config file I the extended the scripts.PiThing object with the property 'identifier = "PiThing"'. Running wsems and luaScriptResource with this configuration obviously did the thing because now the communication between Foundation server, EMS and Lua script finally seems to work.

I have attached an archive containing the trace logs of the EMS and Lua scripts as well as some screenshots from the Composer and Monitor.

Some strange things that i noticed: My PiThing is shown as a bound and an unbound thing? Is this a normal behaviour? (see screenshots).

So, can I ascertain that the Raspberry Pi tutorial is somewhat oudated? There, the creation of a new Thing inside Composer is explicitly done after the Pi sends its data to the server.

[rwiseman]

I got the impression that if you specify an identifier in the Lua config, the Remote Thing tries to bind to a Thing with the same identifier.  If there's no Thing with the same identifier, the Remote Thing remains unbound.  If there's no identifier specified in the Lua config, it tries to bind to a Thing with the same name as in the Lua config, and if that's not found, it remains unbound.

Does that sound correct?

[skämpfer]

That's what I would assume, too, but my observations were different as stated above. May I ask if you encountered the exact same problem, Richard? If so, do you succeed as well in transfering the values with the approach I described?

[rwiseman]

I don't know if my problem was exactly the same, but it was certainly very similar.  I saw both bound and unbound remote entities, and sometimes the bound ones weren't properly bound (they had an exclamation mark rather than a tick next to them).

What fixed it for me was to remove the identifier stuff completely and just make sure that the name of my Thing matched that in the Lua config file.

[wwang-21]

hello，Aanjan

When running wsems EMS can connect to the platform but appears this problem

[ERROR] 2017-02-22 03:39:20,806 emsRequestHandler: Thing not bound to EMS, or host is not set

why?

Hope you can help me

[Aanjan]

WangNi, do you have an auto_bind section defined in your config.json? You would get this message if you're connecting the EMS to your platform, but don't have it associated with a Thing yet.

[wwang-21]

hi Aanjan,

but The platform can read the properties

Can not refresh