LTE-M: sending data on trigger and periodic event

[Hercogs]

Hello!

I am using NRF1960 Feather boars and NRF Connect v1.7.0 for developing firmware.

I have a task to send data to server using LTE-M in 2 cases:

• periodically status update (for example every 3 hours);
• on trigger event (For example, if somebody push button, device need to connect some information for server as soon as possible (in best scenario under 2 seconds, if possible))

I must use some power saving mode - PSM during inactivity time, to save battery.

The question is - how to correctly implement that?

I have read some tutorials about implementing LTE-M:

•  Guidelines (LTE) 
•  Measuring PSM idle current on the nRF91 DK 
• and more;

As I understand, I could use TAU timer for periodically sending data to server. As before sending data, TAU process is needed, it is recommended to make data interval equal to TAU timer or multiply of that. But how exactly can I achieve that? How to synchronize those 2 events, that after TAU timer expires, it automatically send data after TAU procedure?

But what would be suggested way to request data from server during trigger event?

Could it be good idea to to do these steps avoiding to use TAU timer (to be honest I do not understand purpose of TAU timer if TAU procedure is done before sending data automatically)?

• Initialize LTE module
• Sending modem to offline mode
• And then using regular timer or trigger event send LTE modem to normal mode (lte_lc_normal() and send all status data or request needed data)
• And again send modem to offline mode

I would be glad to hear some advices or some some tutorials who which explains how to achieve this correctly to optimize battery usage, data usage (LTE-M usage costs) and  get some small data from server under couple of seconds in trigger event.

 

[Didrik Rokhaug]

Hi,

Could it be good idea to to do these steps avoiding to use TAU timer (to be honest I do not understand purpose of TAU timer if TAU procedure is done before sending data automatically)?

When connected to the network, the device must send Tracking Area Updates (TAU) at a regular interval. PSM allows us to extend those intervals, as well as turning the radio off between the TAUs.

However, the TAU interval only specifies the longest time that can pass between two TAUs, the device can send TAUs more often. This means that you don't have to wait for the next scheduled TAU to send data. You can always send data when you want, and the modem will do the TAU as part of the connection re-establishement.

I have a task to send data to server using LTE-M in 2 cases:

• periodically status update (for example every 3 hours);
• on trigger event (For example, if somebody push button, device need to connect some information for server as soon as possible (in best scenario under 2 seconds, if possible))

I must use some power saving mode - PSM during inactivity time, to save battery.

The question is - how to correctly implement that?

