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

Parents
  • 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

  • There is a modem trace, which contains some more information than the IP capture, but the additional information is AFAIK only readable by Nordic.

    In the past there was some documentation about the limits in TLS and DTLS and in some topics, there was a difference between TLS and DTLS. Currently I didn't find that again in the new documentation pages.

    In general. using RSA for embedded is frequently a decision, which comes with pain. ECDSA certificates are smaller and work usually with less pain.

Reply
  • There is a modem trace, which contains some more information than the IP capture, but the additional information is AFAIK only readable by Nordic.

    In the past there was some documentation about the limits in TLS and DTLS and in some topics, there was a difference between TLS and DTLS. Currently I didn't find that again in the new documentation pages.

    In general. using RSA for embedded is frequently a decision, which comes with pain. ECDSA certificates are smaller and work usually with less pain.

Children
Related