TheThingSystem / node-thing-client

A node.js module to interface with TheThingSystem steward, as a thing
MIT License
2 stars 4 forks source link

Error: "UDN is already registered" #5

Closed jdevelvis closed 10 years ago

jdevelvis commented 10 years ago

I'm trying to solidify my STP client, and I'm so close. I'm able to pair and communicate with a fresh client (or if I randomize my UDN/UUIDs to trick it into thinking it's a new thing every time it loads) but when I run my same script twice the first time it successfully pairs and communicates, but the second time it errors out and says the UDN is already registered.

Here's the send/recv log from the communication -

First Run: Successful pair/communication

>>> send: {"path":"/api/v1/thing/pair/JadeWidget1","name":"JadeWidget1","requestID":1}
>>> recv: {"requestID":"1","timestamp":1398915608}
>>> recv: {"requestID":"1","result":{"params":{"algorithm":"sha1","length":40,"name":".things@steward","issuer":"steward","step":30,"base32":"M5MGCRSVLA4TOTK2...UCSONFEEN2U","protocol":"totp"},"success":true,"thingID":"1"},"timestamp":1398915611}
>>> send: {"path":"/api/v1/thing/hello/1","response":"112499","requestID":2}
>>> recv: {"requestID":"2","result":{"uuid":"2f402f80-da50-11e1-9b23-0013efd023ef:things","name":".things","comments":"simple thing protocol client","lastLogin":null,"client":{"uuid":"2f402f80-da50-11e1-9b23-0013efd023ef:things","name":"JadeWidget1","comments":"","lastLogin":null,"thingID":".things/1"},"success":true},"timestamp":1398915612}
Sending prototype message: {
    "/device/sensor/Jade/Widget": {
        "device": {
            "name": "Jade Widget",
            "maker": "Jade Automation, LLC"
        },
        "observe": [
            "voice"
        ],
        "perform": [
            "speak"
        ],
        "name": true,
        "status": [
            "ready",
            "standby",
            "busy"
        ],
        "properties": {
            "command": "text"
        },
        "validate": {
            "observe": false,
            "perform": true
        }
    }
}
>>> send: {"path":"/api/v1/thing/prototype","things":{"/device/sensor/Jade/Widget":{"device":{"name":"Jade Widget","maker":"Jade Automation, LLC"},"observe":["voice"],"perform":["speak"],"name":true,"status":["ready","standby","busy"],"properties":{"command":"text"},"validate":{"observe":false,"perform":true}}},"requestID":3}
>>> recv: {"requestID":"3","things":{"/device/sensor/Jade/Widget":{"success":true}}}
Sending registration message: {
    "t1": {
        "devicetype": "/device/sensor/Jade/Widget",
        "name": "Jade Widget",
        "status": "standby",
        "device": {
            "name": "Jade Widget",
            "maker": "Jade Automation, LLC",
            "unit": {
                "serial": "...",
                "udn": "JadeWidget00000000f170369b"
            }
        },
        "updated": 1398915604356,
        "info": {
            "command": ""
        }
    }
}
>>> send: {"path":"/api/v1/thing/register","things":{"t1":{"devicetype":"/device/sensor/Jade/Widget","name":"Jade Widget","status":"standby","device":{"name":"Jade Widget","maker":"Jade Automation, LLC","unit":{"serial":"...","udn":"JadeWidget00000000f170369b"}},"updated":1398915604356,"info":{"command":""}}},"requestID":4}
>>> recv: {"requestID":"4","things":{"t1":{"success":true,"thingID":"14460309"}}}
{ requestID: '4',
  things: { t1: { success: true, thingID: '14460309' } } }
Ready...

Second run: UDN error at the bottom

