Problems with receiving very first message after a transmission

Jiri_Ctibor · September 21, 2018, 11:22am

Hello guys,

I have a problem with receiving a very first message after I do a transmission with the same device. If I did not perform transmission in the device (after boot) I can catch every incoming message, so it has to be something connected with the transmission before (something is reconfigured or I don’t know). I am confused about that because I spend I lot of time solving this issue but unsuccessfully and I am totally running out of any ideas.

I would like to thank to [color=#333333][size=small][size=medium][color=#426276]zoran skrba[/color][/size][/size][/color] for trying to help me, but i am still stuck

I did not use auto re-enable.
I did not use wait for a response.
It cannot be caused due to a timing issue, because sending a message from another device is done for now by user button, so definitely when the message from another device is sent, the targeted device is already in receiver mode for sure.

TRANSMISSION

dwt_forcetrxoff(); // go to idle from receive mode
stats = dwt_writetxdata(txDataLen,(uint8_t *)txData,0); // fill TX buffer
stats = dwt_writetxfctrl(txDataLen, 0); // write TX cfg (buffer len and offset)
stats = dwt_starttx(DWT_START_TX_IMMEDIATE);// start transmission

TX callback:

dwt_setrxtimeout(0); // diasbale RX timeout
rxEnFlag = dwt_rxenable(DWT_START_RX_IMMEDIATE); //manually reenable RX

RECEPTION

…after device initialization…
rxEnstat = dwt_rxenable(0); // turn on the receiver

RX callback:

dwt_readrxdata(rxData,DataLen,0); // read RX buffer
dwt_setrxtimeout(0); // diasbale RX timeout
rxEnstat = dwt_rxenable(DWT_START_RX_IMMEDIATE); // turn on the receiver

BEHAVIOR DESCRIBTION:
As I said every message except very first one just after the transmission is received successfully:

[code][18/09/18 - 15:05:11:635] NEW ISR CALLED //ISR start

[18/09/18 - 15:05:11:636] SYS_STAT 0000800103 // all
[18/09/18 - 15:05:11:639] SYS_MASK 3C37FF80 // this
[18/09/18 - 15:05:11:639] SYS_STATE 0B00050C00 // is
[18/09/18 - 15:05:11:642] SYS_STAT 0000806F03 // done
[18/09/18 - 15:05:11:642] SYS_MASK 3C37FF80 // in one
[18/09/18 - 15:05:11:644] SYS_STATE 0000010000 // do {dwt_isr()} while (IRQ == 1)
[18/09/18 - 15:05:11:647]
[18/09/18 - 15:05:11:647] RX callback routine - receiver reenable; // callback called
[18/09/18 - 15:05:11:650]
[18/09/18 - 15:05:11:650] RECEIVED DATA: AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA: // print out received data in RX callback
[18/09/18 - 15:05:11:656] AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:
[18/09/18 - 15:05:11:662] AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:C1:
[18/09/18 - 15:05:11:664] D5:
[/code]

Here is log from receiving after transmission is performed (ISSUE!):

[18/09/18 - 15:11:06:139] NEW ISR CALLED // TX before investigated reception [18/09/18 - 15:11:06:140] SYS_STAT 02008000F3 // ... [18/09/18 - 15:11:06:142] SYS_MASK 3C37FF80 // continuing ... [18/09/18 - 15:11:06:144] SYS_STATE 0000010000 // ... [18/09/18 - 15:11:06:145] TX callback routine - reenable RX // ... [18/09/18 - 15:11:06:151] RX ENABLE: OK // ... [18/09/18 - 15:11:11:261] [18/09/18 - 15:11:11:262] [18/09/18 - 15:11:11:262] NEW ISR CALLED // ISR start of tracked reception [18/09/18 - 15:11:11:262] SYS_STAT 0000800103 // ... [18/09/18 - 15:11:11:264] SYS_MASK 3C37FF80 // ... [18/09/18 - 15:11:11:265] SYS_STATE 0B00050C00 // ...

ISR is called (IRQ pin changes to its active value) BUT only RXPRD bit arises (saing that preable is detected). There is no additional bit marking that some problem or error occured. I have masked every interrupt connect with reception: SYS_MASK: 3C37 FF80. The duration and progression of this blank interrupt is also suspicions:
[attachment=195]
As you can see, states register value is 0x00050C00 which mead according to APS022 that the DW1000 is in RX state (0x5) and data reception (0x0C). From SYS_STAT register it could be derived, that preamble is successfully detected, but why SFD and etc. not? I am sure that message is transmitter properly because I have UWB sniffer from Arduino from my preliminary project and it receives it successfully every time.

Then after that, nothing is reconfigured, but the second message after this is received properly.

[21/09/18 - 12:59:08:085] NEW ISR CALLED [21/09/18 - 12:59:08:086] SYS_STAT 00 0080 0103 [21/09/18 - 12:59:08:087] SYS_MASK 3C37 FF80 [21/09/18 - 12:59:08:087] SYS_STATE 0B 0005 0C00 [21/09/18 - 12:59:08:090] SYS_STAT 00 0080 6F03 [21/09/18 - 12:59:08:093] SYS_MASK 3C37 FF80 [21/09/18 - 12:59:08:093] SYS_STATE 00 0001 0000 [21/09/18 - 12:59:08:097] [21/09/18 - 12:59:08:097] RX callback routine - receiver reenable; [21/09/18 - 12:59:08:100] [21/09/18 - 12:59:08:100] RECEIVED DATA: AA:AA:3F:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA: [21/09/18 - 12:59:08:106] AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA: [21/09/18 - 12:59:08:111] AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:E0: [21/09/18 - 12:59:08:119] 5E: [21/09/18 - 12:59:08:119] RXEN:OK
Did you have any idea, what should I try? Or did you somebody met with something similar?
Thank you very much for any advice.
Best regards.

Jiri_Ctibor · September 21, 2018, 12:43pm

UPDATE_______________________________________________

Things are getting “elf-struck” than I think before. Let me describe what I did:

I send a message from device X to observed device 1, both devices are blank after boot. The message is transmitted also receiver properly (time 13:54:40)
I send a message from device 1 to device X. Message is transmitted properly (confirmed with independent Arduino sniffer) but not received in device X because it was already transmitting in step 1.
I send again message from device X to device 1, again transmitted properly and did not receive by dev 1 because of the discussed issue. BUT WHAT IS THE MOST CONFUSING JUST NOW IS, THAT THE MESSAGE WAS RECEIVED IN 10 MINUTES DELAY (BUT PHYSICALLY NO MESSAGE IS SEND, SEE SNIFFER). Whats happen here ?!?! Lets take a look to logs.

DEVICE 1:

[21/09/18 - 13:54:40:528] [21/09/18 - 13:54:40:528] [21/09/18 - 13:54:40:529] NEW ISR CALLED // succesfull reception of the first message AFTER BOOT [21/09/18 - 13:54:40:529] SYS_STAT 00 0080 0103 [21/09/18 - 13:54:40:531] SYS_MASK 3C37 FF80 [21/09/18 - 13:54:40:532] states 0B 0005 0C00 [21/09/18 - 13:54:40:534] SYS_STAT 00 0080 6F03 [21/09/18 - 13:54:40:537] SYS_MASK 3C37 FF80 [21/09/18 - 13:54:40:537] states 00 0001 0000 [21/09/18 - 13:54:40:540] [21/09/18 - 13:54:40:540] RX callback routine - receiver reenable; [21/09/18 - 13:54:40:545] [21/09/18 - 13:54:40:545] RECEIVED DATA: AA:AA:1:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:40:551] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:40:555] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:DA:E [21/09/18 - 13:54:40:558] D: [21/09/18 - 13:54:40:558] RXEN:OK [21/09/18 - 13:54:43:720] TX DATA WRIT STAT:OK TXF CTRL WRIT STAT:OK ; TX_FCTRL: // succesfull transmission [21/09/18 - 13:54:43:726] 298032 ;TX START STAT:OK [21/09/18 - 13:54:43:729] [21/09/18 - 13:54:43:729] [21/09/18 - 13:54:43:729] NEW ISR CALLED [21/09/18 - 13:54:43:729] SYS_STAT 00 0080 00F3 [21/09/18 - 13:54:43:732] SYS_MASK 3C37 FF80 [21/09/18 - 13:54:43:734] states 00 0001 0000 [21/09/18 - 13:54:43:735] TX callback routine - reenable RX [21/09/18 - 13:54:43:741] RX ENABLE: OK [21/09/18 - 13:54:45:417] [21/09/18 - 13:54:45:417] [21/09/18 - 13:54:45:417] NEW ISR CALLED // unsuccessfull reception after transmission [21/09/18 - 13:54:45:418] SYS_STAT 00 0080 0103 // unsuccessfull reception after transmission [21/09/18 - 13:54:45:419] SYS_MASK 3C37 FF80 // unsuccessfull reception after transmission [21/09/18 - 13:54:45:420] states 0B 0005 0C00 // unsuccessfull reception after transmission [21/09/18 - 14:07:48:952] [21/09/18 - 14:07:48:952] [21/09/18 - 14:07:48:952] NEW ISR CALLED // dummy reception 1 [21/09/18 - 14:07:48:952] SYS_STAT 02 0080 0103 [21/09/18 - 14:07:48:955] SYS_MASK 3C37 FF80 [21/09/18 - 14:07:48:955] states 00 0001 0000 [21/09/18 - 14:07:48:958] SYS_STAT 02 0480 0103 [21/09/18 - 14:07:48:960] SYS_MASK 3C37 FF80 [21/09/18 - 14:07:48:961] states 00 0001 0000 [21/09/18 - 14:07:48:964] [21/09/18 - 14:07:48:964] RX callback routine - receiver reenable; [21/09/18 - 14:07:48:968] [21/09/18 - 14:07:48:968] RECEIVED DATA: AA:AA:2:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:07:48:975] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:07:48:979] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:61:7 [21/09/18 - 14:07:48:982] 4: [21/09/18 - 14:07:48:982] RXEN:OK [21/09/18 - 14:14:07:059] [21/09/18 - 14:14:07:059] [21/09/18 - 14:14:07:059] NEW ISR CALLED // dummy reception 2 [21/09/18 - 14:14:07:060] SYS_STAT 02 0080 0103 [21/09/18 - 14:14:07:062] SYS_MASK 3C37 FF80 [21/09/18 - 14:14:07:063] states 00 0001 0000 [21/09/18 - 14:14:07:065] SYS_STAT 02 0480 0103 [21/09/18 - 14:14:07:068] SYS_MASK 3C37 FF80 [21/09/18 - 14:14:07:068] states 00 0001 0000 [21/09/18 - 14:14:07:071] [21/09/18 - 14:14:07:071] RX callback routine - receiver reenable; [21/09/18 - 14:14:07:076] [21/09/18 - 14:14:07:076] RECEIVED DATA: AA:AA:2:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:14:07:081] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:14:07:088] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:61:7 [21/09/18 - 14:14:07:090] 4: [21/09/18 - 14:14:07:090] RXEN:OK [21/09/18 - 14:14:18:438] [21/09/18 - 14:14:18:438] [21/09/18 - 14:14:18:438] NEW ISR CALLED // dummy reception 3 [21/09/18 - 14:14:18:439] SYS_STAT 00 0080 0103 [21/09/18 - 14:14:18:440] SYS_MASK 3C37 FF80 [21/09/18 - 14:14:18:441] states 00 0001 0000 [21/09/18 - 14:14:18:443] SYS_STAT 00 0480 0103 [21/09/18 - 14:14:18:446] SYS_MASK 3C37 FF80 [21/09/18 - 14:14:18:446] states 00 0001 0000 [21/09/18 - 14:14:18:450] [21/09/18 - 14:14:18:450] RX callback routine - receiver reenable; [21/09/18 - 14:14:18:454] [21/09/18 - 14:14:18:454] RECEIVED DATA: AA:AA:2:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:14:18:459] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:14:18:465] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:61:7 [21/09/18 - 14:14:18:468] 4: [21/09/18 - 14:14:18:468] RXEN:OK [21/09/18 - 14:40:00:260] [21/09/18 - 14:40:00:261] NEW ISR CALLED [size=small][font=Monaco, Consolas, Courier, monospace]// dummy reception 4[/font][/size] [21/09/18 - 14:40:00:261] SYS_STAT 02 0080 0103 [21/09/18 - 14:40:00:263] SYS_MASK 3C37 FF80 [21/09/18 - 14:40:00:264] states 00 0001 0000 [21/09/18 - 14:40:00:266] SYS_STAT 02 0480 0103 [21/09/18 - 14:40:00:269] SYS_MASK 3C37 FF80 [21/09/18 - 14:40:00:270] states 00 0001 0000 [21/09/18 - 14:40:00:272] [21/09/18 - 14:40:00:272] RX callback routine - receiver reenable; [21/09/18 - 14:40:00:277] [21/09/18 - 14:40:00:277] RECEIVED DATA: AA:AA:2:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:40:00:282] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 14:40:00:289] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:61:7 [21/09/18 - 14:40:00:291] 4: [21/09/18 - 14:40:00:291] RXEN:OK

DEVICE X:

[code][21/09/18 - 13:54:40:539] TX DATA WRIT STAT:OK TXF CTRL WRIT STAT:OK ; TX_FCTRL:
[21/09/18 - 13:54:40:539] 298032 ;TX START STAT:OK
[21/09/18 - 13:54:40:539]
[21/09/18 - 13:54:40:539]
[21/09/18 - 13:54:40:539] NEW ISR CALLED
[21/09/18 - 13:54:40:545] SYS_STAT 02 0080 00F3
[21/09/18 - 13:54:40:545] SYS_MASK 3C37 FF80
[21/09/18 - 13:54:40:545] states 00 0001 0000
[21/09/18 - 13:54:40:564] TX callback routine - reenable RX
[21/09/18 - 13:54:40:564] RX ENABLE: OK

[21/09/18 - 13:54:43:724]
[21/09/18 - 13:54:43:724]
[21/09/18 - 13:54:43:724] NEW ISR CALLED // unsuccessfull reception
[21/09/18 - 13:54:43:727] SYS_STAT 00 0080 0103 // unsuccessfull reception
[21/09/18 - 13:54:43:727] SYS_MASK 3C37 FF80 // unsuccessfull reception
[21/09/18 - 13:54:43:727] states 0B 0005 0C00 // unsuccessfull reception

[21/09/18 - 13:54:45:441] TX DATA WRIT STAT:OK TXF CTRL WRIT STAT:OK ; TX_FCTRL:
[21/09/18 - 13:54:45:441] 298032 ;TX START STAT:OK
[21/09/18 - 13:54:45:441]
[21/09/18 - 13:54:45:441]
[21/09/18 - 13:54:45:441] NEW ISR CALLED
[21/09/18 - 13:54:45:445] SYS_STAT 02 0080 00F3
[21/09/18 - 13:54:45:445] SYS_MASK 3C37 FF80
[21/09/18 - 13:54:45:445] states 00 0001 0000
[21/09/18 - 13:54:45:445] TX callback routine - reenable RX
[21/09/18 - 13:54:45:445] RX ENABLE: OK
[/code]

INDEPENDENT OTHER PLATFORM UWB SNIFFER:

[21/09/18 - 13:54:40:559] RECEIVED DATA: 10101010:10101010:1:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:40:560] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:40:561] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:40:562] A:AA:AA:DA:ED: [21/09/18 - 13:54:43:751] RECEIVED DATA: 10111011:10111011:1:BB:BB:BB:BB:BB:BB:B [21/09/18 - 13:54:43:752] B:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:B [21/09/18 - 13:54:43:753] B:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:BB:B [21/09/18 - 13:54:43:754] B:BB:BB:99:B5: [21/09/18 - 13:54:45:448] RECEIVED DATA: 10101010:10101010:2:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:45:449] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:45:450] A:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:AA:A [21/09/18 - 13:54:45:451] A:AA:AA:61:74:

As you can see on the sniffer log, physically only three messages have been transmitted. 13:54:40 from dev1, 13:54:43 from devX, 13:54:45 again from dev1.

BUT

From the first log it can be seen, that dev1 received[color=#ff3333] its own message[/color] sent at 13:54:45 13 minutes later? four times? (See sequence number “2” and CRC).

What’s happening here?

Jiri_Ctibor · September 21, 2018, 1:48pm

UPDATE

Event counters also do not report anything unexpected (any errors).

Status LEDs signalizes SFDOK! even while the reception issue… WHY is not then RXSFD bit set?

zoran_skrba · September 24, 2018, 10:56am

Hi Jiri,

so basically, you wait after RXPRD is set, and the receiver eventually (after the 2nd frame is sent) receives the frame and reports …6F…
i.e. you enable RX after TX, you get RXPRD on 1st frame, the receiver still stays in RX state, and then completes with the reception of the 2nd frame.

Could you try with other configurations, change PAC, PRF, bit rate?

Zoran

Jiri_Ctibor · September 24, 2018, 11:26am

Hi Zoran,

I do few changes. First I transit to official API provided on decawave.com web page from 2017 (before I was using “stolen” API from TREK1000 ARM source code from 2015).

I also try another configuration as you recommended:

[code] uwbConfig.chan = 5;
uwbConfig.prf = DWT_PRF_64M;
uwbConfig.txPreambLength = DWT_PLEN_128;
uwbConfig.rxPAC = DWT_PAC8;
uwbConfig.txCode = 3;
uwbConfig.rxCode = 3;
uwbConfig.nsSFD = 1;
uwbConfig.dataRate = DWT_BR_6M8;
uwbConfig.phrMode = DWT_PHRMODE_STD;
//uwbConfig.smartPowerEn = 1;
//uwbConfig.sfdTO = 0;//(2049 + 64 - 64); /* SFD timeout (preamble length + 1 + SFD length - PAC size). Used in RX only. */

uwbtxconfig.PGdly = 0xC0;
uwbtxconfig.power = 0x0E082848;[/code]

(Before it was CHAN1, 16MHz PRF, PLEN 2048, PAC 64, TX/RX code 1, DATARATE 110kbps)

… but without any progress, it is still the same

Yes after TX I manually enable RX(immediate). This results, that the reception is incomplete.

While receiving 1st frame, I got this:

[24/09/18 - 13:15:16:008] NEW ISR CALLED [24/09/18 - 13:15:27:296] SYS_STATUS: 0080 0002 [24/09/18 - 13:15:28:464] SYS_STATES: 4105 0500

and after second this:

[24/09/18 - 13:15:40:258] NEW ISR CALLED [24/09/18 - 13:15:47:149] SYS_STATUS: 0080 6F03 [24/09/18 - 13:15:47:820] SYS_STATES: 0001 0000 [24/09/18 - 13:16:08:450] [24/09/18 - 13:16:08:450] RX callback routine - receiver reenable; [24/09/18 - 13:16:08:453] [24/09/18 - 13:16:08:453] RECEIVED DATA: AA:AA:10:AA:AA:AA:AA:AA:35:E9: [24/09/18 - 13:16:08:457] RXEN:OK

What about MSBs in SYS_STATE ? 0x41… do they have any implication?

Thank you.

Jiri_Ctibor · September 24, 2018, 12:31pm

Zoran, I solve it!

I was caused by this my stupid code in TX callback:

void instance_txcallback(const dwt_cb_data_t *txd)
{
printf(“TX callback routine - reenable RX \n”);

//dwti_forceidle();
//dwt_forcetrxoff();
//dwt_rxreset(); //reset the RX
//dwt_softreset(); // reset all - TX, RX, Host, PMSC

dwt_setrxtimeout(0);
rxEnFlag = dwt_rxenable(DWT_START_RX_IMMEDIATE);

[color=#ff3333] if(!rxEnFlag)[/color]
[color=#ff3333] {[/color]
[color=#ff3333] rxEnFlag = 1;[/color]
[color=#ff3333] dwt_rxenable(0);[/color]
[color=#ff3333] printf("RX ENABLE: ");[/color]
[color=#ff3333] PRINT_COLOR_LINE(COLOR_GREEN,“OK”);[/color]
[color=#ff3333] } else {[/color]
[color=#ff3333] rxEnFlag = 0;[/color]
[color=#ff3333] dwti_forceidle();[/color]
[color=#ff3333] PRINT_COLOR_LINE(COLOR_GREEN,“FAIL”);[/color]
[color=#ff3333] }[/color]

}

It is some rest from my beginning, I badly handle the dwt_rxenable return values, so basically rx_enable was performed two times in a row and maybe this caused the issue I don’t know how.

So as expected, it was caused by myself.

Thank you very much for your time spend on this issue, I have increased your rank for that
Best regards.

zoran_skrba · September 24, 2018, 1:36pm

Ok,

yes, if you issue 2 commands (e.g. RX followed by RX) the DW IC will queue them up, so the 1st will execute and the second will wait until 1st is done. So once your 1st RX completed the second RX command started, so this cleared the system register and put RX into receive mode (e.g. like auto RX re-enable, and it gave impression of phantom RX event/ISR). This queuing up of commands is not advised and can cause mis-operation.