DTM test not returning any packets

[Alex Crombie]

We have the following setup:
 - Both nRF52832 and nRF52840 chips in our product

 - The nRF52832 is a module while the nRF52840 is the chip integrated directly onto our PCB

 - SDK 15.0.0 (and integrating ble_dtm.c into our test firmware)

 -  Our devices communicate quite happily over BLE with each other in all configurations (832-832, 832-840, and 840-840) (relevant a bit later)

We are looking to do certification for our devices and we need to get the packet error rate in a blocking test. I have already looked at nAN34_v1.01 and was planning to retrieve the packet error rate as in the python scripts. As the nRF52 chips are already integrated into our product we have implemented the DTM interface over I2C rather than serial.

The issue we are seeing is that we start the test by setting out of the devices to transmit with the following options followed by running the receiver test for 1-5 seconds before ending the receiver test. When the test is ended the number of received packets is reported as 0:

The transmitter is setup as follows:

- RESET: 0x0000

- Top two bytes in length to 11: 0x010c

- PHY 2M: 0x0208

- TX power -8dBm: 0xb80b

- Start Transmit PRBS9 Max length @ 2442MHz: 0x94fc

The receiver is setup as follows:

- RESET: 0x0000

- Top two bytes in length to 11: 0x010c

- PHY 2M: 0x0208

- Start Receive PRBS9 Max length @ 2442MHz: 0x54fc

- Wait 1-5 seconds

- End Test: 0xc000

For each of the operations ble_dtm.c returns the result as 0, and the ending of the receiver test always returns 32768 which should be packet report: count=0, this is irregardless of the channel selected.

A couple of questions:
1) Is there anything wrong in the setup and commands used?

2) Any Idea why ending any test always returns the packet count as 0?

[Alex Crombie]

Håkon Alseth said:

 Is there a specific reason for not using UART with DTM? How do you interface the nRF? Using a USB->I2C bridge?

The nRF chip is slaved to the CPU embedded in our product and it only has connectivity to the CPU via I2C, and the SWD interface for debug purposes. Thus the only way we can send DTM commands is from userspace in the CPU via I2C.

Håkon Alseth said:

Do you parse the response data from the DUT? Command-wise, this looks OK.

The I2C command structure is a very thin wrapper around the interface provided by ble_dtm:

dtm_cmd_t cmd = ((action->parameter >> 14) & 0x03);
dtm_freq_t freq = ((action->parameter >> 8) & 0x3f);
uint32_t length = ((action->parameter >> 2) & 0x3f);
dtm_pkt_type_t payload = (action->parameter & 0x3);
dtm_event_t evt;

SEGGER_RTT_printf( 0, "cmd: %u(0x%02x), freq: %u(0x%02x), length: %u(%02x), payload: %u(0x%02x)\n",
                   cmd, cmd,
                   freq, freq,
                   length, length,
                   payload, payload);

uint32_t ret = dtm_cmd(cmd, freq, length, payload);
mcu_ctrl_add_event_w_extra(EVT_DTM_COMMAND_RESULT, 0, (uint16_t)ret, clock_get_elapsed_ms());

if (dtm_event_get(&evt)) {
    mcu_ctrl_add_event_w_extra(EVT_DTM_EVENT, 0, (uint16_t)evt, clock_get_elapsed_ms());
}

In the above code snippet the `mcu_ctrl_add_event*()` functions push a bit of data up the I2C lines, in this case first the result then the dtm event.  The `action->parameter` is a 32bit value. We definitely know that the commands for TX are operating correctly (including constant tone mode) and have verified this with a spectrum analyser. 

The receiver test is run as follows, which I believe should be quite close to the python test runner in AN34:

# echo 0x0000 > $DTM && echo 0x010c > $DTM && echo 0x0208 > $DTM && echo 0x54fc > $DTM && sleep 1 && echo 0xc000 > $DTM
DTM Result: 0
DTM Event: 0
DTM Result: 0
DTM Event: 0
DTM Result: 0
DTM Event: 0
DTM Result: 0
DTM Event: 0
# DTM Result: 0
DTM Event: 32768