>>> send: {"path":"/api/v1/thing/hello/1","response":"858650","requestID":1}
>>> recv: {"requestID":"1","result":{"uuid":"2f402f80-da50-11e1-9b23-0013efd023ef:things","name":".things","comments":"simple thing protocol client","lastLogin":"2014-05-01T03:40:11.536Z","client":{"uuid":"2f402f80-da50-11e1-9b23-0013efd023ef:things","name":"JadeWidget1","comments":"","lastLogin":"2014-05-01T03:40:11.536Z","thingID":".things/1"},"success":true},"timestamp":1398915726}
Sending prototype message: {
    "/device/sensor/Jade/Widget": {
        "device": {
            "name": "Jade Widget",
            "maker": "Jade Automation, LLC"
        },
        "observe": [
            "voice"
        ],
        "perform": [
            "speak"
        ],
        "name": true,
        "status": [
            "ready",
            "standby",
            "busy"
        ],
        "properties": {
            "command": "text"
        },
        "validate": {
            "observe": false,
            "perform": true
        }
    }
}
>>> send: {"path":"/api/v1/thing/prototype","things":{"/device/sensor/Jade/Widget":{"device":{"name":"Jade Widget","maker":"Jade Automation, LLC"},"observe":["voice"],"perform":["speak"],"name":true,"status":["ready","standby","busy"],"properties":{"command":"text"},"validate":{"observe":false,"perform":true}}},"requestID":2}
>>> recv: {"requestID":"2","things":{"/device/sensor/Jade/Widget":{"success":true,"diagnostic":"previously defined"}}}
Sending registration message: {
    "t1": {
        "devicetype": "/device/sensor/Jade/Widget",
        "name": "Jade Widget",
        "status": "standby",
        "device": {
            "name": "Jade Widget",
            "maker": "Jade Automation, LLC",
            "unit": {
                "serial": "...",
                "udn": "JadeWidget00000000f170369b"
            }
        },
        "updated": 1398915720300,
        "info": {
            "command": ""
        }
    }
}
>>> send: {"path":"/api/v1/thing/register","things":{"t1":{"devicetype":"/device/sensor/Jade/Widget","name":"Jade Widget","status":"standby","device":{"name":"Jade Widget","maker":"Jade Automation, LLC","unit":{"serial":"...","udn":"JadeWidget00000000f170369b"}},"updated":1398915720300,"info":{"command":""}}},"requestID":3}
>>> recv: {"requestID":"3","things":{"t1":{"error":{"permanent":false,"diagnostic":"UDN is already registered"}}}}
{ requestID: '3',
  things: { t1: { error: { permanent: false, diagnostic: 'UDN is already registered' } } } }
registration: {"error":{"permanent":false,"diagnostic":"UDN is already registered"}}

Exactly the same code, except I do new ThingAPI.ThingAPI with the state present the second time around. Here's the state JSON:

{
        "thingID": "1",
        "params": {
            "algorithm": "sha1",
            "length": 40,
            "name": ".things@steward",
            "issuer": "steward",
            "step": 30,
            "base32": "M5MGCRSVLA...3CPM5SDCUCSONFEEN2U",
            "protocol": "totp"
        }
    }

The thing I find strange is the "name":".things@steward" piece. That's not anywhere in my code that I can find. Doesn't show up until the initial pairing response from the steward.

Same thing happens when I run the test.js code once without the state JSON, then once after pasting in the state that gets returned the first time.

What diagnostics do you need me to do to help? Without hours to devote to digging in, I can't make heads nor tales of much of the api code in the steward... Not enough comments :) So I'm hoping I can give you the info necessary to track down what's going on. Thanks!

jdevelvis commented 10 years ago

The issue I'm running into happens when I run my code then kill it and run it again. The 1st time I run it after rebooting the steward, it works. The second time I run it, I get the UDN already registered error. I'm guessing the steward sends that back because it thinks this thing is already present. Perhaps it's a websocket timeout/disconnect issue?

aallan commented 10 years ago

I'm guessing—or at least the most likely thing it could be—is that your code is sending the pairing message for a second time when it boots up? That's a one-time only thing, not on every boot, see http://thethingsystem.com/dev/Simple-Thing-Protocol.html.

