search

intel / vscode-tcf-debug

Visual Studio Code Target Communication Framework (TCF) Debugger Extension
MIT License
9 stars 3 forks source link

StackTrace calls still timeout despite instant response in log #2

Closed pelrun closed 10 months ago

pelrun commented 11 months ago

As mentioned in #1, here's a sample from the debug log. This is probably two issues in one - something is failing during processing of the Result, and the timeout is only being disabled when the Result is parsed, rather than unconditionally upon reception.

19:49:42 ➡️ Sending C StackTrace/5/getContext/FP15.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP14.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP13.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP12.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP11.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP10.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP9.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP8.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP7.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP6.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0 StackTrace getContext ["FP15.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP14.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP13.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP12.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP11.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP10.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP9.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP8.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP7.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0","FP6.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0"]
19:49:42 ⬅️ Received Result StackTrace/5/getContext/FP15.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP14.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP13.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP12.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP11.JTAG-jsn-JTAG-HS3-210299A8E504 ["[{\"ID\":\"FP15.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":15,\"Level\":0,\"IP\":1687703632},{\"ID\":\"FP14.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":14,\"Level\":1,\"IP\":1687703632,\"RP\":1687703632},{\"ID\":\"FP13.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":13,\"Level\":2,\"Walk\":true,\"FP\":1689847800,\"IP\":1683978232,\"RP\":1687703632},{\"ID\":\"FP12.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":12,\"Level\":3,\"Walk\":true,\"FP\":1689847776,\"IP\":1685922928,\"RP\":1683978232},{\"ID\":\"FP11.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":11,\"Level\":4,\"Walk\":true,\"FP\":1689847712,\"CodeArea\":{\"SAddr\":1684653824,\"SLine\":171,\"EAddr\":1684654128,\"ELine\":172,\"File\":\"messages.cpp\",\"Dir\":\"/home/james.churchill/lib/gamen/common\"},\"IP\":1684654112,\"RP\":1685922928},{\"ID\":\"FP10.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":10,\"Level\":5,\"Walk\":true,\"FP\":1689847712,\"Inlined\":1,\"FuncID\":\"@M0.@S3%FD04.FC21F9.6530C356.124.35C90B+2.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"CodeArea\":{\"SAddr\":1684654100,\"SLine\":181,\"EAddr\":1684654112,\"ELine\":182,\"File\":\"message_queue.hpp\",\"Dir\":\"/home/james.churchill/lib/gamen/common\"},\"IP\":1684654112,\"RP\":1684654112},{\"ID\":\"FP9.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":9,\"Level\":6,\"Walk\":true,\"FP\":1689847712,\"Inlined\":2,\"FuncID\":\"@M0.@S3%FD04.FC21F9.6530C356.124.35CC85+2.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"IP\":1684654112,\"RP\":1684654112},{\"ID\":\"FP8.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":8,\"Level\":7,\"Walk\":true,\"FP\":1689847624,\"CodeArea\":{\"SAddr\":1686846852,\"SLine\":506,\"EAddr\":1686847040,\"ELine\":507,\"File\":\"eth.cpp\",\"Dir\":\"/home/james.churchill/lib/gamen/network/eth\"},\"IP\":1686846892,\"RP\":1684654112},{\"ID\":\"FP7.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":7,\"Level\":8,\"Walk\":true,\"FP\":1689847624,\"Inlined\":1,\"FuncID\":\"@M0.@S3%FD04.FC21F9.6530C356.124.2A72064+2.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"CodeArea\":{\"SAddr\":1686846852,\"SLine\":465,\"EAddr\":1686846896,\"ELine\":466,\"File\":\"eth.cpp\",\"Dir\":\"/home/james.churchill/lib/gamen/network/eth\"},\"IP\":1686846892,\"RP\":1686846892},{\"ID\":\"FP6.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ParentID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"ProcessID\":\"JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"Index\":6,\"Level\":9,\"Walk\":true,\"FP\":1689847624,\"Inlined\":2,\"FuncID\":\"@M0.@S3%FD04.FC21F9.6530C356.124.2A720C6+2.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0\",\"CodeArea\":{\"SAddr\":1686846884,\"SLine\":368,\"EAddr\":1686846896,\"ELine\":369,\"File\":\"eth.cpp\",\"Dir\":\"/home/james.churchill/lib/gamen/network/eth\"},\"IP\":1686846892,\"RP\":1686846892}]","",""]
19:49:52 Command timeout StackTrace/5/getContext/FP15.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP14.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP13.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP12.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP11.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP10.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP9.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP8.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP7.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0+FP6.JTAG-jsn-JTAG-HS3-210299A8E504-5ba00477-0R0
pelrun commented 11 months ago

Importantly, what isn't seen in these cases is a "Parsing async result" log message, but it's there for all the calls that succeed.

pelrun commented 11 months ago

Ok, the root cause is that the token generated by the extension for this api call can have an unlimited length, but the server may not support it. The returned Result has truncated the token to the first 256 chars, so it's not being successfully matched against the record in deleteAsync.

pelrun commented 11 months ago

I just did the simplest thing, which was remove the arguments from the token() implementations, and it's running smoothly. Makes actually reading the debug logs a lot easier, too :)

iebold commented 11 months ago

Ok, the root cause is that the token generated by the extension for this api call can have an unlimited length, but the server may not support it. The returned Result has truncated the token to the first 256 chars, so it's not being successfully matched against the record in deleteAsync.

I've been wondering if that will happen. Technically, the current token is for debugging purposes. We could use a single counter and save bytes. Will probably add a flag for this.

Note that this makes the TCF agent non-compliant. An error response should have been returned if unable to parse the request.

pelrun commented 11 months ago

Well the token is really only intended for matching commands and responses, shoving all the arguments into it is slightly abusing it. :D

I'd argue it doesn't really make the agent non-compliant, if only because the specification doesn't really say anything about the format of the token. 256 chars seems like a reasonable implementation choice for something that was expected to always have just a simple number or identifier in it. It still correctly parsed and executed the request, and the client could potentially still correctly match them up, so bluntly erroring out doesn't make a lot of sense either.

iebold commented 11 months ago

It still correctly parsed and executed the request, and the client could potentially still correctly match them up, so bluntly erroring out doesn't make a lot of sense either.

The agent wrongly parsed the request, executed it and returned a response with a different token. This is an agent bug but only because they made some "reasonable" assumptions which made sense at the time and given the device limitations, etc. etc.

Tools often have to support implementations deviations and bugs, this one is nothing new.

This issue will be dealt with in the next update.

Thanks for reporting, it's an interesting find.

iebold commented 10 months ago

v0.2.5 fixes this: unexpected replies are logged to the user. The default token format is just a plain number.