Enable PSM at startup (https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.1.0/nrf/libraries/modem/lte_lc.html#enabling-power-saving-features), then start a timer for the periodic transmissions. When the timer runs out, or you detect the trigger, send the data.

Could it be good idea to to do these steps avoiding to use TAU timer (to be honest I do not understand purpose of TAU timer if TAU procedure is done before sending data automatically)?

• Initialize LTE module
• Sending modem to offline mode
• And then using regular timer or trigger event send LTE modem to normal mode (lte_lc_normal() and send all status data or request needed data)
• And again send modem to offline mode

Switching between offline and normal mode is more expensive than a TAU, because you will have to do a full network re-attach. However, it might be a good fallback if you don't get granted PSM by the network.

Best regards,

Didrik

[Hercogs]

Thank you for answer. Not it is more clear. I can connect to server and set PSM mode without problem.

Although couple more questions.

In LTE link controller documentation it says, that I can set:

• TAU prewarning notifications

I already achieve to set it, but how exactly can I know, how many seconds before TAU timer expires this pre warning event will be called? Is it some default value?

And second question. When entering in  and exiting from PSM mode in "lte_handler" function , I tried to see TAU timer actual value. I tried like this (did not understand, if  evt->time or evt->modem_sleep.time is correct):

case LTE_LC_EVT_MODEM_SLEEP_ENTER:
			LOG_INF("Eneter sleep mode: %d, time value: %lld, timer value: %lld\n", evt->modem_sleep.type, evt->modem_sleep.time, evt->time);

			break;

But output is some large numbers (the same output is when I try push button and send some data to server, so it exit from PSM mode ):

<inf> Lesson3_Exercise1: Eneter sleep mode: 1, time value: 4294967297, timer value: 613102286537704

So I guess, it is not the actual TAU timer value, because when setting TAU timer, I got respond from net network, that:

<inf> Lesson3_Exercise1: TAU interval: 3600, Active time: 60

So, how exactly it is possible to to get TAU timer actual value (to know, after how long it will expire)?

Any help would be appreciated.

[Didrik Rokhaug]

evt->time is for the LTE_LC_EVT_TAU_PRE_WARNING event.

However, the evt->modem_sleep.time also looks strange.

Could you enable logging in the LTE link controller library, so we can see the AT commands the numbers originate from?

CONFIG_LOG=y

CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y

[Hercogs]

I enabled logging!

So, here is prf.conf file.

#
# Copyright (c) 2022 Nordic Semiconductor ASA
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#

# Logging
CONFIG_LOG=y

# Button and LED support
CONFIG_DK_LIBRARY=y

CONFIG_NEWLIB_LIBC=y

# Network
# STEP 2.1 - Configure the Zephyr networking API
CONFIG_NETWORKING=y
CONFIG_NET_NATIVE=n
# STEP 2.2 - Enable and configure the BSD sockets compatible API
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_OFFLOAD=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y

# Memory
CONFIG_HEAP_MEM_POOL_SIZE=4096
CONFIG_MAIN_STACK_SIZE=4096

# Modem library
CONFIG_NRF_MODEM_LIB=y

# LTE link control
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n
CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y

# Booloader
CONFIG_BOOTLOADER_MCUBOOT=y

# LTE-M notification
CONFIG_LTE_LC_MODEM_SLEEP_NOTIFICATIONS=y
CONFIG_LTE_LC_TAU_PRE_WARNING_NOTIFICATIONS=y

And here is source file:

/*
 * Copyright (c) 2022 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 */
#include <zephyr.h>
#include <stdio.h>
#include <kernel.h>
#include <logging/log.h>
#include <dk_buttons_and_leds.h>
#include <modem/lte_lc.h>



/* STEP 3 - Include the header file for the socket API */
#include <net/socket.h>

/* STEP 4 - Define the hostname and port for the echo server */
#define SERVER_HOSTNAME "nordicecho.westeurope.cloudapp.azure.com"
#define SERVER_PORT "2444"

#define MESSAGE_SIZE 256 
#define MESSAGE_TO_SEND "Hello from nRF9160 SiP"
#define SSTRLEN(s) (sizeof(s) - 1)

/* STEP 5.1 - Declare the structure for the socket and server address */
static int sock;
static struct sockaddr_storage server;

/* STEP 5.2 - Declare the buffer for receiving from server */
static uint8_t recv_buf[MESSAGE_SIZE];

K_SEM_DEFINE(lte_connected, 0, 1);

LOG_MODULE_REGISTER(Lesson3_Exercise1, LOG_LEVEL_INF);

static int server_resolve(void)
{
	/* STEP 6.1 - Call getaddrinfo() to get the IP address of the echo server */
	int err;
	struct addrinfo *result;
	struct addrinfo hints = {
		.ai_family = AF_INET,
		.ai_socktype = SOCK_DGRAM,
	};
	
	err = getaddrinfo(SERVER_HOSTNAME, SERVER_PORT, &hints, &result);
	if (err != 0) {
		LOG_INF("ERROR: getaddrinfo failed %d", err);
		return -EIO;
	}

	if (result == NULL) {
		LOG_INF("ERROR: Address not found");
		return -ENOENT;
	} 	

	/* STEP 6.2 - Retrieve the relevant information from the result structure*/
	struct sockaddr_in *server4 = ((struct sockaddr_in *)&server);

	server4->sin_addr.s_addr =
		((struct sockaddr_in *)result->ai_addr)->sin_addr.s_addr;
	server4->sin_family = AF_INET;
	server4->sin_port = ((struct sockaddr_in *)result->ai_addr)->sin_port;
	
	/* STEP 6.3 - Convert the address into a string and print it */
	char ipv4_addr[NET_IPV4_ADDR_LEN];
	inet_ntop(AF_INET, &server4->sin_addr.s_addr, ipv4_addr,
		  sizeof(ipv4_addr));
	LOG_INF("IPv4 Address found %s", ipv4_addr);
	
	/* STEP 6.4 - Free the memory allocated for result */
	freeaddrinfo(result);

	return 0;
}

static int server_connect(void)
{
	int err;
	/* STEP 7 - Create a UDP socket */
	sock = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
	if (sock < 0) {
		LOG_ERR("Failed to create socket: %d.", errno);
		return -errno;
	}

	/* STEP 8 - Connect the socket to the server */
	err = connect(sock, (struct sockaddr *)&server,
		      sizeof(struct sockaddr_in));
	if (err < 0) {
		LOG_ERR("Connect failed : %d", errno);
		return -errno;
	}
	LOG_INF("Successfully connected to server");

	return 0;
}

static void lte_handler(const struct lte_lc_evt *const evt)
{
     switch (evt->type) {
		case LTE_LC_EVT_NW_REG_STATUS:
			if ((evt->nw_reg_status != LTE_LC_NW_REG_REGISTERED_HOME) &&
				(evt->nw_reg_status != LTE_LC_NW_REG_REGISTERED_ROAMING)) {
				if(evt->nw_reg_status == LTE_LC_NW_REG_NOT_REGISTERED) {
					LOG_INF("Network connection lost!\n");
				}
				break;
			}
			LOG_INF("Network registration status: %s",
					evt->nw_reg_status == LTE_LC_NW_REG_REGISTERED_HOME ?
					"Connected - home network" : "Connected - roaming");
			k_sem_give(&lte_connected);
			break;
		case LTE_LC_EVT_RRC_UPDATE:
			LOG_INF("RRC mode: %s", evt->rrc_mode == LTE_LC_RRC_MODE_CONNECTED ? 
					"Connected" : "Idle");
			break;
		case LTE_LC_EVT_PSM_UPDATE:
			LOG_INF("TAU interval: %d, Active time: %d\n", evt->psm_cfg.tau, evt->psm_cfg.active_time);
			break;
		case LTE_LC_EVT_EDRX_UPDATE:
			LOG_INF("LTE mode: %d, eDRX interval: %f.2f, paging time window: %f.2\n", evt->edrx_cfg.mode, evt->edrx_cfg.edrx, evt->edrx_cfg.ptw);
			break;
		case LTE_LC_EVT_CELL_UPDATE:
			LOG_INF("LTE_LC_EVT_CELL_UPDATE");
			break;
		case LTE_LC_EVT_LTE_MODE_UPDATE:
			LOG_INF("LTE mode update to: %s", evt->lte_mode == LTE_LC_LTE_MODE_NONE ?
					"None" : evt->lte_mode == LTE_LC_LTE_MODE_LTEM ? "LTE-M" : "NB-IoT");

			break;
		case LTE_LC_EVT_TAU_PRE_WARNING:
			LOG_INF("TAU timer pre warning. Time until next TAU: %lld\n", evt->time);

			break;
		case LTE_LC_EVT_NEIGHBOR_CELL_MEAS:
			LOG_INF("LTE_LC_EVT_NEIGHBOR_CELL_MEAS");
			break;
		case LTE_LC_EVT_MODEM_SLEEP_EXIT_PRE_WARNING:
			LOG_INF("Pre exit warning, mode: %d, time value: %lld, timer value: %lld\n", evt->modem_sleep.type, evt->modem_sleep.time, evt->time);
			break;
		case LTE_LC_EVT_MODEM_SLEEP_EXIT:
			LOG_INF("Exit sleep mode: %d, time value: %lld, timer value: %lld\n", evt->modem_sleep.type, evt->modem_sleep.time, evt->time);
			break;
		case LTE_LC_EVT_MODEM_SLEEP_ENTER:
			LOG_INF("Eneter sleep mode: %d, time value: %lld, timer value: %lld\n", evt->modem_sleep.type, evt->modem_sleep.time, evt->time);

			break;		 
		default:
				break;
		}
}

static void modem_configure(void)
{
	LOG_INF("Connecting to LTE network"); 

	int err;

	err = lte_lc_init();
	if (err) {
		printk("lte_lc_init, error: %d\n", err);
	}

	err = lte_lc_psm_param_set("00000110", "00100001"); // 20 sec, 1 minute
	if (err) {
		printk("lte_lc_psm_param_set, error: %d\n", err);
	}
	err = lte_lc_psm_req(true);
	if (err) {
		printk("lte_lc_psm_req, error: %d\n", err);
	}
	err = lte_lc_edrx_req(false);
	if (err) {
		printk("lte_lc_edrx_req, error: %d\n", err);
	}


	err = lte_lc_connect_async(lte_handler);

	if (err) {
		LOG_INF("Modem could not be configured, error: %d", err);
		return;
	}
	k_sem_take(&lte_connected, K_FOREVER);
	LOG_INF("Connected to LTE network");
	dk_set_led_on(DK_LED1);
}

static void button_handler(uint32_t button_state, uint32_t has_changed)
{
	switch (has_changed) {
	case DK_BTN1_MSK:
		/* STEP 9 - call send() when button 1 is pressed */
		if (button_state & DK_BTN1_MSK){
			/*As for PSM configuration*/
			int tau, active_time;
			//int *p_tau = &tau, *p_active_time = &active_time;
			int errr = lte_lc_psm_get(&tau, &active_time);
			if (errr) {
				printk("lte_lc_psm_get, error: %d\n", errr);
			} else {
				LOG_INF("Tau: %d, active time: %d", tau, active_time);
			}

			int err = send(sock, MESSAGE_TO_SEND, SSTRLEN(MESSAGE_TO_SEND), 0);
			if (err < 0) {
				LOG_INF("Failed to send message, %d", errno);
				return;
			} LOG_INF("Successfully sent message: %s", MESSAGE_TO_SEND);
		}
		break;
	}
}

void main(void)
{
	int received;

	if (dk_leds_init() != 0) {
		LOG_ERR("Failed to initialize the LED library");
	}

	modem_configure();

	if (dk_buttons_init(button_handler) != 0) {
		LOG_ERR("Failed to initialize the buttons library");
	}

	if (server_resolve() != 0) {
		LOG_INF("Failed to resolve server name");
		return;
	}
	
	if (server_connect() != 0) {
		LOG_INF("Failed to initialize client");
		return;
	}

	LOG_INF("Press button 1 on your DK or Thingy:91 to send your message");

		while (1) {
			/* STEP 10 - Call recv() to listen to received messages */
			received = recv(sock, recv_buf, sizeof(recv_buf) - 1, 0);

			if (received < 0) {
				LOG_ERR("Socket error: %d, exit", errno);
				break;
			}

			if (received == 0) {
				LOG_ERR("Empty datagram");
				break;
			}

			recv_buf[received] = 0;
			LOG_INF("Data received from the server: (%s)", recv_buf);
			
		}
		(void)close(sock);
}

And here is log file:

PS C:\zephyr-template\app_echo_server> zephyr-tools-monitor --port COM28 --follow --save
Connecting..
Connected to COM28!
*** Booting Zephyr OS build v2.6.99-ncs1  ***
[00:00:00.260,559] <inf> Lesson3_Exercise1: Connecting to LTE network
[00:00:00.267,486] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) are already configured
[00:00:00.281,860] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:00:00.282,104] <dbg> lte_lc.lte_lc_psm_param_set: RPTAU set to 00000110
[00:00:00.282,104] <dbg> lte_lc.lte_lc_psm_param_set: RAT set to 00100001
[00:00:00.283,081] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
[00:00:00.293,548] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:00:00.293,701] <inf> Lesson3_Exercise1: Eneter sleep mode: 4, time value: 4294967300, timer value: 613634862482408