jdevelvis commented 10 years ago

I'm using the thing-client module, and it looks like it's only pairing the first time. Check out the 2nd run JSON messages above, it sends the hello message, then goes right into prototype & register.

I even tried running against a fresh Steward (successful connection), then killing it and running again (UDN already registered) then restarting the steward again (successful connection). Same code, same UDN.

I did resolve the "name":".things@steward" strangeness, though, so that's good.

jdevelvis commented 10 years ago

Just tested it out with test.js, here are my results -

Step 1) ran "node test.js" - paired and connected just fine 2) stopped the process 3) replaced null with the state JSON in test.js 4) ran "node test.js" again, resulting in a UDN is already registered message. 5) restarted the Steward with "sudo sh /etc/init.d/steward restart" 6) ran "node test.js" again with the state JSON. No UDN already registered error this time. 7) stopped the process 8) ran "node test.js" again - error is back.

Only change I made is when I replaced null with the state in Step 2. I didn't modify any code after that.

Edit for completion's sake: Forgot to mention I removed the crtFile bit from the test.js file, before Step 1 - just connecting via developer mode.

mrose17 commented 10 years ago

the very first time you run test.js, it will print out state information. you then edit test.js, comment out pairing, and insert the state information, e.g.,

    new ThingAPI.ThingAPI(
    { steward : { crtPath   : 'server.crt' }
    /*
    , pairing : { thingUUID : 'testing1'
                }
    , state   : null
     */
    , state : {"thingID":"11"
              ,"params: {"algorithm":"sha1","length":40,"name":".things@steward","issuer":"steward","step":30,"base32":"…..","protocol":"totp"}}
    }).on('paired', function(state) {
jdevelvis commented 10 years ago

Didn't help - I commented out the pairing element, so it's only sending the steward & state elements. Then I ran it the first time and it gave me:

>>> send: {"path":"/api/v1/thing/hello/8","response":"149722","requestID":1}
>>> recv: {"requestID":"1","result":{"uuid":"2f402f80-da50-11e1-9b23-0013efd023ef:things","name":".things","comments":"simple thing protocol client","lastLogin":"2014-05-04T11:01:45.214Z","client":{"uuid":"testing5","name":"testing5","comments":"","lastLogin":"2014-05-04T02:06:41.481Z","thingID":".things/8"},"success":true},"timestamp":1399201404}
>>> send: {"path":"/api/v1/thing/prototype","things":{"/device/sensor/macguffin/sound":{"device":{"name":"All-Ears Noise Detector","maker":"Macguffin Industries, Ltd."},"observe":["motion"],"perform":["speak"],"name":true,"status":["quiet","noisy"],"properties":{"noise":"db","threshold":"db"},"validate":{"observe":true,"perform":true}}},"requestID":2}
>>> recv: {"requestID":"2","things":{"/device/sensor/macguffin/sound":{"success":true,"diagnostic":"previously defined"}}}
>>> send: {"path":"/api/v1/thing/register","things":{"t1":{"devicetype":"/device/sensor/macguffin/sound","name":"Living Room noise sensor","status":"quiet","device":{"name":"All-Ears Noise Detector","maker":"Macguffin Industries, Ltd.","unit":{"serial":"...","udn":"5eb160e4-e770-4e97-b8ef-dd89aa0a80ed3"}},"updated":1399201403059,"info":{"noise":20,"threshold":35}}},"requestID":3}
>>> recv: {"requestID":"3","things":{"t1":{"success":true,"thingID":"79348296"}}}
{ requestID: '3',
  things: { t1: { success: true, thingID: '79348296' } } }
>>> getToWork: thingID=79348296

Then I did ctrl+z to kill it and ran it again, and got:

>>> send: {"path":"/api/v1/thing/hello/8","response":"210103","requestID":1}
>>> recv: {"requestID":"1","result":{"uuid":"2f402f80-da50-11e1-9b23-0013efd023ef:things","name":".things","comments":"simple thing protocol client","lastLogin":"2014-05-04T11:03:23.802Z","client":{"uuid":"testing5","name":"testing5","comments":"","lastLogin":"2014-05-04T11:03:23.802Z","thingID":".things/8"},"success":true},"timestamp":1399201415}
>>> send: {"path":"/api/v1/thing/prototype","things":{"/device/sensor/macguffin/sound":{"device":{"name":"All-Ears Noise Detector","maker":"Macguffin Industries, Ltd."},"observe":["motion"],"perform":["speak"],"name":true,"status":["quiet","noisy"],"properties":{"noise":"db","threshold":"db"},"validate":{"observe":true,"perform":true}}},"requestID":2}
>>> recv: {"requestID":"2","things":{"/device/sensor/macguffin/sound":{"success":true,"diagnostic":"previously defined"}}}
>>> send: {"path":"/api/v1/thing/register","things":{"t1":{"devicetype":"/device/sensor/macguffin/sound","name":"Living Room noise sensor","status":"quiet","device":{"name":"All-Ears Noise Detector","maker":"Macguffin Industries, Ltd.","unit":{"serial":"...","udn":"5eb160e4-e770-4e97-b8ef-dd89aa0a80ed3"}},"updated":1399201413894,"info":{"noise":20,"threshold":35}}},"requestID":3}
>>> recv: {"requestID":"3","things":{"t1":{"error":{"permanent":false,"diagnostic":"UDN is already registered"}}}}
{ requestID: '3',
  things: { t1: { error: { permanent: false, diagnostic: 'UDN is already registered' } } } }
registration: {"error":{"permanent":false,"diagnostic":"UDN is already registered"}}
GuySawyer commented 10 years ago

I'm not really sure where this problem is coming from. In my case, the udn is also already registered I guess, but it successfully registers on second run.

mrose17 commented 10 years ago

this is what i'm doing. the first time that it runs, pairing is there and state is not. the second time that it runs, pairing is not there and state is filled-in from the output of the first run.

    mrose% node test.js
    >>> send: {"path":"/api/v1/thing/pair/testing1","name":"testing1","requestID":1}
    >>> recv: {"requestID":"1","timestamp":1399274943}
    >>> recv: {"requestID":"1","result":{"params":{"algorithm":"sha1","length":40,"name":".things@arden-arcade","issuer":"arden-arcade","step":30,"base32":"GZKHK3KKIVFEGSLQOBFW22LGJJTGIQ2TJ4YG222XJZSTA4ZWKB3HGSKLHB3HIZ2K","protocol":"totp"},"success":true,"thingID":"11"},"timestamp":1399274943}
    paired state={"thingID":"11","params":{"algorithm":"sha1","length":40,"name":".things@arden-arcade","issuer":"arden-arcade","step":30,"base32":"GZKHK3KKIVFEGSLQOBFW22LGJJTGIQ2TJ4YG222XJZSTA4ZWKB3HGSKLHB3HIZ2K","protocol":"totp"}}
    ...
    >>> getToWork: thingID=53520646
    ^C

    // edit test.js

    mrose% fgrep state test.js | head -1
    , state   : {"thingID":"11","params":{"algorithm":"sha1","length":40,"name":".things@arden-arcade","issuer":"arden-arcade","step":30,"base32":"GZKHK3KKIVFEGSLQOBFW22LGJJTGIQ2TJ4YG222XJZSTA4ZWKB3HGSKLHB3HIZ2K","protocol":"totp"}}

    mrose% node test.js
    >>> send: {"path":"/api/v1/thing/hello/11","response":"032892","requestID":1}
    >>> recv: {"requestID":"1","result":{"uuid":"2f402f80-da50-11e1-9b23-14109fe5a283:things","name":".things","comments":"simple thing protocol client","lastLogin":"2014-05-05T07:30:20.142Z","client":{"uuid":"2f402f80-da50-11e1-9b23-14109fe5a283:things","name":"testing1","comments":"","lastLogin":"2014-05-05T07:30:20.142Z","thingID":".things/11"},"success":true},"timestamp":1399275052}
    >>> send: {"path":"/api/v1/thing/prototype","things":{"/device/sensor/macguffin/sound":{"device":{"name":"All-Ears Noise Detector","maker":"Macguffin Industries, Ltd."},"observe":["motion"],"perform":["speak"],"name":true,"status":["quiet","noisy"],"properties":{"noise":"db","threshold":"db"},"validate":{"observe":true,"perform":true}}},"requestID":2}
    >>> recv: {"requestID":"2","things":{"/device/sensor/macguffin/sound":{"success":true,"diagnostic":"previously defined"}}}
    >>> send: {"path":"/api/v1/thing/register","things":{"t1":{"devicetype":"/device/sensor/macguffin/sound","name":"Living Room noise sensor","status":"quiet","device":{"name":"All-Ears Noise Detector","maker":"Macguffin Industries, Ltd.","unit":{"serial":"...","udn":"5eb160e4-e770-4e97-b8ef-dd89aa0a80ed"}},"updated":1399275051437,"info":{"noise":20,"threshold":35}}},"requestID":3}
    >>> recv: {"requestID":"3","things":{"t1":{"success":true,"thingID":"56966176"}}}
    { requestID: '3',
      things: { t1: { success: true, thingID: '56966176' } } }
    >>> getToWork: thingID=56966176
    ^C
jdevelvis commented 10 years ago

I didn't think about this before, but it looks like the issue is between me using ctrl+z and you using ctrl+c.

I've been doing ctrl+z, which is killing the process before ws can close the socket. That has to be why it's telling me it's already registered, because it actually is... I tested it out with ctrl+c and it worked with no problems!

I also experimented a bit more - issuing sudo reboot while test.js is running gives it a chance to kill the socket, so it's fine when it boots back up. But unplugging the Pi that is running test.js (to simulate a power outage) gives me the UDN is already registered message when I try running test.js after the Pi boots back up.

That will present a problem for things using STP, not only after power outages, but also if the user unplugs a device to move it to another place in the room, then plugs it back in. It's not going to be able to connect when it boots back up. This will likely present a problem if the thing crashes and has to reboot as well.

Give it a try with ctrl+z and unplugging the device both. I think that'll give you the error I'm looking at.

Two thoughts on how to address this -

mrose17 commented 10 years ago

thanks for figuring this out.

when you suspend a process, that doesn't prevent the underlying kernel from keeping the tcp connection alive. so, as far as the steward is concerned, the connection is still there, but the thing is quiet. there's no rules against that.

you are right that there are implications to having a second connection come in for the same UDN, so perhaps when the second connection authenticates, any other connection for that UDN should be closed.

@aallan - your thoughts?

aallan commented 10 years ago

I can see a bunch of ways where this might happen. So agreed, I think the sensible thing to do would be that, when the second connection authenticates, any other connection for that UDN should be closed.

mrose17 commented 10 years ago

i have updated the steward, so that for thing clients, only one connection is allowed at a time. if a new connection comes in, any other existing connection is automatically closed. enjoy!

mrose17 commented 10 years ago

closed due to lack of response… it's working for me!

GuySawyer commented 10 years ago

I just came across this issue and had a proper read, and it raised a big question. Sorry to re-awaken this, as its been dormant for some time.

Mr Rose, you said you updated the Steward so that for thing-clients, only one connection is allowed at a time. Does this mean that I will NOT be able to simultaneously connect two BBB's (both running the thing-client) to the Steward?

Or would it be allowed so long as the "thingUUID" differs between the BBB's? This scenario would make the most sense to me in terms of how it should work.

mrose17 commented 10 years ago

the answer is: the latter. you can have as many BBBs as you want talking to the thing system, providing they each have a different thingUUID...

GuySawyer commented 10 years ago

OK, great. Thanks