DTLS with certificate handshake debugging

Hello.

I'm trying to connect to a CoAP server (Thingsboard) with a certificate based DTLS socket. In Wireshark I see that the handshake failes, but not why. I post the relevant code here:

int modem_configure(void)
{
    int err;
    nrf_sec_tag_t sec_tag = SEC_TAG;

    LOG_INF("Initializing modem library");
    err = nrf_modem_lib_init();
    if (err)
    {
        LOG_ERR("Failed to initialize the modem library, error: %d", err);
        return err;
    }

    err = modem_key_mgmt_clear(sec_tag);
    if (err)
    {
        LOG_ERR("Failed to clear credentials on sectag, err %d\n", err);
    }

    err = modem_key_mgmt_write(sec_tag, MODEM_KEY_MGMT_CRED_TYPE_CA_CHAIN, myiot_onesolutions_io_cert, sizeof(myiot_onesolutions_io_cert));
    if (err)
    {
        LOG_ERR("Failed to provision certificate, err %d\n", err);
    }

    /* Disable PSM (Power Saving Mode) */
    err = lte_lc_psm_req(false);
    if (err)
    {
        LOG_ERR("Failed to disable PSM, error: %d", err);
    }

    /* Disable eDRX (Extended Discontinuous Reception) */
    err = lte_lc_edrx_req(false);
    if (err)
    {
        LOG_ERR("Failed to disable eDRX, error: %d", err);
    }

    LOG_INF("Connecting to LTE network");
    err = lte_lc_connect_async(lte_handler);
    if (err)
    {
        LOG_ERR("Error in lte_lc_connect_async, error: %d", err);
        return err;
    }

    if (k_sem_take(&lte_connected, K_SECONDS(60)) == 0)
    {
        k_event_set(&lte_connected_event, 0x001);
        LOG_INF("Connected to LTE network");
    }
    else
    {
        LOG_ERR("No connection to LTE network!");
    }

    return 0;
}

static int client_init(void)
{
    int err;
    enum
    {
        NONE = 0,
        OPTIONAL = 1,
        REQUIRED = 2,
    };
    int verify = NONE;

    sock = socket(AF_INET, SOCK_DGRAM, IPPROTO_DTLS_1_2);
    if (sock < 0)
    {
        LOG_ERR("Failed to create CoAP socket: %d.\n", errno);
        return -errno;
    }

    err = setsockopt(sock, SOL_TLS, TLS_PEER_VERIFY, &verify, sizeof(verify));
    if (err)
    {
        LOG_ERR("Failed to setup peer verification, errno %d\n", errno);
        return -errno;
    }

    err = setsockopt(sock, SOL_TLS, TLS_HOSTNAME, CONFIG_COAP_SERVER_HOSTNAME, strlen(CONFIG_COAP_SERVER_HOSTNAME));
    if (err)
    {
        LOG_ERR("Failed to setup TLS hostname (%s), errno %d\n", CONFIG_COAP_SERVER_HOSTNAME, errno);
        return -errno;
    }

    uint8_t cyph_id[2] = {MBEDTLS_TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 >> 8, MBEDTLS_TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 & 0xFF};
    err = setsockopt(sock, SOL_TLS, TLS_CIPHERSUITE_LIST, cyph_id, sizeof(cyph_id));
    if (err)
    {
        LOG_ERR("Failed to setup cypher suit, errno %d\n", errno);
        return -errno;
    }

    sec_tag_t sec_tag_list[] = {SEC_TAG};
    err = setsockopt(sock, SOL_TLS, TLS_SEC_TAG_LIST, sec_tag_list, sizeof(sec_tag_t) * ARRAY_SIZE(sec_tag_list));
    if (err)
    {
        LOG_ERR("Failed to setup socket security tag, errno %d\n", errno);
        return -errno;
    }

    err = connect(sock, (struct sockaddr *)&server, sizeof(struct sockaddr_in));
    if (err < 0)
    {
        LOG_ERR("Connect failed : %d\n", errno);
        return -errno;
    }

    LOG_INF("Successfully connected to server");

    return 0;
}