Within 1s I would expect 1600 packets to be received which should come nowhere close to overflowing the packet report.

Håkon Alseth said:

Have you checked that the devices enter its respective RX and TX mode? If you do not have a spectrum analyzer, you can look at the current consumption when the nRF enters RX or TX mode.

As mentioned above we have checked that the device enters TX. I will check the current consumption but is there a way to check if the device has entered RX mode correctly (from a software standpoint) or some other definitive way of knowing? 

As a comparison of your logs to what we are sending the TX is pretty much identical except in your logs the tx power is set first then the top 2 bits of the packet length.
In terms of the RX we don't explicitly set the TX power, and we don't explicitly set the modulation index also the receive packet length in the receive test is set to 1 rather than max as per the TX test. Should any of these have an affect on receiving packets?

Another thing I noticed is that the logs don't contain the results from the end of the test, are these reporting the correct numbers as well?

Alex

[Håkon Alseth]

Hi Alex,

  

Alex Crombie said:

The nRF chip is slaved to the CPU embedded in our product and it only has connectivity to the CPU via I2C, and the SWD interface for debug purposes. Thus the only way we can send DTM commands is from userspace in the CPU via I2C.

Understood. The translation layer looks to be minimalistic, so I assume there's little issues there.

 

Alex Crombie said:

We definitely know that the commands for TX are operating correctly (including constant tone mode) and have verified this with a spectrum analyser. 

 This is good. I assume then its the RX that is misbehaving.

Alex Crombie said:

As mentioned above we have checked that the device enters TX. I will check the current consumption but is there a way to check if the device has entered RX mode correctly (from a software standpoint) or some other definitive way of knowing? 

As a comparison of your logs to what we are sending the TX is pretty much identical except in your logs the tx power is set first then the top 2 bits of the packet length.

When the RADIO is in RX mode, you can read the register contents of the NRF_RADIO peripheral:

STATE: https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/radio.html?cp=4_2_0_22_13_24#register.STATE

MODE: https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/radio.html?cp=4_2_0_22_13_10#register.MODE 

FREQ: https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/radio.html?cp=4_2_0_22_13_8#register.FREQUENCY

 

.STATE will give you if its actually running RX mode, .MODE will give you the modulation, and .FREQUENCY gives you the listening channel (2400 + register-value) 

 

Alex Crombie said:

In terms of the RX we don't explicitly set the TX power, and we don't explicitly set the modulation index also the receive packet length in the receive test is set to 1 rather than max as per the TX test. Should any of these have an affect on receiving packets?

 This is not a problem. RX does not have a transmit function, or a "gain" setting. The things that are required is the modulation scheme (BLE 2MBIT for instance) and the listening frequency.

 

Alex Crombie said:

Another thing I noticed is that the logs don't contain the results from the end of the test, are these reporting the correct numbers as well?

My apologies, I didn't stop the test when providing logs. Here's the snippet that ends the test when 0 packets are received:

2021-03-09T12:00:10.229Z INFO Ending test
2021-03-09T12:00:10.231Z DEBUG DTM Transport: Create test end CMD
2021-03-09T12:00:10.231Z DEBUG DTM Transport: Sending data: 0xC0 0x00
2021-03-09T12:00:10.250Z DEBUG DTM Transport: Receiving data: 0x80 0x00
2021-03-09T12:00:10.255Z INFO Receiver test finished successfully. Received 0 packets. 

 

Here's a RX log on 2442MHz (BLE2MBIT), and successfully receiving ~4k packets :

