Cellular: Improve ATHandler AT debug traces #10121

kivaisan · 2019-03-15T11:14:03Z

Description

Original AT debug traces had several issues:

Can be overwritten by other traces (printf/mbed-trace)
No way to know which direction message was going (TX or RX)
and characters were not visible in trace
etc.

This commit addresses those issues using mbed-trace and showing separately
each filehandle write and read.

Pull request type

[X] Fix
[ ] Refactor
[ ] Target update
[ ] Functionality change
[ ] Docs update
[ ] Test update
[ ] Breaking change

Reviewers

@AriParkkila @mirelachirica @jarvte

Release Notes

ciarmcom · 2019-03-15T12:00:38Z

@kivaisan, thank you for your changes.
@AriParkkila @mirelachirica @jarvte @ARMmbed/mbed-os-wan @ARMmbed/mbed-os-maintainers please review.

NirSonnenschein · 2019-03-17T13:35:48Z

@kivaisan , please fix the a-style issues

kivaisan · 2019-03-18T06:40:58Z

a-style issues are now fixed.

cmonr · 2019-03-19T01:04:50Z

features/cellular/framework/AT/ATHandler.cpp

@@ -1225,30 +1222,41 @@ void ATHandler::flush()
    }
 }

-void ATHandler::debug_print(const char *p, int len)
+void ATHandler::debug_print(const char *p, int len, ATType type)


I really don't like that we have this precedent of internal/external APIs, and which are alright to change in a patch, but so it goes.

Especially since this a debug function.

cmonr · 2019-03-19T01:08:39Z

features/cellular/framework/AT/ATHandler.cpp

+            if (isprint(c)) {
+                *pbuf++ = c;
+            } else if (c == '\r') {
+                sprintf(pbuf, "<cr>");


Thanks for the commit message. Made it really easy to tell why \r and \n were changed.

cmonr · 2019-03-27T21:20:46Z

Anyone else want to review the PR?

@mbed-os-wan @AriParkkila @mirelachirica @jarvte

AriParkkila · 2019-03-28T13:00:48Z

This fixes the problems mentioned in the description but it seems to be quite verbose, which is likely to cause timing issues. For example, instead of AT+CEREG? it prints:

[INFO][CELL]: AT TX ( 8): AT+CEREG
[INFO][CELL]: AT TX ( 1): ?
[INFO][CELL]: AT TX ( 1): <cr>

AT debug prints are very useful when running Mbed OS Greentea TESTS. It seems that debug macro (used by the current AT debug) prints now fine but with this new debugging TESTS should be updated to use mbed-trace.

AriParkkila · 2019-03-28T13:08:54Z

features/cellular/framework/AT/ATHandler.cpp

-#endif
-        char c;
+        const int buf_size = len * 4; // x4 -> reserve space for extra characters
+        char *buffer = (char *)malloc(buf_size);


Check for NULL or use nothrow.

AriParkkila · 2019-03-28T13:09:43Z

features/cellular/framework/AT/ATHandler.cpp

-        mbed_cellular_trace::mutex_wait();
-#endif
-        char c;
+        const int buf_size = len * 4; // x4 -> reserve space for extra characters


len * 4 + 1 where +1 for sprintf zero termination.

kivaisan · 2019-03-28T13:46:59Z

@AriParkkila timing issue is true but that is really problematic in our current mbed-os tracing system which uses UART on traces. On the other hand those time traces are really useful in some debugging cases so that's why I'd like to use it. And we get extra overhead especially for RX traces as modems tend to send responses in multiple pieces and there is nothing we can do for it. TX we could maybe improve in future to construct full command before sending. Also debug() prints tend to have a problem that other trace overwrites the written data.

trowbridgec · 2019-03-28T18:22:15Z

For what it's worth, I pulled in these changes and was able to diagnose cell module communication issues much easier. This PR is a great idea.

cmonr · 2019-03-28T22:17:15Z

CI started

mbed-ci · 2019-03-29T08:52:34Z

Test run: FAILED

Summary: 1 of 13 test jobs failed
Build number : 1
Build artifacts

Failed test jobs:

jenkins-ci/mbed-os-ci_greentea-test

alekla01 · 2019-03-29T08:52:46Z

Restarted jenkins-ci/greentea-test

adbridge · 2019-03-29T13:41:54Z

@AriParkkila are you happy with the changes on this PR after review ?

AriParkkila · 2019-03-29T14:01:50Z

@kivaisan do you have any idea how to avoid timing issues. I tried this with some real world applications and they tend to fail when this new logging is enabled - That's likely because debug prints take so much time that data from a modem is lost.

@SeppoTakalo do you think we could enable mbed-trace for Mbed OS networking TESTS?

kivaisan · 2019-04-01T07:33:54Z

One workaround is to increase baud rate on boards which support bigger baud rates for UART. This (PDMC) seems to work on WISE-1570 with 230400 baud rate, but as long as we use UART, these all are workarounds and we cannot guarantee any trace print is not causing timing issues.

SeppoTakalo · 2019-04-01T08:33:07Z

Enabling mbed-trace would require code changes and test cases are not using mbed-trace.
I would therefore wait until they provide a module that initialises the trace library automatically, if enabled.

SeppoTakalo · 2019-04-01T08:36:38Z

features/cellular/framework/AT/ATHandler.cpp

            }
