Sterling Hughes created MYNEWT-497:
--------------------------------------
Summary: Cleanup newtmgr debug output
Key: MYNEWT-497
URL: https://issues.apache.org/jira/browse/MYNEWT-497
Project: Mynewt
Issue Type: Improvement
Affects Versions: v1_0_0_rel
Reporter: Sterling Hughes
Fix For: v1_0_0_rel
Hi Christopher,
The latest version has improved debug output with the combined HEX and DEC
which I don't remember in earlier versions, so thanks for that. We've been
using the -t trace option but it's good to point out to anyone who stumbles
across this thread anyway.
I don't find the DEC very useful in the [DEBUG] output lines within 'Data:'
which is what I was referring to in the original email, but the TX packet dump
is a nice approach where you list both HEX and ASCII. My brain is just
hard-wired to HEX and I find myself converting the verbose DEC values on top
(which are very useful for the labels) into the HEX payload below to match
things up. 100% HEX might be more natural for a lot of people.
Between -lDEBUG and -t we were able to get everything we needed and there are
higher priority things to cleanup, and I'm happy to have what is there today,
but I'd say just dropping DEC altogether probably isn't going to cause any
problems ... but perhaps other users will disagree???
On 30/11/16 17:42, Christopher Collins wrote:
I accidently wrapped the newtmgr output with short lines. Here is the
unadalterated output:
[ccollins@ccollins-mac:~/releases/1.0.0-b1/rc2]$ newtmgr -ldebug -c ttys010
echo abc123
2016/11/30 08:25:57 [DEBUG] Writing newtmgr request &{Op:2 Flags:0 Len:10
Group:0 Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]}
2016/11/30 08:25:57 [DEBUG] Serializing request &{Op:2 Flags:0 Len:10 Group:0
Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]} into buffer [2 0 0 10 0 0 0
0 161 97 100 102 97 98 99 49 50 51]
2016/11/30 08:25:57 [DEBUG] Tx packet dump:
00000000 02 00 00 0a 00 00 00 00 a1 61 64 66 61 62 63 31 |.........adfabc1|
00000010 32 33 |23|
2016/11/30 08:25:57 [DEBUG] Writing [6 9] to data channel
2016/11/30 08:25:57 [DEBUG] Writing [65 66 81 67 65 65 65 75 65 65 65 65 65 75
70 104 90 71 90 104 89 109 77 120 77 106 79 53 57 65 61 61] to data channel
2016/11/30 08:25:57 [DEBUG] Writing [10] to data channel
^C
[ccollins@ccollins-mac:~/releases/1.0.0-b1/rc2]$ newtmgr -t -ldebug -c ttys010
echo abc123
2016/11/30 08:26:13 [DEBUG] Writing newtmgr request &{Op:2 Flags:0 Len:10
Group:0 Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]}
2016/11/30 08:26:13 [DEBUG] Serializing request &{Op:2 Flags:0 Len:10 Group:0
Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]} into buffer [2 0 0 10 0 0 0
0 161 97 100 102 97 98 99 49 50 51]
2016/11/30 08:26:13 [DEBUG] Tx packet dump:
00000000 02 00 00 0a 00 00 00 00 a1 61 64 66 61 62 63 31 |.........adfabc1|
00000010 32 33 |23|
2016/11/30 08:26:13 [INFO] Outgoing:
00000000 06 09 |..|
2016/11/30 08:26:13 [DEBUG] Writing [6 9] to data channel
2016/11/30 08:26:13 [INFO] Outgoing:
00000000 41 42 51 43 41 41 41 4b 41 41 41 41 41 4b 46 68 |ABQCAAAKAAAAAKFh|
00000010 5a 47 5a 68 59 6d 4d 78 4d 6a 4f 35 39 41 3d 3d |ZGZhYmMxMjO59A==|
2016/11/30 08:26:13 [DEBUG] Writing [65 66 81 67 65 65 65 75 65 65 65 65 65 75
70 104 90 71 90 104 89 109 77 120 77 106 79 53 57 65 61 61] to data channel
2016/11/30 08:26:13 [INFO] Outgoing:
00000000 0a |.|
2016/11/30 08:26:13 [DEBUG] Writing [10] to data channel
^C
Thanks,
Chris
On Wed, Nov 30, 2016 at 08:40:39AM -0800, Christopher Collins wrote:
Hi Kevin,
On Wed, Nov 30, 2016 at 01:37:38PM +0100, Kevin Townsend wrote:
We're currently working on a mobile version of newtmgr, and the DEBUG
output is very useful to sanity check commands and responses, but the
output in DEC is kind of a pain when most SW engineering on embedded
devices is done in HEX. Is there an option I'm missing to output HEX
instead of DEC, or is this something worth considering changing
internally in the tool to default to HEX which feels like a far more
natural choice from my PoV?
The newtmgr debug output is pretty much a mess at the moment. That
said, it does do a hex dump of incoming and outgoing packets when you
specify the "-ldebug" flag. If you are only seeing decimal output, then
is it possible you are using an old version of newtmgr?
The reason I say the debug output is a mess is that it prints both a
decimal and a hex dump. For example:
[ccollins@ccollins-mac:~/releases/1.0.0-b1/rc2]$ newtmgr -ldebug -c
ttys010 echo abc123
2016/11/30 08:25:57 [DEBUG] Writing newtmgr request &{Op:2 Flags:0
Len:10 Group:0 Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]}
2016/11/30 08:25:57 [DEBUG] Serializing request &{Op:2 Flags:0 Len:10
Group:0 Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]} into buffer
[2 0 0 10 0 0 0 0 161 97 100 102 97 98 99 49 50 51]
2016/11/30 08:25:57 [DEBUG] Tx packet dump:
00000000 02 00 00 0a 00 00 00 00 a1 61 64 66 61 62 63 31
|.........adfabc1|
00000010 32 33 |23|
2016/11/30 08:25:57 [DEBUG] Writing [6 9] to data channel
2016/11/30 08:25:57 [DEBUG] Writing [65 66 81 67 65 65 65 75 65 65 65 65
65 75 70 104 90 71 90 104 89 109 77 120 77 106 79 53 57 65 61 61] to
data channel
2016/11/30 08:25:57 [DEBUG] Writing [10] to data channel
^C
I don't have a device connected to that serial port, so there is no
received packet. If there were, it would (should!) have gotten dumped
as well.
Another problem with the debug output is that it doesn't reflect
transport-specific encoding. For example, when the console is used as a
newtmgr transport, all data gets base64 encoded before being
transmitted. The packets that dumped are pre-encoding (for tx) and
post-decoding (for rx). This is annoying when there are encoding errors
in received packets, because these packets get silently dropped.
The workaround for this problem is to specify the "-x" flag ("trace").
This adds yet another dump to the debug output. This dump indicates
exactly what went "over the wire." For example:
[ccollins@ccollins-mac:~/releases/1.0.0-b1/rc2]$ newtmgr -t -ldebug -c
ttys010 echo abc123
2016/11/30 08:26:13 [DEBUG] Writing newtmgr request &{Op:2 Flags:0
Len:10 Group:0 Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]}
2016/11/30 08:26:13 [DEBUG] Serializing request &{Op:2 Flags:0 Len:10
Group:0 Seq:0 Id:0 Data:[161 97 100 102 97 98 99 49 50 51]} into buffer
[2 0 0 10 0 0 0 0 161 97 100 102 97 98 99 49 50 51]
2016/11/30 08:26:13 [DEBUG] Tx packet dump:
00000000 02 00 00 0a 00 00 00 00 a1 61 64 66 61 62 63 31
|.........adfabc1|
00000010 32 33 |23|
2016/11/30 08:26:13 [INFO] Outgoing:
00000000 06 09 |..|
2016/11/30 08:26:13 [DEBUG] Writing [6 9] to data channel
2016/11/30 08:26:13 [INFO] Outgoing:
00000000 41 42 51 43 41 41 41 4b 41 41 41 41 41 4b 46 68
|ABQCAAAKAAAAAKFh|
00000010 5a 47 5a 68 59 6d 4d 78 4d 6a 4f 35 39 41 3d 3d
|ZGZhYmMxMjO59A==|
2016/11/30 08:26:13 [DEBUG] Writing [65 66 81 67 65 65 65 75 65 65 65 65
65 75 70 104 90 71 90 104 89 109 77 120 77 106 79 53 57 65 61 61] to
data channel
2016/11/30 08:26:13 [INFO] Outgoing:
00000000 0a |.|
2016/11/30 08:26:13 [DEBUG] Writing [10] to data channel
^C
Notice the base64 dump in the middle of the sea of output.
I think we definitely need to clean up the debug output. When I added
the hex dump, I think I was afraid of removing the decimal dump in fear
that someone was relying on it. In retrospect, this fear was probably
silly, so unless someone pipes up, I suggest we remove it soon.
Chris
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
