diff --git a/src/transport_layer/etcp.c b/src/transport_layer/etcp.c index c55059bb..9fd05d8d 100644 --- a/src/transport_layer/etcp.c +++ b/src/transport_layer/etcp.c @@ -297,11 +297,23 @@ static void etcp_fire_conn_status(struct ETCP_CONN* etcp, int status) { static void etcp_on_up(struct ETCP_CONN* etcp) { DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection UP (links_up=%d initialized=%d)", etcp->log_name, etcp->links_up, etcp->initialized); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_ON_UP_BEFORE: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x", + etcp->log_name, + etcp->crypto_ctx.session_key[0], etcp->crypto_ctx.session_key[1], + etcp->crypto_ctx.session_key[2], etcp->crypto_ctx.session_key[3], + etcp->crypto_ctx.peer_public_key[0], etcp->crypto_ctx.peer_public_key[1], + etcp->crypto_ctx.peer_public_key[2], etcp->crypto_ctx.peer_public_key[3]); etcp->callbacks_running = 1; struct etcp_cbk_entry* cbe = etcp->up_cbks; while (cbe) { struct etcp_cbk_entry* n = cbe->next; cbe->fn(etcp, cbe->arg); cbe = n; } etcp_fire_conn_status(etcp, ETCP_CONN_STATUS_UP); etcp->callbacks_running = 0; + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_ON_UP_AFTER: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x", + etcp->log_name, + etcp->crypto_ctx.session_key[0], etcp->crypto_ctx.session_key[1], + etcp->crypto_ctx.session_key[2], etcp->crypto_ctx.session_key[3], + etcp->crypto_ctx.peer_public_key[0], etcp->crypto_ctx.peer_public_key[1], + etcp->crypto_ctx.peer_public_key[2], etcp->crypto_ctx.peer_public_key[3]); } static void etcp_on_down(struct ETCP_CONN* etcp) { @@ -592,6 +604,17 @@ void etcp_conn_ready(struct ETCP_CONN* conn) { conn->reset_done = 1; if (conn->tx_state == 0) { conn->tx_state = ETCP_TX_STATE_DATA_WAIT; } DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection ready", conn->log_name); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_CONN_READY: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x my_pub=%02x%02x%02x%02x links=%p", + conn->log_name, + conn->crypto_ctx.session_key[0], conn->crypto_ctx.session_key[1], + conn->crypto_ctx.session_key[2], conn->crypto_ctx.session_key[3], + conn->crypto_ctx.peer_public_key[0], conn->crypto_ctx.peer_public_key[1], + conn->crypto_ctx.peer_public_key[2], conn->crypto_ctx.peer_public_key[3], + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[0] : 0, + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[1] : 0, + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[2] : 0, + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[3] : 0, + (void*)conn->links); etcp_conn_queue_set_ready(conn); } diff --git a/src/transport_layer/etcp_connections.c b/src/transport_layer/etcp_connections.c index be93fbd5..fd0066a6 100644 --- a/src/transport_layer/etcp_connections.c +++ b/src/transport_layer/etcp_connections.c @@ -1555,12 +1555,19 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { recv_len, (unsigned long long)link->etcp->crypto_ctx.rx_counter); sc_status_t dec_rc = sc_decrypt(&link->etcp->crypto_ctx, data, recv_len, (uint8_t*)&pkt->timestamp, &pkt_len); if (!dec_rc) { + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_DECRYPT_OK: log=%s seskey=%02x%02x%02x%02x rx=%llu pkt_len=%zu", + link->etcp->log_name, + link->etcp->crypto_ctx.session_key[0], link->etcp->crypto_ctx.session_key[1], + link->etcp->crypto_ctx.session_key[2], link->etcp->crypto_ctx.session_key[3], + (unsigned long long)link->etcp->crypto_ctx.rx_counter, pkt_len); goto process_decrypted; } - DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp: DECRYPT FAIL rc=%d link=%p log=%s sess=%d link_state=%d keepalive=%d enc_errs=%zu my_pub=%016llx peer_pub=%016llx", + DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp: DECRYPT FAIL rc=%d link=%p log=%s sess=%d link_state=%d keepalive=%d enc_errs=%zu my_pub=%016llx peer_pub=%016llx seskey=%02x%02x%02x%02x", dec_rc, link, link->etcp->log_name, link->etcp->crypto_ctx.session_ready, link->link_state, link->recv_keepalive, link->encrypt_errors, - *(uint64_t*)link->etcp->crypto_ctx.pk->public_key, *(uint64_t*)link->etcp->crypto_ctx.peer_public_key); + *(uint64_t*)link->etcp->crypto_ctx.pk->public_key, *(uint64_t*)link->etcp->crypto_ctx.peer_public_key, + link->etcp->crypto_ctx.session_key[0], link->etcp->crypto_ctx.session_key[1], + link->etcp->crypto_ctx.session_key[2], link->etcp->crypto_ctx.session_key[3]); } else { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "SKIP normal decrypt: link=%p session_ready=%d — trying init decrypt", link, link && link->etcp ? link->etcp->crypto_ctx.session_ready : -1); @@ -1703,6 +1710,16 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { conn=etcp_connection_create(e_sock->instance,""); if (!conn) { errorcode=55; DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "failed to create connection"); goto ec_fr; } memcpy(&conn->crypto_ctx, &sc, sizeof(sc)); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_CTX_INIT: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x my_priv=%02x%02x%02x%02x", + conn->log_name, + conn->crypto_ctx.session_key[0], conn->crypto_ctx.session_key[1], + conn->crypto_ctx.session_key[2], conn->crypto_ctx.session_key[3], + conn->crypto_ctx.peer_public_key[0], conn->crypto_ctx.peer_public_key[1], + conn->crypto_ctx.peer_public_key[2], conn->crypto_ctx.peer_public_key[3], + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[0] : 0, + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[1] : 0, + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[2] : 0, + conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[3] : 0); etcp_conn_set_peer_node_id(conn, peer_id); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "New connection received on socket %s: log_name=%s peer_id=%lu peer:%s", e_sock->name, conn->log_name, (unsigned long)peer_id, sockaddr_storage_to_str(&addr).str); DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "New connection from %s peer_id=%ld etcp=%p total=%d",