Second HTTP request on NRF91 isn't going into PSM mode.

[SimonBursten]

I'm experimenting with the nrf91 https example to simulate my use case. In general my device will come online hourly and send some data, get a 204 response back from the server, then go to sleep again until the next hour.

For development i've configured the a 2 minute PSM. Every 2 minutes I send establish a connection to my server with a new socket, send the data, then close the socket (both server side and client side).

The first time I do this, everything works fine. After sending data and closing the connection the modem goes into psm mode with a very low ~2.9ua current, but when i go ahead and establish the second connection, that never happens. instead after going to sleep i see regular 428 ua spikes.

I know i can reuse the socket, but i'd rather not. My understanding is the modem should be detecting that there's no more data available on the network and should be putting the modem to sleep.

my config is as follows. I'm including a modem trace as well, and some screenshots of my power profile. I'm at a bit of a loss here.

CONFIG_NRF_MODEM_LIB=y

CONFIG_NETWORKING=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_NATIVE=n

CONFIG_HEAP_MEM_POOL_SIZE=1024
CONFIG_MAIN_STACK_SIZE=2048

CONFIG_MODEM_KEY_MGMT=y
CONFIG_LTE_LINK_CONTROL=y
# Request eDRX from the network

# https://aeriscom.zendesk.com/hc/en-us/articles/360049848254-Understanding-LTE-M-Power-Management-Modes
# PSM requested periodic TAU 1 hours
# CONFIG_LTE_PSM_REQ_RPTAU="00100001"
# PSM requested periodic TAU 2 minutes
CONFIG_LTE_PSM_REQ_RPTAU="10100010"
# PSM requested active time 1 seconds (immediate PSM)
CONFIG_LTE_PSM_REQ_RAT="00011111"
# edrx value ~ 1 hour
# CONFIG_LTE_RAI_REQ_VALUE="4"

CONFIG_LTE_AUTO_INIT_AND_CONNECT=y

CONFIG_NEWLIB_LIBC=y


# General options to reduce code size
CONFIG_CONSOLE=n
CONFIG_GPIO=n
CONFIG_LOG=n
CONFIG_PRINTK=n
CONFIG_SERIAL=n
CONFIG_UART_CONSOLE=n   # Set explicitly to 'n' to avoid Kconfig warning
CONFIG_USE_SEGGER_RTT=n
CONFIG_BOOT_BANNER=n
CONFIG_NET_SOCKETS_OFFLOAD=y

CONFIG_NRF_MODEM_LIB_TRACE=n

trace-2023-03-07T16-34-51.160Z.pcapng

After the first connection:

After any subsequent connections:

[Charlie]

Hi Simon,

1) Looks like your active timer is set to 31x2=62 seconds instead of 1s.

2) For the extra power consumption, the potential reason could be PSM is set too short and so SIM card will not be shut down during PSM period. Could you test with a longer PSM period?

Note:  +CPSMS can be used to set PSM period and active timers, but the value may not accept by the network operator, using %XMONITOR to check the actual timer values. See Exercise 1 – Nordic Developer Academy (nordicsemi.com)

Best regards,

Charlie

[SimonBursten]

Hi charlie,

I've included a zip of my source. Please let me know if anything stands out to you, i've made it as minimal as possible. Besides SIM issues, i'm out of ideas.

The server i'm using is a python3 http.server instance, just returning a 204 header and a content-length of 0. I can see the full response if I turn logging on.

In this project i've set the TUA to 1 hour and 6 seconds of active time, sending 200 bytes of data.

I'll also add main.c here so people can see what we are discussing without downloading the file. Note this is using NCS 1.9.1, although I didn't note any difference by trying to update to 2.2.0.

#include <string.h>
#include <zephyr.h>
#include <stdlib.h>
#include <net/socket.h>
#include <modem/nrf_modem_lib.h>
#include <net/tls_credentials.h>
#include <modem/lte_lc.h>
#include <modem/modem_key_mgmt.h>

#define HTTP_PORT xxxx

#define HTTP_HOSTNAME "xxxxxxxxxxxxxxx"

