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)