NRF_LOG_INFO output problem (output is not what actually provided)

Question

First of all,I don't study the LOG module yet,just copy & paste from example.

I'm trying to process APP_USBD_CDC_ACM_USER_EVT_RX_DONE event,print debug info to monitor the execution.

This is the buffer to receive data from USB,5 bytes max per time,reserve 1 byte for '\0':

static char m_rx_buffer[5+1];

Limit the packet size to 5 bytes to test the code:

case APP_USBD_CDC_ACM_USER_EVT_RX_DONE:
{
    ret_code_t ret;
			
	//test : pkt len = 5
	//it should can process data len bigger than 5
			
	const uint8_t bufferLen = 5;
	char buffer[50]={0};
	buffer[0] = m_rx_buffer[0];
	char* p = buffer + 1 ;
	uint8_t cntToreadPertime,cntRead;
				
    uint16_t waitingCharCount = app_usbd_cdc_acm_bytes_stored(p_cdc_acm);
    NRF_LOG_INFO("Bytes waiting: %d",waitingCharCount );

	NRF_LOG_INFO("1st byte: %c",m_rx_buffer[0] );
	
	if(waitingCharCount>0){
		while(true){
			if(waitingCharCount>bufferLen){
				cntToreadPertime = bufferLen;
				waitingCharCount -= bufferLen;
			}else{
				cntToreadPertime = waitingCharCount;
				waitingCharCount = 0;
			}
			
			NRF_LOG_INFO("read: %d chars",cntToreadPertime );
			for(int i=0;i<sizeof(m_rx_buffer);i++)
				m_rx_buffer[i] = 0;
			ret = app_usbd_cdc_acm_read(&m_app_cdc_acm, m_rx_buffer, cntToreadPertime);
			
			if(ret == NRF_SUCCESS){
				cntRead = app_usbd_cdc_acm_rx_size(p_cdc_acm);
				
				NRF_LOG_INFO("have read in %d chars : %s",cntRead,m_rx_buffer );
				
				memcpy(p,m_rx_buffer,cntRead);
				p += cntRead;
				
				if(cntRead<cntToreadPertime){
					NRF_LOG_INFO("what read out is less than want: %d < %d",cntRead,cntToreadPertime );
					waitingCharCount = app_usbd_cdc_acm_bytes_stored(p_cdc_acm);
					NRF_LOG_INFO("refresh waiting bytes: %d",waitingCharCount );
				}
			}else{
				//what to do? error triggered
				NRF_LOG_WARNING("return of app_usbd_cdc_acm_read() is error: %d,it should be 0",ret );
				break;
			}
			
			//exit,
			if(waitingCharCount == 0){
				break;
			}
			
		}//while(true)
		
	}//if(waitingCharCount>0)
	
	//waiting for following data
	//if error happened?
	app_usbd_cdc_acm_read(&m_app_cdc_acm, m_rx_buffer, 1);

	NRF_LOG_INFO("All bytes: %s",buffer );
	NRF_LOG_INFO("APP_USBD_CDC_ACM_USER_EVT_RX_DONE"); 
	
	UNUSED_VARIABLE(ret);
    UNUSED_VARIABLE(waitingCharCount);
    break;
}

Debug info is not right if data count from USB is bigger than 6:

7 bytes data means:

1) 1 byte returned by previous call to app_usbd_cdc_acm_read();

2) 5 bytes returned by current 1st call to app_usbd_cdc_acm_read();

3) 1 byte returned by current 2nd call to app_usbd_cdc_acm_read();

But the actual output like this(send string: "2345678"):

<info> app: APP_USBD_CDC_ACM_USER_EVT_PORT_OPEN
<info> app: Bytes waiting: 6
<info> app: 1st byte: 2
<info> app: read: 5 chars
<info> app: have read in 5 chars : 8
<info> app: read: 1 chars
<info> app: have read in 1 chars : 8
<info> app: All bytes: 
<info> app: APP_USBD_CDC_ACM_USER_EVT_RX_DONE

We can see the the info for 1st call is wrong, it is same with 2nd call,and no info for whole string("2345678").

I have traced the code,the returned data are right.

I thought the reason:

1)this is based on event processing model, the real process should delay for some time;

2)when real process executed,the data in variable has been changed(m_rx_buffer will keep the last data:"8" )

But I don't think the real data not buffered by LOG module.

How to do it?

Susheel Nuguru · Accepted Answer

Hi Meng, 
 I think the issue is that the logs are not flushing the data out in time while the buffer is changing, this can happen due to many reasons, one of which is if the logs are flushed to a slower transport layer like UART, try using RTT instead. The other big reason can be that the logs might be configured to be deferred, meaning that they are not flushed out to the serial immediately when NRF_LOG_XXX is executed, but instead they are flushed when there is less important context to execute. 
 To fix this you can change the below two settings in your sdk_config.h file to below 
 # define NRF_LOG_DEFERRED 0 # define NRF_LOG_NON_DEFFERED_CRITICAL_REGION_ENABLED 1 
 Maybe increase the buffer size aswell if you are using UART as backend for logs so that this is not a bottleneck 
 # define NRF_LOG_STR_PUSH_BUFFER_SIZE XXX 
 One brute force mechanism is to use NRF_LOG_FLUSH(); after every NRF_LOG_XXX call so that you are sure that every log is flushed immediately. See if this helps.

NRF_LOG_INFO output problem (output is not what actually provided)

Top Replies