[00:00:00.323,364] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:00:00.323,516] <inf> Lesson3_Exercise1: Exit sleep mode: 4, time value: 4294967300, timer value: 613634862482408

[00:00:01.465,881] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"AE38","003E0A26",7

[00:00:01.466,094] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
[00:00:01.466,125] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:01.466,186] <inf> Lesson3_Exercise1: LTE_LC_EVT_CELL_UPDATE
[00:00:01.466,186] <inf> Lesson3_Exercise1: LTE mode update to: LTE-M
[00:00:01.661,010] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:01.661,132] <inf> Lesson3_Exercise1: RRC mode: Connected
[00:00:02.525,512] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"AE38","003E0A26",7,,,"00100001","0~
[00:00:02.525,787] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:02.525,787] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:02.525,817] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec

[00:00:02.525,909] <inf> Lesson3_Exercise1: Network registration status: Connected - home network
[00:00:02.525,939] <inf> Lesson3_Exercise1: Connected to LTE network
[00:00:02.526,092] <inf> Lesson3_Exercise1: TAU interval: 3600, Active time: 60

[00:00:02.643,920] <inf> Lesson3_Exercise1: IPv4 Address found 20.56.165.163
[00:00:02.644,531] <inf> Lesson3_Exercise1: Successfully connected to server
[00:00:02.644,561] <inf> Lesson3_Exercise1: Press button 1 on your DK or Thingy:91 to send your message
[00:00:02.701,538] <err> log: argument 0 in source Lesson3_Exercise1 log message "IPv4 Address found %s" missinglog_strdup().
[00:00:12.326,568] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:12.326,690] <inf> Lesson3_Exercise1: RRC mode: Idle
[00:00:12.326,843] <dbg> lte_lc.at_handler: %XT3412 notification
[00:00:12.988,372] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"AE38","003E0A1C",7,,,"00100001","0~
[00:00:12.988,647] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:12.988,647] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:12.988,677] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec

[00:00:12.988,769] <inf> Lesson3_Exercise1: LTE_LC_EVT_CELL_UPDATE
[00:01:12.378,662] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:01:12.378,814] <inf> Lesson3_Exercise1: Eneter sleep mode: 1, time value: 4294967297, timer value: 613634862482408

[00:04:53.169,403] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec

[00:04:53.169,433] <dbg> lte_lc.lte_lc_psm_get: TAU: 3600 sec, active time: 60 sec

[00:04:53.169,525] <inf> Lesson3_Exercise1: Tau: 3600, active time: 60
[00:04:53.175,415] <inf> Lesson3_Exercise1: Successfully sent message: Hello from nRF9160 SiP
[00:04:53.205,230] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:04:53.205,383] <inf> Lesson3_Exercise1: Exit sleep mode: 1, time value: 4294967297, timer value: 613634862482408

[00:04:57.673,217] <dbg> lte_lc.at_handler: %XT3412 notification
[00:04:57.673,492] <dbg> lte_lc.at_handler: +CSCON notification
[00:04:57.673,614] <inf> Lesson3_Exercise1: RRC mode: Connected
[00:04:58.044,647] <inf> Lesson3_Exercise1: Data received from the server: (Time: 2022-12-05 08:21:05 Message: Hello from nRF9160 SiP)
[00:04:58.692,230] <err> log: argument 0 in source Lesson3_Exercise1 log message "Data received from the server: (%s)" missinglog_strdup().
[00:05:04.979,217] <dbg> lte_lc.at_handler: +CSCON notification
[00:05:04.979,339] <inf> Lesson3_Exercise1: RRC mode: Idle
[00:05:04.979,492] <dbg> lte_lc.at_handler: %XT3412 notification
[00:06:05.031,341] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:06:05.031,494] <inf> Lesson3_Exercise1: Eneter sleep mode: 1, time value: 4294967297, timer value: 613634862482408

