DS 1.2.0 & 2.0.0 TRACE limitation

IoT Modules Development tools
1

For the same code,

ie, DS 1.2.0 has failed to expand the format fields.

It seems that DS 1.2.0 has a limit to the number of fields that it will expand in a TRACE - beyond that limit, no fields will be expanded.

The limit seems to be about 6?

2

DS 2.0.0 is the same.

3

A workaround, of course, is to sprintf to a buffer first, and then TRACE the buffer; ie,

instead of this:

TRACE(( TRACE_LEVEL, "  RTC Time: %04d/%02d/%02d %02d:%02d:%02d = UTC seconds: %d",
        rtcTimeStruct.Year, rtcTimeStruct.Month,  rtcTimeStruct.Day, 
        rtcTimeStruct.Hour, rtcTimeStruct.Minute, rtcTimeStruct.Second, 
        rtcTimeStamp.TimeStamp ));

do this:

sprintf( buffer, "  RTC Time: %04d/%02d/%02d %02d:%02d:%02d = UTC seconds: %d",
         rtcTimeStruct.Year, rtcTimeStruct.Month,  rtcTimeStruct.Day, 
         rtcTimeStruct.Hour, rtcTimeStruct.Minute, rtcTimeStruct.Second, 
         rtcTimeStamp.TimeStamp );
TRACE((  TRACE_LEVEL, buffer ));

But what is the implication for TRACE performance?

4

We’ll have a look at this and keep you informed.
Concerning the performance aspect, it’s true that when you use sprintf on the target side, you’ll loose some additional time regarding sole TRACE macro usage.
Indeed, when using TRACE, the string processing (“sprintf”-like) is done on the PC side. When using DS, the Java String.format() method is used, with the drawback that it is not always a perfect match of what the C sprintf is supposed to do.
Anyway, it actually depends on how often (how many times per second :wink:) you use this kind of trace…

5

Do you agree that this is a DS limitation?

I’ve had this “problem” before a while ago, but then I just gave up and did sprintf instead.

Then it happened again yesterday, and I had the idea of trying it in TMT - where it worked!

6

As it’s working in TMT but not in DS, let’s call it a bug :wink:
Can’t imagine any technical reason which should prevent us to fix it.

7

DS 2.1.0 seems to be failing to expand even traces with just 2 variables in :open_mouth: :exclamation:

The corresponding source lines are:

TRACE(( TRCLVL_BASE, "atDnldFsm NewSt=%u Rslt=%u", dnldState, dnldRslt ));

and:

TRACE(( TRCLVL_BASE, "atDnldFsm S=%u E=%u L=%u", dnldState, callEvent, rxDataLen ));
8

Arg, sounds like a regression in 2.1.0…
We’ve added preferences to handle these cases where it’s needed to pre-replace sprintf formating characters:

694b3abe46f54e861d72c6f423bb773e6d3c8d6f.PNG734×390 14.9 KB


But it seems that it doesn’t work…
We’re taking a look and probably will publish a patch here ASAP.

9

As a workaround, I changed the code to:

TRACE(( TRCLVL_BASE, "atDnldFsm NewSt=%d Rslt=%d", dnldState, dnldRslt ));

and:

TRACE(( TRCLVL_BASE, "atDnldFsm S=%d E=%d L=%d", dnldState, callEvent, rxDataLen ));

and that now seems to work:

Does the limit of 6 (or whatever) replacement fields still apply?

10

The fact that the target can’t send more than 6 arguments in traces is, actually, a target limitation.
But we’ve fixed the DS behavior in 2.1.0 to at least replace the 6 first arguments in the displayed trace (supplementary replacement fields will be displayed unchanged).

11

Just pushed a patch to fix the replace bug:
[url]https://forum.sierrawireless.com/t/patch-traces-view-replacement-bug-in-ds-2-1-0/5240/1]

12

So why could I get more than 6 in TMT (see initial post) :question:

13

Mmmm, pretty sure that even in TMT, a trace with more than 6 formatting chars isn’t correctly processed.
(unless proven otherwise; if you’ve got an evidence, please just tell :wink: )

14

See the initial post in this very thread:

That example contained 7 fields!

Note that those examples are from the same executable in the same device - the only difference is whether TMT or DS was used to view the traces.

15

Please can you elaborate on the used embedded SW versions?
Done the test with FW 7.46 + OS 6.36, and got the same behavior with TMT & DS: 7th field is not replaced.
Maybe a regression in recent embedded SW…

16

Hmmm… digs back to find old Trace file from May:

Do you mean that the other six were replaced?

If so, that is certainly a different issue: in my original report it was “all or nothing” - not “first n”

17

To be clear (with a trace sent from embedded app with 7 replacement fields):

  • DS < 2.1.0: nothing is replaced
  • DS 2.1.0: first six are replaced, seventh and more not replaced
  • TMT: all is replaced, but seventh and more values are completely random (or at least nothing to do with the real expected values)

Concerning this third point, are you sure that seventh (and more) values were correct with TMT?
I’ve done the test even with 7.44 FW, and behavior is the same.
Quite dangerous (can lead to bad interpretation); that’s why in DS we preferred not replacing fields for which we don’t have values coming from the target.

18

Excellent :smiley:

Stupid :angry:

Looking at the example from earlier:

The “UTC seconds” field there should be the UNIX timestamp for the “RTC Time”
Putting 1095106560 into onlineconversion.com/unix_time.htm gives:

So, aparently, the value presented by TMT is wrong! :unamused:

Has it always been this way?
The limitation was not documented before Open-AT v6.31

Indeed! Especially as it was undocumented in the releases when TMT was current!

Whoever decided to do otherwise deserves a good slapping!

19

AFAIR yes…