2021-03-09T12:08:34.562Z INFO Running device setup
2021-03-09T12:08:34.562Z DEBUG DTM Transport: Create setup CMD with control: 0
2021-03-09T12:08:34.562Z DEBUG DTM Transport: Create setup CMD with parameter: 0
2021-03-09T12:08:34.562Z DEBUG DTM Transport: Create setup CMD with dc type: 00
2021-03-09T12:08:34.562Z DEBUG DTM Transport: Sending data: 0x00 0x00
2021-03-09T12:08:34.569Z DEBUG DTM Transport: Receiving data: 0x00 0x00
2021-03-09T12:08:34.569Z DEBUG DTM Transport: Create tx power CMD: 0
2021-03-09T12:08:34.570Z DEBUG DTM Transport: Sending data: 0x80 0x0B
2021-03-09T12:08:34.575Z DEBUG DTM Transport: Receiving data: 0x00 0x00
2021-03-09T12:08:34.576Z DEBUG DTM Transport: Create setup CMD with control: 1
2021-03-09T12:08:34.576Z DEBUG DTM Transport: Create setup CMD with parameter: 0
2021-03-09T12:08:34.576Z DEBUG DTM Transport: Create setup CMD with dc type: 00
2021-03-09T12:08:34.576Z DEBUG DTM Transport: Sending data: 0x01 0x00
2021-03-09T12:08:34.582Z DEBUG DTM Transport: Receiving data: 0x00 0x00
2021-03-09T12:08:34.583Z DEBUG DTM Transport: Create setup CMD with control: 3
2021-03-09T12:08:34.583Z DEBUG DTM Transport: Create setup CMD with parameter: 0
2021-03-09T12:08:34.583Z DEBUG DTM Transport: Create setup CMD with dc type: 00
2021-03-09T12:08:34.583Z DEBUG DTM Transport: Sending data: 0x03 0x00
2021-03-09T12:08:34.591Z DEBUG DTM Transport: Receiving data: 0x00 0x00
2021-03-09T12:08:34.591Z DEBUG DTM Transport: Create setup CMD with control: 2
2021-03-09T12:08:34.591Z DEBUG DTM Transport: Create setup CMD with parameter: 2
2021-03-09T12:08:34.591Z DEBUG DTM Transport: Create setup CMD with dc type: 00
2021-03-09T12:08:34.592Z DEBUG DTM Transport: Sending data: 0x02 0x08
2021-03-09T12:08:34.598Z DEBUG DTM Transport: Receiving data: 0x00 0x00
2021-03-09T12:08:34.598Z INFO Starting test
2021-03-09T12:08:34.608Z DEBUG DTM Transport: Create receiver CMD with frequency: 2442
2021-03-09T12:08:34.608Z DEBUG DTM Transport: Create receiver CMD with length: 1
2021-03-09T12:08:34.608Z DEBUG DTM Transport: Create receiver CMD with packet type: 0
2021-03-09T12:08:34.614Z DEBUG DTM Transport: Sending data: 0x54 0x04
2021-03-09T12:08:34.620Z DEBUG DTM Transport: Receiving data: 0x00 0x00
2021-03-09T12:08:37.520Z INFO Ending test
2021-03-09T12:08:37.520Z DEBUG DTM Transport: Create test end CMD
2021-03-09T12:08:37.520Z DEBUG DTM Transport: Sending data: 0xC0 0x00
2021-03-09T12:08:37.540Z DEBUG DTM Transport: Receiving data: 0x92 0x40
2021-03-09T12:08:37.544Z INFO Receiver test finished successfully. Received 4672 packets.

 

Which SDK version have you based your firmware on?

 

Kind regards,

Håkon

[Alex Crombie]

Håkon Alseth said:

Which SDK version have you based your firmware on?

We are using Version 15.0.0.

Håkon Alseth said:

STATE: https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/radio.html?cp=4_2_0_22_13_24#register.STATE

MODE: https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/radio.html?cp=4_2_0_22_13_10#register.MODE 

FREQ: https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/radio.html?cp=4_2_0_22_13_8#register.FREQUENCY

Thank you for this, I will check what values these returns.

One thing I have noticed when running the commands in the order given above and also the ones from the logs is that when setting the PHY in the transmit test (0x0208) it returns 4(DTM_ERROR_ILLEGAL_CONFIGURATION) from the dtm_cmd() function and the event is 1. I have added debugging to ensure that I am not somehow corrupting the commands, but all the values seem fine, so I am not sure how I am getting into this code path.