proj.conf

# Configure Sowftware Version
CONFIG_MCUBOOT_IMGTOOL_SIGN_VERSION="1.0.16"

# Logging
CONFIG_LOG=y
CONFIG_LOG_BUFFER_SIZE=4096
CONFIG_LOG_MAX_LEVEL=4

CONFIG_EVENTS=y

# Newlib
CONFIG_NEWLIB_LIBC=y

CONFIG_GPIO=y
CONFIG_SPI=y
CONFIG_SPI_NOR=y
CONFIG_SPI_NOR_SFDP_DEVICETREE=y
CONFIG_SPI_NOR_FLASH_LAYOUT_PAGE_SIZE=4096
# QSPI drivers are enabled by defualt for some chips.
# Disable it explicitly to be sure QSPI is disabled.
CONFIG_NORDIC_QSPI_NOR=n

# Enable flash operations
CONFIG_FLASH=y
CONFIG_FLASH_MAP=y
CONFIG_FLASH_PAGE_LAYOUT=y

# Enable file system
CONFIG_FILE_SYSTEM=y
CONFIG_FILE_SYSTEM_LITTLEFS=y
CONFIG_PM_PARTITION_REGION_LITTLEFS_EXTERNAL=y
# LittleFS with ~30MB
CONFIG_PM_PARTITION_SIZE_LITTLEFS=0x1C00000

# Modem library
CONFIG_NRF_MODEM_LIB=y
CONFIG_MODEM_KEY_MGMT=y

# LTE link control
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_NETWORK_MODE_LTE_M_NBIOT=y
CONFIG_LTE_LC_EDRX_MODULE=y
CONFIG_LTE_LC_PSM_MODULE=y
CONFIG_LTE_EDRX_REQ=n
CONFIG_LTE_PSM_REQ=n

# Network
CONFIG_NETWORKING=y
CONFIG_NET_NATIVE=n
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_OFFLOAD=y
CONFIG_POSIX_API=y

# CoAP
CONFIG_COAP=y
CONFIG_COAP_CLIENT=y
CONFIG_COAP_CLIENT_BLOCK_SIZE=1024
CONFIG_COAP_CLIENT_MAX_REQUESTS=100
CONFIG_COAP_CLIENT_STACK_SIZE=2048
CONFIG_COAP_CLIENT_THREAD_PRIORITY=-2
CONFIG_COAP_SERVER_HOSTNAME="myiot.one-solutions.io"
CONFIG_COAP_SERVER_PORT=5684

CONFIG_IMG_MANAGER=y
CONFIG_STREAM_FLASH=y
CONFIG_DFU_TARGET=y
CONFIG_DFU_TARGET_MCUBOOT=y

# Memory
CONFIG_HEAP_MEM_POOL_SIZE=4096
CONFIG_MAIN_STACK_SIZE=4096

################ SHA-256 ###########################
# Using hardware crypto accelerator
CONFIG_PSA_CRYPTO_DRIVER_CC3XX=y
CONFIG_TFM_PROFILE_TYPE_NOT_SET=y

# Enable nordic security backend and PSA APIs
CONFIG_NRF_SECURITY=y
CONFIG_MBEDTLS_PSA_CRYPTO_C=y

CONFIG_PSA_WANT_ALG_SHA_256=y
####################################################

################ DTLS ##############################
CONFIG_MBEDTLS_DEBUG=n
CONFIG_MBEDTLS_DEBUG_C=y
CONFIG_MBEDTLS_TLS_LIBRARY=y
# --- Zeit (für Zertifikate wichtig) ---
CONFIG_DATE_TIME=y
CONFIG_DATE_TIME_AUTO_UPDATE=y
CONFIG_MODEM_KEY_MGMT_LOG_LEVEL_DBG=y
CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y
#CONFIG_NRF_MODEM_LIB_TRACE=y      # erzeugt .etrace für TLS/Handshake-Analyse
#CONFIG_MBEDTLS_PK_C=n

