Unexpected messages in websocket stream

ph1l commented 7 years ago

Hi there,

While experimenting with creating a signalk client application, I noticed a bunch of odd messages in the websocket stream. Most of the following messages do not follow the delta format from the spec.

$ wsdump ws://raspberrypi:3000/signalk/v1/stream
Press Ctrl+C to quit
< {"self":"motu","version":"v1.0.0","timestamp":"2016-11-04T20:35:02.751Z"}
< {"self":null,"version":null,"timestamp":"2016-11-04T20:35:02.902Z"}
< {"vessels":{"motu":{"environment":{"wind":{"angleApparent":{"timestamp":"2016-11-04T20:35:03.104Z"}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"angleApparent":{"value":0.97738438}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"angleApparent":{"values":{"/dev/ttyACM0":{"NMEA0183":{"MWV":{"timestamp":"2016-11-04T20:35:03.104Z"}}}}}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"angleApparent":{"values":{"/dev/ttyACM0":{"NMEA0183":{"MWV":{"value":0.97738438}}}}}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"speedApparent":{"timestamp":"2016-11-04T20:35:03.104Z"}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"speedApparent":{"value":3.5702136}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"speedApparent":{"values":{"/dev/ttyACM0":{"NMEA0183":{"MWV":{"timestamp":"2016-11-04T20:35:03.104Z"}}}}}}}}}}
< {"vessels":{"motu":{"environment":{"wind":{"speedApparent":{"values":{"/dev/ttyACM0":{"NMEA0183":{"MWV":{"value":3.5702136}}}}}}}}}}
< {"vessels":{"motu":{"environment":{"depth":{"belowTransducer":{"source":{"value":"$SDDPT,3.4,*7E","$source":"unknown","timestamp":"2016-11-04T20:35:03.147Z"}}}}}}}
< {"vessels":{"motu":{"environment":{"depth":{"belowTransducer":{"timestamp":"2016-11-04T20:35:03.147Z"}}}}}}
< {"vessels":{"motu":{"environment":{"depth":{"belowTransducer":{"values":{"/dev/ttyACM0":{"NMEA0183":{"DPT":{"timestamp":"2016-11-04T20:35:03.147Z"}}}}}}}}}}
< {"vessels":{"motu":{"environment":{"depth":{"belowTransducer":{"source":{"value":"$SDDBT,11.5,f,3.4,M,1.9,F*3C","$source":"unknown","timestamp":"2016-11-04T20:35:03.165Z"}}}}}}}
< {"vessels":{"motu":{"environment":{"depth":{"belowTransducer":{"timestamp":"2016-11-04T20:35:03.165Z"}}}}}}
< {"vessels":{"motu":{"environment":{"depth":{"belowTransducer":{"values":{"/dev/ttyACM0":{"NMEA0183":{"DBT":{"timestamp":"2016-11-04T20:35:03.165Z"}}}}}}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"source":{"value":"$VWVHW,,T,,M,0.00,N,0.00,K*54","$source":"unknown","timestamp":"2016-11-04T20:35:03.180Z"}}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"timestamp":"2016-11-04T20:35:03.180Z"}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"values":{"/dev/ttyACM0":{"NMEA0183":{"VHW":{"timestamp":"2016-11-04T20:35:03.180Z"}}}}}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"value":0.0}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"values":{"/dev/ttyACM0":{"NMEA0183":{"VHW":{"value":0.0}}}}}}}}}
< {"context":"vessels.motu","updates":[{"values":[{"path":"environment.depth.belowTransducer","value":3.4}],"source":{"value":"$SDDBT,11.5,f,3.4,M,1.9,F*3C","$source":"unknown","timestamp":"2016-11-04T20:35:03.165Z"},"timestamp":"2016-11-04T20:35:03.165Z"},{"values":[{"path":"environment.wind.speedApparent","value":3.5702136},{"path":"environment.wind.angleApparent","value":0.97738438},{"path":"environment.wind.directionTrue","value":0.89011792},{"path":"environment.wind.speedTrue","value":3.6988236}],"source":{"value":"$WIMWV,56.0,R,6.94,N,A*2B","$source":"unknown","timestamp":"2016-11-04T20:35:03.104Z"},"timestamp":"2016-11-04T20:35:03.104Z"},{"values":[{"path":"navigation.speedOverGround","value":0.0}],"source":{"value":"$VWVHW,,T,,M,0.00,N,0.00,K*54","$source":"unknown","timestamp":"2016-11-04T20:35:03.180Z"},"timestamp":"2016-11-04T20:35:03.180Z"},{"values":[{"path":"navigation.position","value":{"altitude":0.0,"latitude":37.8,"longitude":-122.3}},{"path":"navigation.magneticVariation","value":0.239057}],"source":{"value":"$GPRMC,203503.000,A,3752.1021,N,12218.9637,W,0.00,211.88,041116,,,A*78","timestamp":"2016-11-04T20:35:03.302Z"},"timestamp":"2016-11-04T20:35:02.411Z"},{"values":[{"path":"uuid","value":"motu"}]}]}
< {"vessels":{"motu":{"navigation":{"position":{"latitude":37.8}}}}}
< {"vessels":{"motu":{"navigation":{"position":{"timestamp":"2016-11-04T20:35:03.302Z"}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"source":{"value":"$GPRMC,203503.000,A,3752.1021,N,12218.9637,W,0.00,211.88,041116,,,A*78","$source":"unknown","timestamp":"2016-11-04T20:35:03.302Z"}}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"timestamp":"2016-11-04T20:35:03.302Z"}}}}}
< {"vessels":{"motu":{"navigation":{"speedOverGround":{"value":0.0}}}}}