+
+            delete buffer;


You get the buffer from malloc() and free it by calling delete. This is a bit inconstant.

Use malloc()/free() pair or new/delete pair.

Good catch. Fixed.

Original AT traces had several issue: - Can be overwritten by other traces (printf/mbed-trace) - No way to know which direction message was going (TX or RX) - <cr> and <ln> characters were not visible in trace etc. This commit addresses those issues using mbed-trace and showing separately each filehandle write and read.

0xc0170 · 2019-04-02T09:35:11Z

CI started

@AriParkkila Please leave the review feedback

mbed-ci · 2019-04-02T16:23:49Z

Test run: FAILED

Summary: 1 of 13 test jobs failed
Build number : 2
Build artifacts

Failed test jobs:

jenkins-ci/mbed-os-ci_exporter

0xc0170 · 2019-04-03T07:00:26Z

CI was restarted, all green

ciarmcom requested review from AriParkkila, jarvte, mirelachirica and a team March 15, 2019 12:00

ciarmcom added the needs: review label Mar 15, 2019

NirSonnenschein added needs: work and removed needs: review labels Mar 17, 2019

0xc0170 added needs: review and removed needs: work labels Mar 18, 2019

cmonr approved these changes Mar 19, 2019

View reviewed changes

cmonr added the release-version: 5.12.1 label Mar 19, 2019

jarvte approved these changes Mar 28, 2019

View reviewed changes

AriParkkila suggested changes Mar 28, 2019

View reviewed changes

cmonr added needs: CI and removed needs: review labels Mar 28, 2019

adbridge added needs: review and removed needs: CI labels Mar 29, 2019

SeppoTakalo reviewed Apr 1, 2019

View reviewed changes

cmonr requested a review from SeppoTakalo April 1, 2019 19:13

SeppoTakalo approved these changes Apr 2, 2019

View reviewed changes

0xc0170 added needs: CI and removed needs: review labels Apr 2, 2019

AriParkkila approved these changes Apr 2, 2019

View reviewed changes

0xc0170 added ready for merge and removed needs: CI labels Apr 3, 2019

0xc0170 merged commit 8cbcc55 into ARMmbed:master Apr 3, 2019

0xc0170 removed the ready for merge label Apr 3, 2019

Cellular: Improve ATHandler AT debug traces #10121

Cellular: Improve ATHandler AT debug traces #10121

Uh oh!

Conversation

kivaisan commented Mar 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Pull request type

Reviewers

Release Notes

Uh oh!

ciarmcom commented Mar 15, 2019

Uh oh!

NirSonnenschein commented Mar 17, 2019

Uh oh!

kivaisan commented Mar 18, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cmonr commented Mar 27, 2019

Uh oh!

AriParkkila commented Mar 28, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kivaisan commented Mar 28, 2019

Uh oh!

trowbridgec commented Mar 28, 2019

Uh oh!

cmonr commented Mar 28, 2019

Uh oh!

mbed-ci commented Mar 29, 2019

Uh oh!

alekla01 commented Mar 29, 2019

Uh oh!

adbridge commented Mar 29, 2019

Uh oh!

AriParkkila commented Mar 29, 2019

Uh oh!

kivaisan commented Apr 1, 2019

Uh oh!

SeppoTakalo commented Apr 1, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

0xc0170 commented Apr 2, 2019

Uh oh!

mbed-ci commented Apr 2, 2019

Uh oh!

0xc0170 commented Apr 3, 2019

Uh oh!

Uh oh!

kivaisan commented Mar 15, 2019 •

edited

Loading