Using the logging in my previous reply for the command above i am getting:

cmd: 0(0x00), freq: 2(0x02), length: 2(02), payload: 0(0x00)

The logging added in ble_dtm.c

else if (freq == LE_TEST_SETUP_SET_PHY)
{
    SEGGER_RTT_printf(0, "PHY: 1M=%u, 2M=%u, CS8=%u, CS2=%u, actual=%u\n",
                      LE_PHY_1M, LE_PHY_2M, LE_PHY_LE_CODED_S8, LE_PHY_LE_CODED_S2,
                      length);

The result from this logging is pretty much as expected:

PHY: 1M=1, 2M=2, CS8=3, CS2=4, actual=2

Given that the length matches the 2M PHY interface the case for LE_PHY_2M performs an explicit return of radio_init(). It appears it must be something in the validation of the configuration

# echo 0x0208 > $DTM
# DTM Result: 4
DTM Event: 1

EDIT:

There appears to be a bug in the setting of the TX power first and then starting the radio in 2M mode:

Bitwise the power calculation is correct however the fact that it is assigned to a signed int8 causes the issues later when assigning it to m_tx_power:

int8_t new_power8 = (int8_t)(new_tx_power & 0xFF);

// The two most significant bits are not sent in the 6 bit field of the DTM command.
// These two bits are 1's if and only if the tx_power is a negative number.
// All valid negative values have the fourth most significant bit as 1.
// All valid positive values have the fourth most significant bit as 0.
// By checking this bit, the two most significant bits can be determined.
new_power8 = (new_power8 & 0x30) != 0 ? (new_power8 | 0xC0) : new_power8;
...
m_tx_power = new_power8;

m_tx_power is defined as an int32_t which would result in a negative tx power level (i.e -8 being 0xFFFFFFF8).

When dtm_radio_validate() is called with the signed value and attempts to perform a comparison with a valid power level it fails due to RADIO_TXPOWER_TXPOWER_Neg8dBm being defined as:

#define RADIO_TXPOWER_TXPOWER_Neg8dBm (0xF8UL) /*!< -8 dBm */

If m_tx_power were to have been masked to 0xFF this would have worked correctly

However even with that fix, the RX test is still not reporting any packets

EDIT 2: 

When logging the state of the radio, the transmitter seems to be doing sensible stuff while the test is enabled:

170000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
170500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
171500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
172000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
173000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
173500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
174500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
175000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
176000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
176500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
177500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
178000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
179000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
179500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
180500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
181000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
182000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
182500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
183500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
184000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
185000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
185500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
186500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
187000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
188000: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
188500: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248
189500: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 248
190000: Radio - STATE: 11, MODE: 4, FREQ: 42, TX POWER: 248

It appears to be alternating between between disabled and Transmitting. As the sampling on occurs when an event wakes the nRF up I am missing the ramp up stage for the TX. Interestingly it appears the TX state occurs once a second or so based on events waking the nRF device up.

For the RX the situation is very different:

cmd: 1(0x01), freq: 20(0x14), length: 1(01), payload: 0(0x00)
Ret: 0 Evt: 0
Radio - STATE: 1, MODE: 4, FREQ: 42, TX POWER: 0
152936: Radio - STATE: 1, MODE: 4, FREQ: 42, TX POWER: 0
152936: Radio - STATE: 3, MODE: 4, FREQ: 42, TX POWER: 0
152936: Radio - STATE: 3, MODE: 4, FREQ: 42, TX POWER: 0
152946: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152946: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152947: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152974: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152974: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
152975: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
...
153930: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
153930: Radio - STATE: 0, MODE: 4, FREQ: 42, TX POWER: 0
Ret: 0 Evt: 32768 <- 1 second has passed and the RX test terminated

It starts by going into the RX ramp up state and then stays in RX mode for a very short amount of time (I estimate this to be maybe ~12ms) before going to disabled for the remainder of the time

[Håkon Alseth]

Hi,

 

Alex Crombie said:

It appears to be alternating between between disabled and Transmitting. As the sampling on occurs when an event wakes the nRF up I am missing the ramp up stage for the TX. Interestingly it appears the TX state occurs once a second or so based on events waking the nRF device up.

This is expected. The DTM protocol states that each slot should be setup in a n*625 (n=1..4, based on payload length). When the transmission is finished, it will return to idle state and await for the next slot to occur. 

 

Alex Crombie said:

It starts by going into the RX ramp up state and then stays in RX mode for a very short amount of time (I estimate this to be maybe ~12ms) before going to disabled for the remainder of the time

The receiver should work similar as the TX part, meaning that it should be disabled upon valid NRF_RADIO->EVENTS_END event, and restart the RX again in the function "dtm_wait()". Very strange that it does not restart into RX mode here.

 

Alex Crombie said:

There appears to be a bug in the setting of the TX power first and then starting the radio in 2M mode:

If you update to a newer ble_dtm, the power-setting bug should be fixed.

This bug should not affect the RX test.

 

Alex Crombie said:

It starts by going into the RX ramp up state and then stays in RX mode for a very short amount of time (I estimate this to be maybe ~12ms) before going to disabled for the remainder of the time

 Could you try with another test setup, for instance: channel 2440, 1MBit, 37 bytes payload length?

 

Kind regards,

Håkon

[Alex Crombie]

Hi Håkon,

Håkon Alseth said:

If you update to a newer ble_dtm, the power-setting bug should be fixed.

I thought that is probably the case.

Håkon Alseth said:

Could you try with another test setup, for instance: channel 2440, 1MBit, 37 bytes payload length?

I have tried this and the same thing is happening. The TX waking time is faster as you described above due to the shorter packet length, but the RX when performing the test with both a packet length of 37 bytes and 1 byte showed identical results where it would ramp up to RX and then stay disabled returning a packet count of 0

[Håkon Alseth]

Hi,

 

Alex Crombie said:

I have tried this and the same thing is happening. The TX waking time is faster as you described above due to the shorter packet length, but the RX when performing the test with both a packet length of 37 bytes and 1 byte showed identical results where it would ramp up to RX and then stay disabled returning a packet count of 0

Have you tried debugging to see if the NRF_RADIO->TASKS_RXEN in dtm_wait() is continuously called? 

 

Kind regards,

Håkon

[Alex Crombie]

Hi Håkon,

I have added debugging to dtm_wait() and have also reverted the code to wake up only on events (rather than busy looping) while running the 1M test you proposed.

I mistakenly used the wrong channel and had the device in RX waking up every so often in the RX state:

Radio - STATE: 0, MODE: 3, FREQ: 42, TX POWER: 0
cmd: 1(0x01), freq: 20(0x14), length: 1(01), payload: 0(0x00)
Ret: 0 Evt: 0
Radio - STATE: 1, MODE: 3, FREQ: 42, TX POWER: 0
94474: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
95000: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
95500: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
96500: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
97500: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
98000: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
99000: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
99477: Radio - STATE: 3, MODE: 3, FREQ: 42, TX POWER: 0
cmd: 3(0x03), freq: 0(0x00), length: 0(00), payload: 0(0x00)
Ret: 0 Evt: 32768

However in the case where the channel is correct, the device is waking up periodically in the disabled state.

cmd: 1(0x01), freq: 19(0x13), length: 1(01), payload: 0(0x00)
Ret: 0 Evt: 0
Radio - STATE: 1, MODE: 3, FREQ: 40, TX POWER: 0
513041: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513045: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513046: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513046: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513047: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513048: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513048: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513049: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513050: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
513500: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
514500: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
515000: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
516000: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
517000: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
517500: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
518044: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
518500: Radio - STATE: 0, MODE: 3, FREQ: 40, TX POWER: 0
cmd: 3(0x03), freq: 0(0x00), length: 0(00), payload: 0(0x00)
Ret: 0 Evt: 32768

When I first implemented this firmware, I must have missed the need to call dtm_wait(). Having added this to our code it now works correctly.

Thank you very much for your help and time