#define HTTP_HEAD \
	"PUT /xxxxxxxxxxxxxx HTTP/1.1\r\n" \
	"Host: "HTTP_HOSTNAME":xxxx\r\n" \
    "Connection: close\r\n" \
	"Content-Length: 200" \
    "\r\n\r\n"

#define HTTP_HEAD_LEN (sizeof(HTTP_HEAD) - 1)

#define RECV_BUF_SIZE 200

static char recv_buf[RECV_BUF_SIZE + 1] = {'\0'};

static const char head_buf[] = HTTP_HEAD;
static uint8_t data_buf[200] = {100};

static struct k_work_delayable server_transmission_work;

static void server_transmission_work_fn(struct k_work *work)
{
    int err;
	int fd;
	char *p;
	int bytes;
	size_t off;
	struct addrinfo *res;
	struct addrinfo hints = {
		.ai_family = AF_INET,
		.ai_socktype = SOCK_STREAM,
	};

    printk("starting run");
    err = getaddrinfo(HTTP_HOSTNAME, NULL, &hints, &res);
    if (err) {
        printk("getaddrinfo() failed, err %d\n", errno);
        return;
    }

    ((struct sockaddr_in *)res->ai_addr)->sin_port = htons(HTTP_PORT);


    if (IS_ENABLED(CONFIG_SAMPLE_TFM_MBEDTLS)) {
        fd = socket(AF_INET, SOCK_STREAM | SOCK_NATIVE_TLS, IPPROTO_TLS_1_2);
    } else {
        fd = socket(AF_INET, SOCK_STREAM, IPPROTO_TCP);
    }
    if (fd == -1) {
        printk("Failed to open socket!\n");
        goto clean_up;
    }

    struct timeval tv;
    tv.tv_sec = 10;
    tv.tv_usec = 0;
    setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char*)&tv, sizeof tv);
    // setsockopt(fd, SOL_SOCKET, SO_SNDTIMEO, (const char*)&tv, sizeof tv);

    printk("Connecting to %s\n", HTTP_HOSTNAME);
    err = connect(fd, res->ai_addr, sizeof(struct sockaddr_in));
    if (err) {
        printk("connect() failed, err: %d\n", errno);
        goto clean_up;
    }

    printk("start test\n");
    // send head
    off = 0;
    do {
        bytes = send(fd, &head_buf[off], HTTP_HEAD_LEN - off, 0);
        if (bytes < 0) {
            printk("send() failed, err %d\n", errno);
            goto clean_up;
        }
        printk("sending %d head bytes\n", bytes);
        off += bytes;
    } while (off < HTTP_HEAD_LEN);

    // send data
    off = 0;
    do {
        bytes = send(fd, &data_buf[off], sizeof(data_buf) - off, 0);
        if (bytes < 0) {
            printk("send() failed, err %d\n", errno);
            goto clean_up;
        }
        off += bytes;
    } while (off < sizeof(data_buf));

    printk("Sent %d bytes\n", off);

    off = 0;
    do {
        bytes = recv(fd, &recv_buf[off], RECV_BUF_SIZE - off, 0);
        if (bytes < 0) {
            if (errno != EAGAIN) {
                printk("recv() failed, err %d\n", errno);
                goto clean_up;
            }
        }
        off += bytes;
    } while (bytes != 0 /* peer closed connection */);

    printk("Received %d bytes\n", off);

    /* Make sure recv_buf is NULL terminated (for safe use with strstr) */
    if (off < sizeof(recv_buf)) {
        recv_buf[off] = '\0';
    } else {
        recv_buf[sizeof(recv_buf) - 1] = '\0';
    }

    printk("\n>\t %s\n\n", recv_buf);

    freeaddrinfo(res);
    (void)close(fd);
    return;
clean_up:
	freeaddrinfo(res);
	(void)close(fd);

    while (true) {

    }
}

void main(void)
{
	printk("HTTPS client sample started\n\r");
    k_work_init_delayable(&server_transmission_work,
			      server_transmission_work_fn);

    k_work_schedule(&server_transmission_work, K_NO_WAIT);
}

simon_test_sanatized.zip

[SimonBursten]

I'll also add i'm now seeing the high power state all the time. Not sure what was going on previously. I'm also talking to my SIM provider to see if it's a SIM related issue.