rob42 commented 7 years ago

Hmm, they are in full format but with a single key being sent per line. Very strange - almost like a debug line is being sent somehow?

Can you elaborate on how you triggered this, including the subscriptions, and if its reproducible?

My server is currently exposed on http://www.42.co.nz:8088, and ws://www.42.co.nz:3000. Check them and see if its different?

BTW There is a demo file that uses the 'motu' vessel id (its my boat, came from early days, I need to change it to a uuid) You can do full format with a suitable subscription, but default is delta. I see there are delta format lines in there... The value/values stuff is correctly handled multiple values, but for simplicity I use the same format internally even when there is only one value. Much easier to code, removes the need to decide and switch when a duplicate comes in. Looking at the lines its almost like

ph1l commented 7 years ago

Lets see, running on a raspberry pi, with my freeboardPLC hooked up to it. default configs at commit 9a6d9d7f5d0ce4c72092b97eccc99d20017fc7e0.

pi@raspberrypi:~/signalk-server-java $ git diff
pi@raspberrypi:~/signalk-server-java $ git status
On branch master
Your branch is up-to-date with 'origin/master'.
nothing to commit, working directory clean

rob42 commented 7 years ago

Just tried a fresh install of latest signalk-java, and I get this (I formatted for readability):

{
    "context": "vessels.urn:mrn:signalk:uuid:6fb32f5b-7bd3-47a6-9e41-032a15faca55",
    "updates": [{
        "values": [{
            "path": "flag",
            "value": ""
        }, {
            "path": "mmsi",
            "value": ""
        }, {
            "path": "port",
            "value": ""
        }, {
            "path": "name",
            "value": "No name"
        }, {
            "path": "uuid",
            "value": "urn:mrn:signalk:uuid:6fb32f5b-7bd3-47a6-9e41-032a15faca55"
        }]
    }]
}

rob42 commented 7 years ago

@ph1l The strange output may be a result of running signalk-server-java directly, rather that via the signalk-java project, which wraps the server in a full website ?

ph1l commented 7 years ago

okay so I should be running from signalk-java repo instead? I'll try that and report back, thanks!

ph1l commented 7 years ago

Recent tests Continue to indicate the websocket update stream has weird messages in it:

2017-03-20 02:23:47,290 - root - WARNING - ignoring unrecognized delta message: {u'vessels': {u'urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46': {u'environmen
t': {u'wind': {u'directionTrue': {u'values': {u'urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46': {u'value': 0.01788462}}}}}}}}
2017-03-20 02:23:47,298 - root - WARNING - ignoring unrecognized delta message: {u'vessels': {u'urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46': {u'environmen
t': {u'wind': {u'directionTrue': {u'value': 0.01788462}}}}}}
2017-03-20 02:23:47,322 - root - WARNING - ignoring unrecognized delta message: {u'vessels': {u'urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46': {u'environmen
t': {u'wind': {u'speedTrue': {u'values': {u'urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46': {u'value': 6.04449582}}}}}}}}

According to the spec, https://github.com/SignalK/specification/blob/master/schemas/delta.json, updates should come in an updates object. It looks like these are individual updates without the proper format:

elektron@x61s:~$ wsdump ws://raspberrypi:3000/signalk/v1/stream
Press Ctrl+C to quit
< {"self":"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46","version":"v1.0.0","timestamp":"2017-03-20T09:35:59.047Z"}
< {"self":null,"version":null,"timestamp":"2017-03-20T09:35:59.246Z"}
< {"vessels":{"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46":{"environment":{"wind":{"directionTrue":{"values":{"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46":{"value":0.0174629}}}}}}}}
< {"vessels":{"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46":{"environment":{"wind":{"speedTrue":{"values":{"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46":{"value":5.0312232}}}}}}}}
< {"vessels":{"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46":{"environment":{"wind":{"speedTrue":{"value":5.0312232}}}}}}
< {"vessels":{"urn:mrn:signalk:uuid:48fa5c95-7316-4ad9-bdf1-f99c9124ac46":{"environment":{"wind":{"directionTrue":{"value":0.0174629}}}}}}

rob42 commented 7 years ago

Ahh - found it. It happens when you connect and have no subscription. All my tests subscribe...

rob42 commented 7 years ago

Mostly fixed. Still the occassional full format message coming through

ph1l commented 7 years ago

Ah. Glad you were able to reproduce! I've haven't messed with subscriptions before.

SignalK / signalk-server-java

Unexpected messages in websocket stream #32