[01:05:00.120,452] <dbg> lte_lc.at_handler: %XT3412 notification
[01:05:00.120,605] <inf> Lesson3_Exercise1: TAU timer pre warning. Time until next TAU: 68719481736

[01:05:00.121,154] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[01:05:00.121,307] <inf> Lesson3_Exercise1: Pre exit warning, mode: 1, time value: 4294967297, timer value: 613634862482408

[01:05:05.150,726] <dbg> lte_lc.at_handler: %XT3412 notification
[01:05:05.151,031] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[01:05:05.151,153] <inf> Lesson3_Exercise1: Exit sleep mode: 1, time value: 4294967297, timer value: 613634862482408

[01:05:18.145,874] <dbg> lte_lc.at_handler: +CSCON notification
[01:05:18.146,026] <inf> Lesson3_Exercise1: RRC mode: Connected
[01:05:19.974,548] <dbg> lte_lc.at_handler: +CSCON notification
[01:05:19.974,670] <inf> Lesson3_Exercise1: RRC mode: Idle
[01:05:19.974,822] <dbg> lte_lc.at_handler: %XT3412 notification
[01:06:20.026,611] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[01:06:20.026,763] <inf> Lesson3_Exercise1: Eneter sleep mode: 1, time value: 4294967297, timer value: 613634862482408

Small explanation, what happens. 

After startup it enters in sleep mode after 60 seconds. 

After 4 minutes I pressed button to send request to server. So it exits sleep mode. And then again it enters in sleep mode. 

I can see, that TAU timer is reseted after server request and pre TAU timer warning is 5 seconds (Not sure, how it is determined, maybe by network). And TAU timer expires after 60 minutes as seted. 

But TUA timer value is no understandable as described before. 

evt->modem_sleep.time and evt.time is strange. 

[Didrik Rokhaug]

The evt->time is for the LTE_LC_EVT_TAU_PRE_WARNING event, so it is expected to be invalid for LTE_LC_EVT_MODEM_SLEEP_* events.

However, evt->modem_sleep.time should give you the proper value. And when I run the code you attached, or a small project I created myself, I get the correct values.

Which SDK version are you using? And which toolchain version?

Did you install the SDK and toolchain with the Toolchain Manager or did you install them manually?

Could you try this project, and see if you get the proper values printed?

