Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Describe ACK token and message ID to APPLICATION request is incorrect #1181

Closed
brycekahle opened this issue Nov 21, 2016 · 2 comments · Fixed by #1226

Comments

@brycekahle
Copy link
Contributor

commented Nov 21, 2016

  • Very consistent, happens every time.
  • Can impact the ability to make function calls to the device

Photon, system firmware version 0.6.0, but same behavior observed on 0.5.3. Running stock tinker.

  1. Server sends Describe for SYSTEM
  2. Device ACKs with SYSTEM information
  3. Server sends Describe for APPLICATION
  4. Device ACKs with APPLICATION information, but using token value from step 2, and an unknown message ID.
  5. Device ACKs again with SYSTEM information, but using the token and message ID value from step 3.

The relevant logs:

coap msg sent msg=GET coap://127.0.0.1/d? (T=CON ID=13385 TK=02), length=9, type=Describe
coap msg msg=2.05 Content (127.0.0.1 T=ACK ID=13385 TK=02), length=462, type=DescribeReturn, payload={"p":6,"m":[{"s":16384,"l":"m","vc":30,"vv":30,"f":"b","n":"0","v":7,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"1","v":101,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"2","v":101,"d":[{"f":"s","n":"1","v":101,"_":""}]},{"s":131072,"l":"m","vc":30,"vv":30,"u":"2BA4E71E840F596B812003882AAE7CA6496F1590CA4A049310AF76EAF11C943A","f":"u","n":"1","v":2,"d":[{"f":"s","n":"2","v":1,"_":""}]},{"s":131072,"l":"f","vc":30,"vv":0,"d":[]}]}
coap msg sent msg=GET coap://127.0.0.1/d? (T=CON ID=13386 TK=03), length=9, type=Describe
coap msg msg=2.05 Content (127.0.0.1 T=ACK ID=37505 TK=02), length=76, type=DescribeReturn, payload={"f":["digitalread","digitalwrite","analogread","analogwrite"],"v":{}}
coap msg msg=2.05 Content (127.0.0.1 T=ACK ID=13386 TK=03), length=462, type=DescribeReturn, payload={"p":6,"m":[{"s":16384,"l":"m","vc":30,"vv":30,"f":"b","n":"0","v":7,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"1","v":101,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"2","v":101,"d":[{"f":"s","n":"1","v":101,"_":""}]},{"s":131072,"l":"m","vc":30,"vv":30,"u":"2BA4E71E840F596B812003882AAE7CA6496F1590CA4A049310AF76EAF11C943A","f":"u","n":"1","v":2,"d":[{"f":"s","n":"2","v":1,"_":""}]},{"s":131072,"l":"f","vc":30,"vv":0,"d":[]}]}

Full trace collapsed below:

Full server-side trace
ApiComm trace publish +1s { topic: 'device-describe-request',
  data: 'system',
  deviceID: '34003c000547343233323032' }
  CoAPDevice sendMessage +0ms Describe
  ConnectedDevice send +1ms <Buffer 41 01 34 49 02 b1 64 41 01>
debug: coap msg sent msg=GET coap://127.0.0.1/d? (T=CON ID=13385 TK=02), length=9, type=Describe, device_id=34003c000547343233323032, conn_id=1
debug: coap msg msg=2.05 Content (127.0.0.1 T=ACK ID=13385 TK=02), length=462, type=DescribeReturn, payload={"p":6,"m":[{"s":16384,"l":"m","vc":30,"vv":30,"f":"b","n":"0","v":7,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"1","v":101,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"2","v":101,"d":[{"f":"s","n":"1","v":101,"_":""}]},{"s":131072,"l":"m","vc":30,"vv":30,"u":"2BA4E71E840F596B812003882AAE7CA6496F1590CA4A049310AF76EAF11C943A","f":"u","n":"1","v":2,"d":[{"f":"s","n":"2","v":1,"_":""}]},{"s":131072,"l":"f","vc":30,"vv":0,"d":[]}]}, device_id=34003c000547343233323032, conn_id=1
debug: acknowledged msgId=13385, token=02, device_id=34003c000547343233323032, conn_id=1
  Describe return +20ms 2.05 Content (127.0.0.1 T=ACK ID=13385 TK=02) {"p":6,"m":[{"s":16384,"l":"m","vc":30,"vv":30,"f":"b","n":"0","v":7,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"1","v":101,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"2","v":101,"d":[{"f":"s","n":"1","v":101,"_":""}]},{"s":131072,"l":"m","vc":30,"vv":30,"u":"2BA4E71E840F596B812003882AAE7CA6496F1590CA4A049310AF76EAF11C943A","f":"u","n":"1","v":2,"d":[{"f":"s","n":"2","v":1,"_":""}]},{"s":131072,"l":"f","vc":30,"vv":0,"d":[]}]}
  ...
  ApiComm trace publish +0ms { topic: 'device-describe-request',
  data: 'application',
  deviceID: '34003c000547343233323032' }
  CoAPDevice sendMessage +0ms Describe
  ConnectedDevice send +0ms <Buffer 41 01 34 4a 03 b1 64 41 02>