CONFIG_MBEDTLS_RSA_C=y
CONFIG_MBEDTLS_X509_USE_C=y
CONFIG_MBEDTLS_X509_CRT_PARSE_C=y

# --- Modem Trace (TLS-Handshake/Alerts sichtbar machen) ---
#CONFIG_UART_ASYNC_API=y
#CONFIG_NRF_MODEM_LIB_TRACE_BACKEND_RTT=y

CONFIG_MBEDTLS_DEBUG_LEVEL=4
####################################################

CONFIG_NANOPB=y

# --- Ressourcen (Handshake braucht RAM) ---
CONFIG_MAIN_STACK_SIZE=4096
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048
CONFIG_HEAP_MEM_POOL_SIZE=32768
CONFIG_LOG_BUFFER_SIZE=4096

How can I activate debug messages, so that I can find out more details why handshaking fails?
Is there any obvious mistake I made?

Thanks in advance.
BR
Christian

  • If you followed an example, maybe a "short-cut" would be, if you provide a link to that.

    And if you have a wireshark capture, that may also help, if you provide it.

    In general it may require to check, if all components (e.g. modem and server) really supports MBEDTLS_TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 for DTLS, including the size of the used certificates. And also checks, if that provided CA_CHAIN certificate also fits for that cipher suite.

  • Hi,
    Please provide a Wireshark capture and the logs. To enable debug-level logging, set CONFIG_LOG_DEFAULT_LEVEL=4.

    Best regards,
    Benjamin

  • Hi.

    I followed the example from nrf IoT fundamental course: https://academy.nordicsemi.com/courses/cellular-iot-fundamentals/lessons/lesson-5-cellular-fundamentals/topic/lesson-5-exercise-2/
    Except that I do not use PSK but certificate. Is there an example for CoAP over DTLS with certificate which I can follow?

    I'm attaching a wireshark log: coap_dtls_handshake_error.pcapng

    And the log with CONFIG_LOG_DEFAULT_LEVEL=4: 

    *** Booting MCUboot v2.1.0-dev-ae1ee57f3906 ***
    *** Using nRF Connect SDK v3.0.2-89ba1294ac9b ***
    *** Using Zephyr OS v4.0.99-f791c49f492c ***
    I: Starting bootloader
    I: Primary image: magic=good, swap_type=0x2, copy_done=0x1, image_ok=0x1
    I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
    I: Boot source: none
    I: Image index: 0, Swap type: none
    I: Bootloader chainload address offset: 0x10000
    I: Image version: v1.0.16
    �[00:00:00.250,854] <dbg> os: setup_thread_stack: stack 0x2002eb58 for thread 0x20026230: obj_size=4096 buf_start=0x2002eb58  buf_size 4096 stack_ptr=0x2002fb58
    [00:00:00.420,196] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    --- 3004 messages dropped ---
    [00:00:00.420,227] <dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x2002f898 (2), current_rx 0x2002f898 (2), tx buf/len 0x2002f8a8/5, rx buf/len 0x2002f8a8/5
    [00:00:00.420,288] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.420,318] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.420,410] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.420,440] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.420,471] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    [00:00:00.420,562] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    [00:00:00.420,593] <dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x2002f898 (2), current_rx 0x2002f898 (2), tx buf/len 0x2002f8a8/5, rx buf/len 0x2002f8a8/5
    [00:00:00.420,654] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.420,684] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.420,776] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.420,806] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.420,837] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    [00:00:00.420,928] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    [00:00:00.420,959] <dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x2002f898 (2), current_rx 0x2002f898 (2), tx buf/len 0x2002f8a8/5, rx buf/len 0x2002f8a8/5
    [00:00:00.421,020] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.421,051] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.421,112] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.421,142] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.421,173] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    [00:00:00.421,264] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    [00:00:00.421,295] <dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x2002f898 (2), current_rx 0x2002f898 (2), tx buf/len 0x2002f8a8/5, rx buf/len 0x2002f8a8/5
    [00:00:00.421,356] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.421,386] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.421,478] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.421,508] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.421,539] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    --- 5 messages dropped ---
    [00:00:00.421,875] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    --- 8 messages dropped ---
    [00:00:00.422,363] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    --- 1 messages dropped ---
    [00:00:00.422,454] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.422,485] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.422,576] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.422,607] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    --- 3 messages dropped ---
    [00:00:00.422,821] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.422,851] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.422,943] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.422,973] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.422,973] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    [00:00:00.423,065] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    [00:00:00.423,126] <dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x2002f898 (2), current_rx 0x2002f898 (2), tx buf/len 0x2002f8a8/5, rx buf/len 0x2002f8a8/5
    [00:00:00.423,187] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.423,217] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.423,278] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    --- 4 messages dropped ---
    [00:00:00.423,522] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.423,553] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.423,645] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.423,675] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.423,706] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    [00:00:00.423,797] <dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x2002f890 - rx_bufs 0x2002f888 - 1
    [00:00:00.423,828] <dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x2002f898 (2), current_rx 0x2002f898 (2), tx buf/len 0x2002f8a8/5, rx buf/len 0x2002f8a8/5
    [00:00:00.423,889] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20027750/16
    [00:00:00.423,919] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20027750/16
    [00:00:00.424,011] <dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0
    [00:00:00.424,041] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    [00:00:00.424,041] <dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0
    --- 12 messages dropped ---
    [00:00:00.424,743] <dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0
    --- 14 messages dropped ---
    [00:00:00.701,812] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.701,843] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.701,873] <dbg> nrf_modem: nrf_modem_lib_init: Modem init callback: 0x6ec51
    [00:00:00.701,904] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    --- 3 messages dropped ---
    [00:00:00.703,002] <dbg> lte_lc: psm_param_set: RPTAU set to 00000011
    [00:00:00.703,063] <dbg> lte_lc: psm_param_set: RAT set to 00100001
    [00:00:00.703,094] <dbg> lte_lc: on_modem_init: PSM configs set from string: tau=00000011, rat=00100001
    [00:00:00.703,155] <dbg> lte_lc: psm_req: enable=0, tau=00000011, rat=00100001
    [00:00:00.703,186] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.710,083] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.710,113] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.710,113] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.710,968] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.710,998] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.711,029] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.711,853] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.711,883] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.712,066] <dbg> lte_lc: edrx_request: enable=0, requested_edrx_value_ltem=1001, edrx_value_ltem=, requested_ptw_value_ltem=, ptw_value_ltem=, 
    [00:00:00.712,219] <dbg> lte_lc: edrx_request: enable=0, requested_edrx_value_nbiot=1001, edrx_value_nbiot=, requested_ptw_value_nbiot=, ptw_value_nbiot=
    [00:00:00.712,249] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.719,116] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.719,146] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.719,177] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x2001f044, count: 1, orig prio: 0
    [00:00:00.719,207] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.719,787] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.719,818] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.719,879] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.760,192] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.760,223] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.760,253] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.796,112] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.796,142] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.796,173] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.796,813] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.796,844] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.796,997] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.892,608] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.892,639] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.892,669] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f044 lock_count: 1
    [00:00:00.892,700] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f044: (nil) (prio: -1000)
    [00:00:00.892,730] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x2001f044, count: 1, orig prio: 0
    [00:00:00.892,761] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.893,188] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.893,218] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.893,249] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:00.893,890] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:00.893,920] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:00.893,951] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.004,791] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.004,821] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.004,852] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.005,279] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.005,279] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.005,310] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f044 lock_count: 1
    [00:00:01.005,340] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f044: (nil) (prio: -1000)
    [00:00:01.005,401] <dbg> lte_lc: psm_req: enable=0, tau=00000011, rat=00100001
    [00:00:01.005,432] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.006,042] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.006,072] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.006,256] <dbg> lte_lc: edrx_request: enable=0, requested_edrx_value_ltem=1001, edrx_value_ltem=, requested_ptw_value_ltem=, ptw_value_ltem=, 
    [00:00:01.006,408] <dbg> lte_lc: edrx_request: enable=0, requested_edrx_value_nbiot=1001, edrx_value_nbiot=, requested_ptw_value_nbiot=, ptw_value_nbiot=
    [00:00:01.006,439] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.013,275] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.013,305] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.013,336] <inf> lte_service: Connecting to LTE network
    [00:00:01.013,366] <dbg> lte_lc: lte_lc_connect_async: Connecting asynchronously
    [00:00:01.013,397] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x2001f058, count: 1, orig prio: 0
    [00:00:01.013,458] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:01.013,488] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:01.013,519] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.020,507] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.020,538] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.020,568] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.026,916] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.026,947] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.026,977] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.027,526] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.027,557] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.027,618] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.028,015] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.028,045] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.028,106] <dbg> os: z_impl_k_mutex_lock: 0x20026230 took mutex 0x20027aa0, count: 1, orig prio: 0
    [00:00:01.060,455] <dbg> nrf_modem: cfun_callback: CFUN callback 0x72c65
    [00:00:01.060,485] <dbg> nrf_modem: cfun_callback: CFUN callback 0x6edf1
    [00:00:01.060,516] <dbg> nrf_modem: cfun_callback: CFUN callback 0x70d55
    [00:00:01.060,577] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.060,607] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.060,638] <dbg> lte_lc: cfun_mode_set: Functional mode set to 1
    [00:00:01.859,710] <dbg> os: z_impl_k_mutex_lock: 0x20026040 took mutex 0x20027aa0, count: 1, orig prio: 14
    [00:00:01.860,229] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:01.860,229] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:01.860,260] <dbg> date_time: date_time_modem_xtime_subscribe_work_fn: Subscribing to modem AT%XTIME notifications succeeded
    [00:00:05.652,557] <dbg> at_monitor: at_monitor_task: AT notif: +CEREG: 2,"36E2","0115232A",7
    [00:00:05.652,648] <dbg> at_monitor: at_monitor_task: Dispatching to 0x6fa0d
    [00:00:05.652,709] <dbg> lte_lc: at_handler_cereg: +CEREG notification: +CEREG: 2,"36E2","0115232A",7
    [00:00:05.652,770] <dbg> lte_lc: parse_cereg: Network registration status: 2
    [00:00:05.652,954] <dbg> lte_lc: parse_cereg: LTE mode: 7
    [00:00:05.652,984] <dbg> os: z_impl_k_mutex_lock: 0x20026410 took mutex 0x2001f058, count: 1, orig prio: -1
    [00:00:05.653,015] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=0
    [00:00:05.653,045] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:05.653,045] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:05.653,076] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:05.653,137] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:05.653,137] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:05.653,198] <dbg> os: z_impl_k_mutex_lock: 0x20026410 took mutex 0x2001f058, count: 1, orig prio: -1
    [00:00:05.653,198] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=4
    [00:00:05.653,228] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:05.653,259] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:05.653,259] <inf> lte_service: Cell update: MCC=0, MNC=0, ID=18162474, TAC=14050, EARFCN=0, Timing Advance=0, RSRP=0, RSRQ=0
    [00:00:05.653,289] <inf> lte_service: Measurement time: 0 ms, Timing advance measurement time: 0 ms
    [00:00:05.653,320] <inf> lte_service: Physical Cell ID: 0
    [00:00:05.653,320] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:05.653,350] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:05.653,381] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:05.653,411] <dbg> os: z_impl_k_mutex_lock: 0x20026410 took mutex 0x2001f058, count: 1, orig prio: -1
    [00:00:05.653,411] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=5
    [00:00:05.653,442] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:05.653,472] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:05.653,472] <inf> lte_service: LTE mode update: 7
    [00:00:05.653,503] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:05.653,503] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:05.653,533] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:05.694,305] <dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 1
    [00:00:05.694,335] <dbg> at_monitor: at_monitor_task: Dispatching to 0x700ed
    [00:00:05.694,366] <dbg> lte_lc: at_handler_cscon: +CSCON notification
    [00:00:05.694,427] <dbg> os: z_impl_k_mutex_lock: 0x20026410 took mutex 0x2001f058, count: 1, orig prio: -1
    [00:00:05.694,458] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3
    [00:00:05.694,488] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:05.694,519] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:05.694,549] <inf> lte_service: RRC mode: Connected
    [00:00:05.694,580] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:05.694,580] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:05.694,610] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:06.710,327] <dbg> at_monitor: at_monitor_task: AT notif: +CEREG: 1,"36E2","0115232A",7,,,"11100000","11100000"
    [00:00:06.710,388] <dbg> at_monitor: at_monitor_task: Dispatching to 0x6fa0d
    [00:00:06.710,449] <dbg> lte_lc: at_handler_cereg: +CEREG notification: +CEREG: 1,"36E2","0115232A",7,,,"11100000","11100000"
    [00:00:06.710,510] <dbg> lte_lc: parse_cereg: Network registration status: 1
    [00:00:06.710,754] <dbg> lte_lc: parse_cereg: LTE mode: 7
    [00:00:06.710,845] <dbg> lte_lc: parse_cereg: Active time: 11100000
    [00:00:06.710,906] <dbg> lte_lc: parse_cereg: TAU: 11100000
    [00:00:06.710,968] <dbg> lte_lc: psm_parse: TAU: -1 sec, active time: -1 sec
    [00:00:06.710,968] <dbg> os: z_impl_k_mutex_lock: 0x20026410 took mutex 0x2001f058, count: 1, orig prio: -1
    [00:00:06.710,998] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=0
    [00:00:06.711,059] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:06.711,090] <dbg> date_time: date_time_lte_ind_handler: Date time update scheduled in 1 second due to LTE registration
    [00:00:06.711,120] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:06.711,151] <inf> lte_service: Network registration status: Connected - home network
    [00:00:06.711,181] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:06.711,212] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:06.711,242] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:06.711,334] <inf> lte_service: Connected to LTE network
    [00:00:06.711,944] <inf> coap_service2: IPv4 Address found 172.31.14.176
    
    [00:00:06.711,975] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001f030, count: 1, orig prio: 5
    [00:00:06.712,005] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f030 lock_count: 1
    [00:00:06.712,036] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f030: (nil) (prio: -1000)
    [00:00:06.712,249] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001f01c, count: 1, orig prio: 5
    [00:00:06.712,280] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f01c lock_count: 1
    [00:00:06.712,310] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f01c: (nil) (prio: -1000)
    [00:00:06.712,341] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001e7d8, count: 1, orig prio: 5
    [00:00:06.712,371] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001e7d8 lock_count: 1
    [00:00:06.712,402] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001e7d8: (nil) (prio: -1000)
    [00:00:06.712,402] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001e7d8, count: 1, orig prio: 5
    [00:00:06.712,463] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001e7d8 lock_count: 1
    [00:00:06.712,493] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001e7d8: (nil) (prio: -1000)
    [00:00:06.712,524] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001e7d8, count: 1, orig prio: 5
    [00:00:06.712,768] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001e7d8 lock_count: 1
    [00:00:06.712,799] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001e7d8: (nil) (prio: -1000)
    [00:00:06.712,799] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001e7d8, count: 1, orig prio: 5
    [00:00:06.712,829] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001e7d8 lock_count: 1
    [00:00:06.712,860] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001e7d8: (nil) (prio: -1000)
    [00:00:06.712,890] <dbg> os: z_impl_k_mutex_lock: 0x2001f390 took mutex 0x2001e7d8, count: 1, orig prio: 5
    [00:00:06.728,698] <dbg> at_monitor: at_monitor_task: AT notif: %XTIME: "80","52901081319280","01"
    [00:00:06.728,759] <dbg> at_monitor: at_monitor_task: Dispatching to 0x7271d
    [00:00:06.728,790] <dbg> date_time: date_time_core_current_check: Date time never set
    [00:00:06.728,820] <dbg> date_time: date_time_at_xtime_handler: Time obtained from cellular network (XTIME notification)
    [00:00:06.728,881] <dbg> date_time: date_time_core_schedule_update: New periodic date time update in: 14400 seconds
    [00:00:06.728,942] <dbg> date_time: date_time_core_store_tz: System time updated: 2025-09-01 18:13:29+08
    [00:00:06.728,942] <dbg> date_time: date_time_core_notify_event: No date-time event handler registered
    [00:00:06.930,053] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001e7d8 lock_count: 1
    [00:00:06.930,084] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001e7d8: (nil) (prio: -1000)
    [00:00:06.930,084] <err> coap_service2: Connect failed : 111
    
    [00:00:06.930,114] <inf> coap_service2: Failed to initialize client
    [00:00:07.151,672] <dbg> os: z_impl_k_mutex_lock: 0x20025f08 took mutex 0x20027aa0, count: 1, orig prio: 14
    [00:00:07.152,801] <dbg> os: z_impl_k_mutex_unlock: mutex 0x20027aa0 lock_count: 1
    [00:00:07.152,832] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x20027aa0: (nil) (prio: -1000)
    [00:00:07.153,167] <dbg> lte_lc: psm_parse: TAU: 3240 sec, active time: -1 sec
    [00:00:07.153,167] <dbg> lte_lc: psm_get: TAU: 3240 sec, active time: -1 sec
    [00:00:07.153,198] <dbg> os: z_impl_k_mutex_lock: 0x20025f08 took mutex 0x2001f058, count: 1, orig prio: 14
    [00:00:07.153,228] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=1
    [00:00:07.153,259] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:07.153,259] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:07.153,289] <inf> lte_service: PSM update: tau=3240, active_time=-1
    [00:00:07.153,320] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:07.153,350] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:07.153,381] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)
    [00:00:17.816,894] <dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 0
    [00:00:17.816,925] <dbg> at_monitor: at_monitor_task: Dispatching to 0x700ed
    [00:00:17.816,955] <dbg> lte_lc: at_handler_cscon: +CSCON notification
    [00:00:17.817,016] <dbg> os: z_impl_k_mutex_lock: 0x20026410 took mutex 0x2001f058, count: 1, orig prio: -1
    [00:00:17.817,047] <dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3
    [00:00:17.817,077] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x000718D9
    [00:00:17.817,077] <dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0006261D
    [00:00:17.817,138] <inf> lte_service: RRC mode: Idle
    [00:00:17.817,138] <dbg> lte_lc: event_handler_list_dispatch: Done
    [00:00:17.817,169] <dbg> os: z_impl_k_mutex_unlock: mutex 0x2001f058 lock_count: 1
    [00:00:17.817,230] <dbg> os: z_impl_k_mutex_unlock: new owner of mutex 0x2001f058: (nil) (prio: -1000)

    Thanks
    BR
    Christian

  • From the capture:

    The "Client Hello" doesn't contain any cipher suite (except the TLS_EMPTY_RENEGOTIATION_INFO_SCSV). Therefore the handshake is denied by the server with a "Handshake Failure".

    Not sure, why the modem don't send a cipher suite. Maybe the DTLS implementation of the modem is compiled without support for MBEDTLS_TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (please provide the modem firmware version to check). Or the CA_CHAIN doesn't contain a RSA certificate, or that could not be used by the modem for some reasons.

  • Hello.

    Modem firmware version is 2.0.2
    Is there a way to activate more debugging output of the modem to see what is happening?
    With CONFIG_LOG_DEFAULT_LEVEL=4 there are still no modem debug infos.

    Thanks
    BR
    Christian

Related