1401.sleep_time.zip

Hercogs said:

I can see, that TAU timer is reseted after server request and pre TAU timer warning is 5 seconds (Not sure, how it is determined, maybe by network

The pre-warning time is selected by the application, when it sends the %XMODEMSLEEP command. In this case, that is handled by the LTE link control library, which defaults to 5 seconds. You can change it by setting CONFIG_LTE_LC_TAU_PRE_WARNING_TIME_MS.

[Hercogs]

So, I tested your programm and it works almost correctly. Here is log file:

Connecting..
Connected to COM28!
*** Booting Zephyr OS build v2.6.99-ncs1  ***
Hello World! circuitdojo_feather_nrf9160
%XMODEMSLEEP: 4
Modem going to type 4 sleep for -1ms
%XMODEMSLEEP: 4
Modem going to type 4 sleep for -1ms
%XMODEMSLEEP: 4,0
Modem has exited sleep. Type: 4
[00:00:00.271,118] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) are already configured
[00:00:00.292,999] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:00:00.296,356] <dbg> APP.lte_handler: Modem going to type 4 sleep for 8589934591ms
[00:00:00.296,508] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
[00:00:00.313,049] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:00:00.316,406] <dbg> APP.lte_handler: Modem going to type 4 sleep for 8589934591ms
[00:00:00.352,905] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
+CEREG: 2,"AE38","003E0A26",7
Not registered to a network
Cell update. TAC: 44600, ID: 4065830
LTE mode update: 7
+CSCON: 1
RRC update: Connected
[00:00:02.229,003] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"AE38","003E0A26",7

[00:00:02.229,187] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
[00:00:02.229,217] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:02.287,902] <dbg> lte_lc.at_handler: +CSCON notification
+CEREG: 1,"AE38","003E0A26",7,,,"00100001","00000110"
Registered to a network
PSM update. TAU: 3600, AT: 60
[00:00:04.083,160] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"AE38","003E0A26",7,,,"00100001","0~
[00:00:04.083,465] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:04.083,465] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:04.083,496] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec

+CSCON: 0
RRC update: Idle
%XT3412: 3599999
+CEREG: 1,"AE38","003E0A1C",7,,,"00100001","00000110"
Cell update. TAC: 44600, ID: 4065820
[00:00:14.364,501] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:14.367,736] <dbg> lte_lc.at_handler: %XT3412 notification
[00:00:15.029,205] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"AE38","003E0A1C",7,,,"00100001","0~
[00:00:15.029,449] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:15.029,479] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:15.029,510] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec

%XMODEMSLEEP: 1,3539950
Modem going to type 1 sleep for 3539950ms
[00:01:14.417,877] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
[00:01:14.421,691] <dbg> APP.lte_handler: Modem going to type 1 sleep for 4298507246ms
%XT3412: 5000
TAU pre-warning: 5000ms to TAU
%XMODEMSLEEP: 1,5000
Modem waking up from sleep in 5000ms
[01:00:09.507,263] <dbg> lte_lc.at_handler: %XT3412 notification
[01:00:09.512,054] <dbg> lte_lc.at_handler: %XMODEMSLEEP notification
%XT3412: 0

And loooking at 50. and 52. line strange thing happen. "printk" and "LOG_DBG" gives different output. Not sure, why???

It comes from your code:

case LTE_LC_EVT_MODEM_SLEEP_ENTER:
	printk("Modem going to type %d sleep for %lldms\n", evt->modem_sleep.type, evt->modem_sleep.time);
	LOG_DBG("Modem going to type %d sleep for %lldms", evt->modem_sleep.type, evt->modem_sleep.time);

Answering to questions:

Which SDK version are you using?

sdk-nrf v1.7.0

And which toolchain version?

 NCS Toolchain 2.1.1

Did you install the SDK and toolchain with the Toolchain Manager or did you install them manually?

I installed Toolchain with toolchain manager, but SDK using plugin:

circuitdojo.zephyr-tools

from website: https://github.com/circuitdojo/zephyr-template/

I guess, I mixed wrong SDK and Toolchain version!

[Didrik Rokhaug]

I originally tested on NCS v2.1.0, and did not see any difference between printk and LOG_DBG.

However, if I go back to 1.7.0 or 1.8.0, I see the same difference that you do, while it is gone in 1.9.0.

So it looks like some change introduced in NCS v1.9.0 removes the printk/LOG_DBG mismatch, but I haven't yet found out what causes the change in behavior.