debug: coap msg sent msg=GET coap://127.0.0.1/d? (T=CON ID=13386 TK=03), length=9, type=Describe, device_id=34003c000547343233323032, conn_id=1
debug: coap msg msg=2.05 Content (127.0.0.1 T=ACK ID=37505 TK=02), length=76, type=DescribeReturn, payload={"f":["digitalread","digitalwrite","analogread","analogwrite"],"v":{}}, device_id=34003c000547343233323032, conn_id=1
debug: coap msg msg=2.05 Content (127.0.0.1 T=ACK ID=13386 TK=03), length=462, type=DescribeReturn, payload={"p":6,"m":[{"s":16384,"l":"m","vc":30,"vv":30,"f":"b","n":"0","v":7,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"1","v":101,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"2","v":101,"d":[{"f":"s","n":"1","v":101,"_":""}]},{"s":131072,"l":"m","vc":30,"vv":30,"u":"2BA4E71E840F596B812003882AAE7CA6496F1590CA4A049310AF76EAF11C943A","f":"u","n":"1","v":2,"d":[{"f":"s","n":"2","v":1,"_":""}]},{"s":131072,"l":"f","vc":30,"vv":0,"d":[]}]}, device_id=34003c000547343233323032, conn_id=1
debug: acknowledged msgId=13386, token=03, device_id=34003c000547343233323032, conn_id=1
  Describe return +18ms 2.05 Content (127.0.0.1 T=ACK ID=13386 TK=03) {"p":6,"m":[{"s":16384,"l":"m","vc":30,"vv":30,"f":"b","n":"0","v":7,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"1","v":101,"d":[]},{"s":262144,"l":"m","vc":30,"vv":30,"f":"s","n":"2","v":101,"d":[{"f":"s","n":"1","v":101,"_":""}]},{"s":131072,"l":"m","vc":30,"vv":30,"u":"2BA4E71E840F596B812003882AAE7CA6496F1590CA4A049310AF76EAF11C943A","f":"u","n":"1","v":2,"d":[{"f":"s","n":"2","v":1,"_":""}]},{"s":131072,"l":"f","vc":30,"vv":0,"d":[]}]}
---

Completeness:

  • Minimum test case added
  • Device, system and user firmware versions stated
  • Particle confirmed

@technobly technobly added this to the 0.7.x milestone Nov 21, 2016

@brycekahle

This comment has been minimized.

Copy link
Contributor Author

commented Nov 21, 2016

Upon further inspection of the code in https://github.com/spark/firmware/blob/b57dffcfc99d0308c4a2da33b187aed19e969f91/communication/src/spark_protocol.cpp#L1409 it appears the code only expects a single Describe message and does not inspect the flags passed with the request, like the UDP variant does.

@brycekahle

This comment has been minimized.

Copy link
Contributor Author

commented Nov 21, 2016

In the single Describe request scenario, this is still a CoAP spec violation because of multiple ACK responses to a single request.

@technobly technobly modified the milestones: 0.7.x, 0.6.1 Nov 29, 2016

@technobly technobly modified the milestones: 0.6.1, 0.7.0 Jan 12, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.