@ -1,394 +1,394 @@
=== ETCP Simple Traffic Test (Queue-based) ===
[03:05:50-380.206 ] [TRACE] [32] (test_etcp_simple_traffic.c:361) main() *************1
[03:30:18-202.523 ] [TRACE] [32] (test_etcp_simple_traffic.c:361) main() *************1
Function names enabled: YES
===========================
[03:05:50-380.234 ] [INFO] [256] (utun_instance.c:34) utun_instance_set_tun_init_enabled() TUN initialization disabled
[03:30:18-202.631 ] [INFO] [256] (utun_instance.c:34) utun_instance_set_tun_init_enabled() TUN initialization disabled
Creating server instance...
[03:05:50-380.239 ] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-380.253 ] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[CONFIG DEBUG] Opening config file: /tmp/utun_test_319Txg /server.conf
[03:30:18-202.658 ] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:30:18-202.719 ] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[CONFIG DEBUG] Opening config file: /tmp/utun_test_jUbh3w /server.conf
[CONFIG DEBUG] Successfully opened config file
[CONFIG DEBUG] Checking config - priv_key='67b705a92b41bcaae105af2d6a17743faa7b26ccebba8b3b9b0af05e9cd1d5fb' (len=64), pub_key='1c55e4ccae7c4470707759086738b10681bf88b81f198cc2ab54a647d1556e17c65e6b1833e0c771e5a39382c03067c388915a4c732191bc130480f20f8e00b9' (len=128), node_id=1229782938247303441
[CONFIG DEBUG] Validation results - need_priv_key=0, need_pub_key=0, need_node_id=0
[CONFIG DEBUG] Opening config file: /tmp/utun_test_319Txg /server.conf
[CONFIG DEBUG] Opening config file: /tmp/utun_test_jUbh3w /server.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-380.341 ] [INFO] [16] (secure_channel.c:174) sc_init_local_keys() sc_init_local_keys: public_key len=128, private_key len=64
[03:05:50-380.400 ] [INFO] [16] (secure_channel.c:188) sc_init_local_keys() sc_init_local_keys: keys initialized successfully
[03:05:50-380.409] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 0 to callback 0x60fa13eb93d0 for instance 0x60fa30cb7 4e0
[03:05:50-380.413 ] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:05:50-380.416 ] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:05:50-380.419 ] [INFO] [256] (utun_instance.c:133) utun_instance_create() TUN initialization disabled - skipping TUN device setup
[03:05:50-380.423] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cb8 830, hash_size=0
[03:05:50-380.426] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 1 to callback 0x60fa13eb8480 for instance 0x60fa30cb7 4e0
[03:05:50-380.430 ] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:05:50-380.433 ] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:05:50-380.436 ] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
[03:30:18-202.864 ] [INFO] [16] (secure_channel.c:174) sc_init_local_keys() sc_init_local_keys: public_key len=128, private_key len=64
[03:30:18-203.055 ] [INFO] [16] (secure_channel.c:188) sc_init_local_keys() sc_init_local_keys: keys initialized successfully
[03:30:18-203.087] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 0 to callback 0x62cb2dbbf3d0 for instance 0x62cb67cd5 4e0
[03:30:18-203.111 ] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:30:18-203.115 ] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:30:18-203.182 ] [INFO] [256] (utun_instance.c:133) utun_instance_create() TUN initialization disabled - skipping TUN device setup
[03:30:18-203.187] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67cd6 830, hash_size=0
[03:30:18-203.210] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 1 to callback 0x62cb2dbbe480 for instance 0x62cb67cd5 4e0
[03:30:18-203.214 ] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:30:18-203.218 ] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:30:18-203.244 ] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
ℹ️ Server TUN disabled - initializing connections only
[03:05:50-380.440] [TRACE] [4] (etcp_connections.c:807 ) init_connections()
[03:05:50-380.444] [TRACE] [4] (etcp_connections.c:269 ) etcp_socket_add()
[03:05:50-380.455 ] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 6
[03:05:50-380.468] [INFO] [8] (etcp_connections.c:340 ) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:05:50-380.474] [INFO] [4] (etcp_connections.c:362 ) etcp_socket_add() Registered ETCP socket with uasync
[03:05:50-380.477] [INFO] [8] (etcp_connections.c:364) etcp_socket_add() [ETCP] Socket 0x60fa30cb8 4d0 registered and active
[03:05:50-380.482] [INFO] [4] (etcp_connections.c:835 ) init_connections() Initialized server test on 127.0.0.1:9001 (links: 0)
[03:05:50-380.485] [DEBUG] [4] (etcp_connections.c:842) init_connections() init_connections called, instance=0x60fa30cb74e0, config=0x60fa30cb7 db0, clients=(nil), connections_count=0
[03:05:50-380.489] [INFO] [4] (etcp_connections.c:1018 ) init_connections() Initialized 0 connections
Server connections initialized: sockets=0x60fa30cb8 4d0, connections=(nil)
[03:30:18-203.249] [TRACE] [4] (etcp_connections.c:809 ) init_connections()
[03:30:18-203.253] [TRACE] [4] (etcp_connections.c:271 ) etcp_socket_add()
[03:30:18-203.303 ] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 6
[03:30:18-203.344] [INFO] [8] (etcp_connections.c:342 ) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:30:18-203.372] [INFO] [4] (etcp_connections.c:364 ) etcp_socket_add() Registered ETCP socket with uasync
[03:30:18-203.376] [INFO] [8] (etcp_connections.c:366) etcp_socket_add() [ETCP] Socket 0x62cb67cd6 4d0 registered and active
[03:30:18-203.402] [INFO] [4] (etcp_connections.c:837 ) init_connections() Initialized server test on 127.0.0.1:9001 (links: 0)
[03:30:18-203.406] [DEBUG] [4] (etcp_connections.c:844) init_connections() init_connections called, instance=0x62cb67cd54e0, config=0x62cb67cd5 db0, clients=(nil), connections_count=0
[03:30:18-203.430] [INFO] [4] (etcp_connections.c:1020 ) init_connections() Initialized 0 connections
Server connections initialized: sockets=0x62cb67cd6 4d0, connections=(nil)
✅ Server instance initialized successfully (node_id=1111111111111111)
Server instance ready (node_id=1111111111111111)
Creating client instance...
[CONFIG DEBUG] Opening config file: /tmp/utun_test_319Txg /client.conf
[CONFIG DEBUG] Opening config file: /tmp/utun_test_jUbh3w /client.conf
[CONFIG DEBUG] Successfully opened config file
[CONFIG DEBUG] Checking config - priv_key='4813d31d28b7e9829247f488c6be7672f2bdf61b2508333128e386d1759afed2' (len=64), pub_key='c594f33c91f3a2222795c2c110c527bf214ad1009197ce14556cb13df3c461b3c373bed8f205a8dd1fc0c364f90bf471d7c6f5db49564c33e4235d268569ac71' (len=128), node_id=2459565876494606882
[CONFIG DEBUG] Validation results - need_priv_key=0, need_pub_key=0, need_node_id=0
[CONFIG DEBUG] Opening config file: /tmp/utun_test_319Txg /client.conf
[CONFIG DEBUG] Opening config file: /tmp/utun_test_jUbh3w /client.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-380.517 ] [INFO] [16] (secure_channel.c:174) sc_init_local_keys() sc_init_local_keys: public_key len=128, private_key len=64
[03:05:50-380.544 ] [INFO] [16] (secure_channel.c:188) sc_init_local_keys() sc_init_local_keys: keys initialized successfully
[03:05:50-380.551] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 0 to callback 0x60fa13eb93d0 for instance 0x60fa30cbb 490
[03:05:50-380.555 ] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:05:50-380.558 ] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:05:50-380.561 ] [INFO] [256] (utun_instance.c:133) utun_instance_create() TUN initialization disabled - skipping TUN device setup
[03:05:50-380.565] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cbc a20, hash_size=0
[03:05:50-380.568] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 1 to callback 0x60fa13eb8480 for instance 0x60fa30cbb 490
[03:05:50-380.571 ] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:05:50-380.574 ] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:05:50-380.577 ] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
[03:30:18-203.549 ] [INFO] [16] (secure_channel.c:174) sc_init_local_keys() sc_init_local_keys: public_key len=128, private_key len=64
[03:30:18-203.643 ] [INFO] [16] (secure_channel.c:188) sc_init_local_keys() sc_init_local_keys: keys initialized successfully
[03:30:18-203.673] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 0 to callback 0x62cb2dbbf3d0 for instance 0x62cb67cd9 490
[03:30:18-203.707 ] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:30:18-203.711 ] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:30:18-203.735 ] [INFO] [256] (utun_instance.c:133) utun_instance_create() TUN initialization disabled - skipping TUN device setup
[03:30:18-203.739] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67cda a20, hash_size=0
[03:30:18-203.743] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 1 to callback 0x62cb2dbbe480 for instance 0x62cb67cd9 490
[03:30:18-203.765 ] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:30:18-203.769 ] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:30:18-203.772 ] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
ℹ️ Client TUN disabled - initializing connections only
About to call init_connections() for client instance
[03:05:50-380.581] [TRACE] [4] (etcp_connections.c:807 ) init_connections()
[03:05:50-380.585] [TRACE] [4] (etcp_connections.c:269 ) etcp_socket_add()
[03:05:50-380.592 ] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 7
[03:05:50-380.599] [INFO] [8] (etcp_connections.c:340 ) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:05:50-380.604] [INFO] [4] (etcp_connections.c:362 ) etcp_socket_add() Registered ETCP socket with uasync
[03:05:50-380.607] [INFO] [8] (etcp_connections.c:364) etcp_socket_add() [ETCP] Socket 0x60fa30cbc 840 registered and active
[03:05:50-380.610] [INFO] [4] (etcp_connections.c:835 ) init_connections() Initialized server test on 127.0.0.1:9002 (links: 0)
[03:05:50-380.614] [DEBUG] [4] (etcp_connections.c:842) init_connections() init_connections called, instance=0x60fa30cbb490, config=0x60fa30cbc160, clients=0x60fa30cbc 640, connections_count=0
[03:05:50-380.617] [INFO] [4] (etcp_connections.c:846) init_connections() Client test_client - keepalive=1, links=0x60fa30cbc 7a0, peer_key_len=128
[03:05:50-380.621 ] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:05:50-380.624] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cb7 330, hash_size=0
[03:05:50-380.627] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cb8 a80, hash_size=0
[03:05:50-380.634] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cbf 300, hash_size=1024
[03:05:50-380.641] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc1 3a0, hash_size=1024
[03:05:50-380.648] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc3 440, hash_size=1024
[03:05:50-380.651] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc5 4e0, hash_size=0
[03:05:50-380.655] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[6882→????] init 0x60fa30cb8 eb0, mtu=1500
[03:05:50-380.658] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc5 570, hash_size=0
[03:05:50-380.662] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc5 600, hash_size=0
[03:05:50-380.665 ] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:05:50-380.668] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [6882→????] connection initialized. ETCP=0x60fa30cb8 eb0 mtu=1500, next_tx_id=1
[03:05:50-380.672 ] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-380.678] [INFO] [16] (etcp_connections.c:873 ) init_connections() init_connections: setting peer public key for client test_client
[03:05:50-381.548] [INFO] [16] (etcp_connections.c:878 ) init_connections() init_connections: successfully set peer public key for client test_client
[03:05:50-381.559] [TRACE] [4] (etcp_connections.c:398 ) etcp_link_new()
[03:05:50-381.563] [TRACE] [4] (etcp_connections.c:234 ) etcp_find_free_local_link_id()
[03:05:50-381.566] [TRACE] [4] (etcp_connections.c:140 ) sockaddr_hash()
[03:05:50-381.570] [TRACE] [4] (etcp_connections.c:184 ) insert_link()
[03:05:50-381.573] [TRACE] [4] (etcp_connections.c:169 ) realloc_links()
[03:05:50-381.576] [TRACE] [4] (etcp_connections.c:147 ) find_link_index()
[03:05:50-381.580] [INFO] [4] (etcp_connections.c:438 ) etcp_link_new() etcp_link_new: client link, calling etcp_link_send_init
[03:05:50-381.583] [TRACE] [4] (etcp_connections.c:42 ) etcp_link_send_init()
[03:05:50-381.586] [INFO] [4] (etcp_connections.c:43) etcp_link_send_init() etcp_link_send_init link=0x60fa30cd4 780, is_server=0
[03:05:50-381.590] [INFO] [4] (etcp_connections.c:81 ) etcp_link_send_init() Sending INIT request to link, node_id=2459565876494606882, retry=0
[03:05:50-381.594] [INFO] [8] (etcp_connections.c:88) etcp_link_send_init() [ETCP] INIT sending to 127.0.0.1:9001, link=0x60fa30cd4 780
[03:05:50-381.597] [TRACE] [4] (etcp_connections.c:471 ) etcp_encrypt_send()
[03:05:50-381.601 ] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-381.604 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-381.607] [INFO] [8] (etcp_connections.c:485 ) etcp_encrypt_send() Encrypt start
[03:05:50-382.400] [INFO] [8] (etcp_connections.c:487 ) etcp_encrypt_send() Encrypt end
[03:05:50-382.430] [INFO] [4] (etcp_connections.c:927) init_connections() Created link 0x60fa30cd4780 for client test_client, socket=0x60fa30cbc 840
[03:05:50-382.435 ] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-382.439] [INFO] [16] (etcp_connections.c:946 ) init_connections() init_connections: setting peer public key for client test_client
[03:05:50-382.517] [INFO] [16] (etcp_connections.c:951 ) init_connections() init_connections: successfully set peer public key for client test_client
[03:05:50-382.521] [INFO] [4] (etcp_connections.c:1007) init_connections() Added connection 0x60fa30cb8 eb0 to instance, total count: 1
[03:05:50-382.524] [INFO] [4] (etcp_connections.c:1018 ) init_connections() Initialized 1 connections
[03:30:18-203.796] [TRACE] [4] (etcp_connections.c:809 ) init_connections()
[03:30:18-203.800] [TRACE] [4] (etcp_connections.c:271 ) etcp_socket_add()
[03:30:18-203.827 ] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 7
[03:30:18-203.856] [INFO] [8] (etcp_connections.c:342 ) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:30:18-203.882] [INFO] [4] (etcp_connections.c:364 ) etcp_socket_add() Registered ETCP socket with uasync
[03:30:18-203.886] [INFO] [8] (etcp_connections.c:366) etcp_socket_add() [ETCP] Socket 0x62cb67cda 840 registered and active
[03:30:18-203.909] [INFO] [4] (etcp_connections.c:837 ) init_connections() Initialized server test on 127.0.0.1:9002 (links: 0)
[03:30:18-203.913] [DEBUG] [4] (etcp_connections.c:844) init_connections() init_connections called, instance=0x62cb67cd9490, config=0x62cb67cda160, clients=0x62cb67cda 640, connections_count=0
[03:30:18-203.917] [INFO] [4] (etcp_connections.c:848) init_connections() Client test_client - keepalive=1, links=0x62cb67cda 7a0, peer_key_len=128
[03:30:18-203.940 ] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:30:18-203.944] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67cd5 330, hash_size=0
[03:30:18-203.967] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67cd6 a80, hash_size=0
[03:30:18-203.976] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67cdd 300, hash_size=1024
[03:30:18-204.004] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67cdf 3a0, hash_size=1024
[03:30:18-204.031] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67ce1 440, hash_size=1024
[03:30:18-204.036] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67ce3 4e0, hash_size=0
[03:30:18-204.060] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[6882→????] init 0x62cb67cd6 eb0, mtu=1500
[03:30:18-204.064] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67ce3 570, hash_size=0
[03:30:18-204.088] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67ce3 600, hash_size=0
[03:30:18-204.092 ] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:30:18-204.095] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [6882→????] connection initialized. ETCP=0x62cb67cd6 eb0 mtu=1500, next_tx_id=1
[03:30:18-204.119 ] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:30:18-204.150] [INFO] [16] (etcp_connections.c:875 ) init_connections() init_connections: setting peer public key for client test_client
[03:30:18-204.738] [INFO] [16] (etcp_connections.c:880 ) init_connections() init_connections: successfully set peer public key for client test_client
[03:30:18-204.748] [TRACE] [4] (etcp_connections.c:400 ) etcp_link_new()
[03:30:18-204.752] [TRACE] [4] (etcp_connections.c:236 ) etcp_find_free_local_link_id()
[03:30:18-204.756] [TRACE] [4] (etcp_connections.c:142 ) sockaddr_hash()
[03:30:18-204.760] [TRACE] [4] (etcp_connections.c:186 ) insert_link()
[03:30:18-204.763] [TRACE] [4] (etcp_connections.c:171 ) realloc_links()
[03:30:18-204.767] [TRACE] [4] (etcp_connections.c:149 ) find_link_index()
[03:30:18-204.770] [INFO] [4] (etcp_connections.c:440 ) etcp_link_new() etcp_link_new: client link, calling etcp_link_send_init
[03:30:18-204.774] [TRACE] [4] (etcp_connections.c:44 ) etcp_link_send_init()
[03:30:18-204.777] [INFO] [4] (etcp_connections.c:45) etcp_link_send_init() etcp_link_send_init link=0x62cb67cf2 780, is_server=0
[03:30:18-204.782] [INFO] [4] (etcp_connections.c:83 ) etcp_link_send_init() Sending INIT request to link, node_id=2459565876494606882, retry=0
[03:30:18-204.786] [INFO] [8] (etcp_connections.c:90) etcp_link_send_init() [ETCP] INIT sending to 127.0.0.1:9001, link=0x62cb67cf2 780
[03:30:18-204.789] [TRACE] [4] (etcp_connections.c:473 ) etcp_encrypt_send()
[03:30:18-204.793 ] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-204.796 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-204.799] [INFO] [8] (etcp_connections.c:487 ) etcp_encrypt_send() Encrypt start
[03:30:18-205.610] [INFO] [8] (etcp_connections.c:489 ) etcp_encrypt_send() Encrypt end
[03:30:18-205.636] [INFO] [4] (etcp_connections.c:929) init_connections() Created link 0x62cb67cf2780 for client test_client, socket=0x62cb67cda 840
[03:30:18-205.641 ] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:30:18-205.644] [INFO] [16] (etcp_connections.c:948 ) init_connections() init_connections: setting peer public key for client test_client
[03:30:18-205.733] [INFO] [16] (etcp_connections.c:953 ) init_connections() init_connections: successfully set peer public key for client test_client
[03:30:18-205.737] [INFO] [4] (etcp_connections.c:1009) init_connections() Added connection 0x62cb67cd6 eb0 to instance, total count: 1
[03:30:18-205.741] [INFO] [4] (etcp_connections.c:1020 ) init_connections() Initialized 1 connections
init_connections() returned: 0
Client connections initialized: sockets=0x60fa30cbc840, connections=0x60fa30cb8 eb0, count=1
Client connections initialized: sockets=0x62cb67cda840, connections=0x62cb67cd6 eb0, count=1
✅ Client instance initialized successfully (node_id=2222222222222222)
Client instance ready (node_id=2222222222222222)
=== Connection Debug ===
Client connection 0x60fa30cb8 eb0: peer_node_id=1
Link 0x60fa30cd4 780: initialized=0, is_server=0, remote_addr family=2, conn->fd=7
Client connection 0x62cb67cd6 eb0: peer_node_id=1
Link 0x62cb67cf2 780: initialized=0, is_server=0, remote_addr family=2, conn->fd=7
=== End Debug ===
Starting packet transmission test...
Running event loop...
Waiting 0.5 seconds for instances initialization...
[03:05:50-382.531] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-382.535] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-382.541] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-382.545] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-382.548] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-382.617] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:05:50-382.620] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d04420, hash_size=0
[03:05:50-382.624] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d044b0, hash_size=0
[03:05:50-382.635] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d04540, hash_size=1024
[03:05:50-382.641] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d03160, hash_size=1024
[03:05:50-382.648] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d032d0, hash_size=1024
[03:05:50-382.652] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d02ea0, hash_size=0
[03:05:50-382.659] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[3441→????] init 0x60fa30d042b0, mtu=1500
[03:05:50-382.663] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d03950, hash_size=0
[03:05:50-382.666] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30d039e0, hash_size=0
[03:05:50-382.669] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:05:50-382.673] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [3441→????] connection initialized. ETCP=0x60fa30d042b0 mtu=1500, next_tx_id=1
[03:05:50-382.676] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-382.680] [DEBUG] [4] (etcp_connections.c:624) etcp_connections_read_callback_socket() New connection from 127.0.0.1:9002 peer_id=2459565876494606882 etcp=0x60fa30d042b0
[03:05:50-382.684] [INFO] [4] (etcp_connections.c:629) etcp_connections_read_callback_socket() Added incoming connection 0x60fa30d042b0 to instance, total count: 1
[03:05:50-382.687] [TRACE] [4] (etcp_connections.c:398) etcp_link_new()
[03:05:50-382.690] [TRACE] [4] (etcp_connections.c:234) etcp_find_free_local_link_id()
[03:05:50-382.694] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-382.697] [TRACE] [4] (etcp_connections.c:184) insert_link()
[03:05:50-382.700] [TRACE] [4] (etcp_connections.c:169) realloc_links()
[03:05:50-382.703] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-382.706] [TRACE] [8] (etcp.c:258) etcp_conn_reset()
[03:05:50-382.709] [DEBUG] [4] (etcp_connections.c:668) etcp_connections_read_callback_socket() Sending INIT RESPONSE, link=0x60fa30d035d0, local_link_id=0, remote_link_id=0
[03:05:50-382.713] [INFO] [8] (etcp_connections.c:669) etcp_connections_read_callback_socket() [ETCP DEBUG] Send INIT RESPONSE
[03:05:50-382.716] [TRACE] [4] (etcp_connections.c:471) etcp_encrypt_send()
[03:05:50-382.719] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-382.722] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-382.726] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-382.731] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-382.741] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x60fa30d035d0 now ready, notifying ETCP_CONN
[03:05:50-382.745] [TRACE] [8] (etcp.c:637) etcp_link_ready_callback()
[03:05:50-382.748] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-382.751] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-382.754] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-382.758] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-382.761] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-382.765] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x60fa30d042b0 to senders_list
[03:05:50-382.768] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (0 routes) to connection
[03:05:50-382.772] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-382.776] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-382.781] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-382.784] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-382.787] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-382.790] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-382.795] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-382.798] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-382.801] [TRACE] [8] (etcp.c:258) etcp_conn_reset()
[03:05:50-382.805] [INFO] [4] (etcp_connections.c:734) etcp_connections_read_callback_socket() [6882→0001] NAT address initialized: 127.0.0.1:9002
[03:05:50-382.811] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-382.815] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x60fa30cd4780 now ready, notifying ETCP_CONN
[03:05:50-382.818] [TRACE] [8] (etcp.c:637) etcp_link_ready_callback()
[03:05:50-382.821] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-382.824] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-382.827] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-382.830] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-382.834] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-382.837] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x60fa30cb8eb0 to senders_list
[03:05:50-382.840] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (0 routes) to connection
[03:05:50-382.843] [INFO] [4] (etcp_connections.c:781) etcp_connections_read_callback_socket() etcp client: Link initialized successfully! Server node_id=1229782938247303441, mtu=0, local_link_id=0, remote_link_id=0
[03:05:50-382.847] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-383.912] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-384.987] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-386.070] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-387.151] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-388.235] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-390.148] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-391.267] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-392.369] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-394.749] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-395.836] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-396.912] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-397.985] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-399.062] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-400.142] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-401.229] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-403.529] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-404.608] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-405.679] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-406.758] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-407.846] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-410.340] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-411.560] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-412.650] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-413.734] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-414.814] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-415.892] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-416.977] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-418.051] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-419.127] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-420.202] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-421.278] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-422.368] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-423.446] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-424.521] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-425.599] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-426.684] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-427.763] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-428.832] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-430.074] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-431.152] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-205.747] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-205.752] [TRACE] [4] (etcp_connections.c:529) etcp_connections_read_callback_socket()
[03:30:18-205.758] [TRACE] [4] (etcp_connections.c:226) etcp_link_find_by_addr()
[03:30:18-205.764] [TRACE] [4] (etcp_connections.c:142) sockaddr_hash()
[03:30:18-205.767] [TRACE] [4] (etcp_connections.c:149) find_link_index()
[03:30:18-205.836] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:30:18-205.840] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d22420, hash_size=0
[03:30:18-205.843] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d224b0, hash_size=0
[03:30:18-205.851] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d22540, hash_size=1024
[03:30:18-205.857] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d21160, hash_size=1024
[03:30:18-205.864] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d212d0, hash_size=1024
[03:30:18-205.867] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d20ea0, hash_size=0
[03:30:18-205.875] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[3441→????] init 0x62cb67d222b0, mtu=1500
[03:30:18-205.878] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d21950, hash_size=0
[03:30:18-205.881] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x62cb67d219e0, hash_size=0
[03:30:18-205.885] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:30:18-205.888] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [3441→????] connection initialized. ETCP=0x62cb67d222b0 mtu=1500, next_tx_id=1
[03:30:18-205.891] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:30:18-205.895] [DEBUG] [4] (etcp_connections.c:626) etcp_connections_read_callback_socket() New connection from 127.0.0.1:9002 peer_id=2459565876494606882 etcp=0x62cb67d222b0
[03:30:18-205.899] [INFO] [4] (etcp_connections.c:631) etcp_connections_read_callback_socket() Added incoming connection 0x62cb67d222b0 to instance, total count: 1
[03:30:18-205.902] [TRACE] [4] (etcp_connections.c:400) etcp_link_new()
[03:30:18-205.905] [TRACE] [4] (etcp_connections.c:236) etcp_find_free_local_link_id()
[03:30:18-205.909] [TRACE] [4] (etcp_connections.c:142) sockaddr_hash()
[03:30:18-205.912] [TRACE] [4] (etcp_connections.c:186) insert_link()
[03:30:18-205.915] [TRACE] [4] (etcp_connections.c:171) realloc_links()
[03:30:18-205.918] [TRACE] [4] (etcp_connections.c:149) find_link_index()
[03:30:18-205.921] [TRACE] [8] (etcp.c:258) etcp_conn_reset()
[03:30:18-205.924] [DEBUG] [4] (etcp_connections.c:670) etcp_connections_read_callback_socket() Sending INIT RESPONSE, link=0x62cb67d215d0, local_link_id=0, remote_link_id=0
[03:30:18-205.928] [INFO] [8] (etcp_connections.c:671) etcp_connections_read_callback_socket() [ETCP DEBUG] Send INIT RESPONSE
[03:30:18-205.931] [TRACE] [4] (etcp_connections.c:473) etcp_encrypt_send()
[03:30:18-205.934] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-205.937] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-205.940] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt start
[03:30:18-205.945] [INFO] [8] (etcp_connections.c:489) etcp_encrypt_send() Encrypt end
[03:30:18-205.956] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x62cb67d215d0 now ready, notifying ETCP_CONN
[03:30:18-205.959] [TRACE] [8] (etcp.c:637) etcp_link_ready_callback()
[03:30:18-205.963] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:30:18-205.966] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-205.969] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-205.972] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-205.975] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:30:18-205.979] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x62cb67d222b0 to senders_list
[03:30:18-205.983] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (0 routes) to connection
[03:30:18-205.986] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-205.990] [TRACE] [4] (etcp_connections.c:529) etcp_connections_read_callback_socket()
[03:30:18-205.995] [TRACE] [4] (etcp_connections.c:226) etcp_link_find_by_addr()
[03:30:18-205.998] [TRACE] [4] (etcp_connections.c:142) sockaddr_hash()
[03:30:18-206.001] [TRACE] [4] (etcp_connections.c:149) find_link_index()
[03:30:18-206.004] [INFO] [8] (etcp_connections.c:687) etcp_connections_read_callback_socket() Decrypt start
[03:30:18-206.009] [INFO] [8] (etcp_connections.c:696) etcp_connections_read_callback_socket() Decrypt end
[03:30:18-206.012] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-206.015] [TRACE] [8] (etcp.c:258) etcp_conn_reset()
[03:30:18-206.019] [INFO] [4] (etcp_connections.c:736) etcp_connections_read_callback_socket() [6882→0001] NAT address initialized: 127.0.0.1:9002
[03:30:18-206.025] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:30:18-206.028] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x62cb67cf2780 now ready, notifying ETCP_CONN
[03:30:18-206.032] [TRACE] [8] (etcp.c:637) etcp_link_ready_callback()
[03:30:18-206.035] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:30:18-206.038] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-206.041] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-206.044] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-206.047] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=0, input_len=0
[03:30:18-206.051] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x62cb67cd6eb0 to senders_list
[03:30:18-206.054] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (0 routes) to connection
[03:30:18-206.057] [INFO] [4] (etcp_connections.c:783) etcp_connections_read_callback_socket() etcp client: Link initialized successfully! Server node_id=1229782938247303441, mtu=0, local_link_id=0, remote_link_id=0
[03:30:18-206.061] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-208.300] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-209.390] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-210.522] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-211.595] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-212.670] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-213.747] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-215.267] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-216.350] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-217.417] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-218.484] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-219.560] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-220.636] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-221.712] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-222.788] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-223.863] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-224.942] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-226.019] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-227.094] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-228.170] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-229.246] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-230.333] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-231.437] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-232.516] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-233.593] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-234.669] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-235.752] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-236.828] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-237.904] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-238.979] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-240.054] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-241.135] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-242.213] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-243.293] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-244.370] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-245.444] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-246.525] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-247.602] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-248.682] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-249.758] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-250.833] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-251.908] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-253.005] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-254.083] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[DEBUG] monitor_and_send: ENTERING (arg=(nil))
[03:05:50-432.236] [TRACE] [8] (test_etcp_simple_traffic.c:274) monitor_and_send() monitor_and_send: ENTERING (arg=(nil))
[DEBUG] is_connection_established: Checking instance 0x60fa30cb74e0
[03:05:50-432.253 ] [TRACE] [8] (test_etcp_simple_traffic.c:114) is_connection_established() is_connection_established: Checking instance 0x60fa30cb7 4e0
[03:30:18-255.174 ] [TRACE] [8] (test_etcp_simple_traffic.c:274) monitor_and_send() monitor_and_send: ENTERING (arg=(nil))
[DEBUG] is_connection_established: Checking instance 0x62cb67cd5 4e0
[03:30:18-255.185 ] [TRACE] [8] (test_etcp_simple_traffic.c:114) is_connection_established() is_connection_established: Checking instance 0x62cb67cd5 4e0
[DEBUG] is_connection_established: Instance has 1 connections
[03:05:50-432.259 ] [DEBUG] [8] (test_etcp_simple_traffic.c:123) is_connection_established() is_connection_established: Instance has 1 connections
[DEBUG] is_connection_established: Checking connection 0x60fa30d04 2b0
[03:05:50-432.265 ] [DEBUG] [8] (test_etcp_simple_traffic.c:129) is_connection_established() is_connection_established: Checking connection 0x60fa30d04 2b0
[DEBUG] is_connection_established: Link 0x60fa30d03 5d0 - initialized=1, is_server=1
[03:05:50-432.270 ] [DEBUG] [8] (test_etcp_simple_traffic.c:135) is_connection_established() is_connection_established: Link 0x60fa30d03 5d0 - initialized=1, is_server=1
[03:30:18-255.191 ] [DEBUG] [8] (test_etcp_simple_traffic.c:123) is_connection_established() is_connection_established: Instance has 1 connections
[DEBUG] is_connection_established: Checking connection 0x62cb67d22 2b0
[03:30:18-255.197 ] [DEBUG] [8] (test_etcp_simple_traffic.c:129) is_connection_established() is_connection_established: Checking connection 0x62cb67d22 2b0
[DEBUG] is_connection_established: Link 0x62cb67d21 5d0 - initialized=1, is_server=1
[03:30:18-255.202 ] [DEBUG] [8] (test_etcp_simple_traffic.c:135) is_connection_established() is_connection_established: Link 0x62cb67d21 5d0 - initialized=1, is_server=1
[DEBUG] is_connection_established: FOUND initialized link!
[03:05:50-432.276 ] [DEBUG] [8] (test_etcp_simple_traffic.c:140) is_connection_established() is_connection_established: FOUND initialized link!
[DEBUG] is_connection_established: Checking instance 0x60fa30cbb 490
[03:05:50-432.295 ] [TRACE] [8] (test_etcp_simple_traffic.c:114) is_connection_established() is_connection_established: Checking instance 0x60fa30cbb 490
[03:30:18-255.207 ] [DEBUG] [8] (test_etcp_simple_traffic.c:140) is_connection_established() is_connection_established: FOUND initialized link!
[DEBUG] is_connection_established: Checking instance 0x62cb67cd9 490
[03:30:18-255.212 ] [TRACE] [8] (test_etcp_simple_traffic.c:114) is_connection_established() is_connection_established: Checking instance 0x62cb67cd9 490
[DEBUG] is_connection_established: Instance has 1 connections
[03:05:50-432.303 ] [DEBUG] [8] (test_etcp_simple_traffic.c:123) is_connection_established() is_connection_established: Instance has 1 connections
[DEBUG] is_connection_established: Checking connection 0x60fa30cb8 eb0
[03:05:50-432.308 ] [DEBUG] [8] (test_etcp_simple_traffic.c:129) is_connection_established() is_connection_established: Checking connection 0x60fa30cb8 eb0
[DEBUG] is_connection_established: Link 0x60fa30cd4 780 - initialized=1, is_server=0
[03:05:50-432.314 ] [DEBUG] [8] (test_etcp_simple_traffic.c:135) is_connection_established() is_connection_established: Link 0x60fa30cd4 780 - initialized=1, is_server=0
[03:30:18-255.217 ] [DEBUG] [8] (test_etcp_simple_traffic.c:123) is_connection_established() is_connection_established: Instance has 1 connections
[DEBUG] is_connection_established: Checking connection 0x62cb67cd6 eb0
[03:30:18-255.223 ] [DEBUG] [8] (test_etcp_simple_traffic.c:129) is_connection_established() is_connection_established: Checking connection 0x62cb67cd6 eb0
[DEBUG] is_connection_established: Link 0x62cb67cf2 780 - initialized=1, is_server=0
[03:30:18-255.228 ] [DEBUG] [8] (test_etcp_simple_traffic.c:135) is_connection_established() is_connection_established: Link 0x62cb67cf2 780 - initialized=1, is_server=0
[DEBUG] is_connection_established: FOUND initialized link!
[03:05:50-432.319 ] [DEBUG] [8] (test_etcp_simple_traffic.c:140) is_connection_established() is_connection_established: FOUND initialized link!
[03:30:18-255.233 ] [DEBUG] [8] (test_etcp_simple_traffic.c:140) is_connection_established() is_connection_established: FOUND initialized link!
[DEBUG] monitor_and_send: Connection check - server=1, client=1
[03:05:50-432.324 ] [DEBUG] [8] (test_etcp_simple_traffic.c:289) monitor_and_send() monitor_and_send: Connection check - server=1, client=1
[03:05:50-432.328 ] [INFO] [8] (test_etcp_simple_traffic.c:294) monitor_and_send() monitor_and_send: Client link initialized, ready to send packet (server=1, client=1)
[03:30:18-255.238 ] [DEBUG] [8] (test_etcp_simple_traffic.c:289) monitor_and_send() monitor_and_send: Connection check - server=1, client=1
[03:30:18-255.242 ] [INFO] [8] (test_etcp_simple_traffic.c:294) monitor_and_send() monitor_and_send: Client link initialized, ready to send packet (server=1, client=1)
[DEBUG] send_test_packet: ENTERING
[03:05:50-432.333 ] [TRACE] [8] (test_etcp_simple_traffic.c:156) send_test_packet() send_test_packet: ENTERING
[DEBUG] send_test_packet: Found connection 0x60fa30cb8 eb0
[03:05:50-432.338 ] [DEBUG] [8] (test_etcp_simple_traffic.c:171) send_test_packet() send_test_packet: Found connection 0x60fa30cb8 eb0
[DEBUG] send_test_packet: connection input_queue=0x60fa30cb7 330
[03:05:50-432.343 ] [DEBUG] [8] (test_etcp_simple_traffic.c:174) send_test_packet() send_test_packet: connection input_queue=0x60fa30cb7 330
[DEBUG] send_test_packet: connection output_queue=0x60fa30cb8 a80
[03:05:50-432.348 ] [DEBUG] [8] (test_etcp_simple_traffic.c:177) send_test_packet() send_test_packet: connection output_queue=0x60fa30cb8 a80
[03:30:18-255.247 ] [TRACE] [8] (test_etcp_simple_traffic.c:156) send_test_packet() send_test_packet: ENTERING
[DEBUG] send_test_packet: Found connection 0x62cb67cd6 eb0
[03:30:18-255.252 ] [DEBUG] [8] (test_etcp_simple_traffic.c:171) send_test_packet() send_test_packet: Found connection 0x62cb67cd6 eb0
[DEBUG] send_test_packet: connection input_queue=0x62cb67cd5 330
[03:30:18-255.257 ] [DEBUG] [8] (test_etcp_simple_traffic.c:174) send_test_packet() send_test_packet: connection input_queue=0x62cb67cd5 330
[DEBUG] send_test_packet: connection output_queue=0x62cb67cd6 a80
[03:30:18-255.262 ] [DEBUG] [8] (test_etcp_simple_traffic.c:177) send_test_packet() send_test_packet: connection output_queue=0x62cb67cd6 a80
[DEBUG] send_test_packet: connection next_tx_id=1
[03:05:50-432.353 ] [DEBUG] [8] (test_etcp_simple_traffic.c:180) send_test_packet() send_test_packet: connection next_tx_id=1
[03:05:50-432.357 ] [DEBUG] [8] (test_etcp_simple_traffic.c:192) send_test_packet() send_test_packet: Created test data, first byte=00, last byte=63
[03:30:18-255.267 ] [DEBUG] [8] (test_etcp_simple_traffic.c:180) send_test_packet() send_test_packet: connection next_tx_id=1
[03:30:18-255.271 ] [DEBUG] [8] (test_etcp_simple_traffic.c:192) send_test_packet() send_test_packet: Created test data, first byte=00, last byte=63
[DEBUG] send_test_packet: Calling etcp_int_send with len=100
[03:05:50-432.362 ] [DEBUG] [8] (test_etcp_simple_traffic.c:198) send_test_packet() send_test_packet: Calling etcp_int_send with len=100
[03:05:50-432.36 7] [TRACE] [8] (etcp.c:283) etcp_int_send()
[03:05:50-432.376] [DEBUG] [8] (etcp.c:326) etcp_int_send() [6882→3441] created PACKET 0x60fa30d03ab0 with data 0x60fa30d0a c20 (len=100)
[03:05:50-432.38 5] [TRACE] [8] (etcp.c:403) input_queue_cb()
[03:05:50-432.390 ] [DEBUG] [8] (etcp.c:434) input_queue_cb() [6882→3441] input -> inflight (seq=1, len=100)
[03:05:50-432.39 4] [TRACE] [8] (etcp.c:453) input_send_q_cb()
[03:05:50-432.398 ] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-432.402 ] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-432.40 6] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.411 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.415 ] [TRACE] [8] (etcp.c:527) wait_ack_cb()
[03:05:50-432.41 8] [TRACE] [8] (etcp.c:464) ack_timeout_check()
[03:05:50-432.42 2] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.42 6] [DEBUG] [8] (etcp.c:517) ack_timeout_check() [6882→3441] ack_timeout_check: retransmission timer set for 1000 units
[03:05:50-432.431 ] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-432.435 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.439 ] [DEBUG] [8] (etcp.c:616) etcp_request_pkt() [6882→3441] add DATA (seq=1, len=100), ack_size=0
[03:05:50-432.443] [TRACE] [4] (etcp_connections.c:471 ) etcp_encrypt_send()
[03:05:50-432.448 ] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-432.452 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.456] [INFO] [8] (etcp_connections.c:485 ) etcp_encrypt_send() Encrypt start
[03:05:50-432.480] [INFO] [8] (etcp_connections.c:487 ) etcp_encrypt_send() Encrypt end
[03:05:50-432.50 7] [TRACE] [8] (etcp_loadbalancer.c:115) etcp_loadbalancer_send() [6882→3441] unlimited bandwidth, skipping shaper update
[03:05:50-432.51 2] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-432.51 6] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.52 0] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-432.52 4] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=100, input_len=0
[03:05:50-432.52 8] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-432.53 2] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-432.53 6] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.54 0] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-432.543 ] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=100, input_len=0
[03:05:50-432.547 ] [DEBUG] [8] (etcp.c:448) input_queue_cb() [6882→3441] nextloop, input_queue size=0
[03:30:18-255.276 ] [DEBUG] [8] (test_etcp_simple_traffic.c:198) send_test_packet() send_test_packet: Calling etcp_int_send with len=100
[03:30:18-255.30 7] [TRACE] [8] (etcp.c:283) etcp_int_send()
[03:30:18-255.319] [DEBUG] [8] (etcp.c:326) etcp_int_send() [6882→3441] created PACKET 0x62cb67d21ab0 with data 0x62cb67d28 c20 (len=100)
[03:30:18-255.32 5] [TRACE] [8] (etcp.c:403) input_queue_cb()
[03:30:18-255.329 ] [DEBUG] [8] (etcp.c:434) input_queue_cb() [6882→3441] input -> inflight (seq=1, len=100)
[03:30:18-255.33 4] [TRACE] [8] (etcp.c:453) input_send_q_cb()
[03:30:18-255.337 ] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:30:18-255.341 ] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-255.34 6] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.350 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.354 ] [TRACE] [8] (etcp.c:527) wait_ack_cb()
[03:30:18-255.35 8] [TRACE] [8] (etcp.c:464) ack_timeout_check()
[03:30:18-255.36 2] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.36 6] [DEBUG] [8] (etcp.c:517) ack_timeout_check() [6882→3441] ack_timeout_check: retransmission timer set for 1000 units
[03:30:18-255.370 ] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-255.374 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.378 ] [DEBUG] [8] (etcp.c:616) etcp_request_pkt() [6882→3441] add DATA (seq=1, len=100), ack_size=0
[03:30:18-255.382] [TRACE] [4] (etcp_connections.c:473 ) etcp_encrypt_send()
[03:30:18-255.386 ] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-255.390 ] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.394] [INFO] [8] (etcp_connections.c:487 ) etcp_encrypt_send() Encrypt start
[03:30:18-255.417] [INFO] [8] (etcp_connections.c:489 ) etcp_encrypt_send() Encrypt end
[03:30:18-255.44 7] [TRACE] [8] (etcp_loadbalancer.c:115) etcp_loadbalancer_send() [6882→3441] unlimited bandwidth, skipping shaper update
[03:30:18-255.45 2] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-255.45 6] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.46 0] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-255.46 4] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=100, input_len=0
[03:30:18-255.46 8] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:30:18-255.47 2] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-255.47 6] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.48 0] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-255.484 ] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=100, input_len=0
[03:30:18-255.488 ] [DEBUG] [8] (etcp.c:448) input_queue_cb() [6882→3441] nextloop, input_queue size=0
[DEBUG] send_test_packet: etcp_int_send returned 0
[03:05:50-432.553] [DEBUG] [8] (test_etcp_simple_traffic.c:202) send_test_packet() send_test_packet: etcp_int_send returned 0
[03:05:50-432.557] [INFO] [8] (test_etcp_simple_traffic.c:210) send_test_packet() send_test_packet: SUCCESS - Test packet sent via etcp_int_send (100 bytes)
[03:05:50-432.561] [TRACE] [8] (test_etcp_simple_traffic.c:215) check_packet_received() check_packet_received: ENTERING
[03:05:50-432.565] [DEBUG] [8] (test_etcp_simple_traffic.c:233) check_packet_received() check_packet_received: Checking server connection 0x60fa30d042b0
[03:05:50-432.569] [DEBUG] [8] (test_etcp_simple_traffic.c:234) check_packet_received() check_packet_received: Server output_queue count: 0
[03:05:50-432.574] [TRACE] [8] (test_etcp_simple_traffic.c:266) check_packet_received() check_packet_received: No packet found in output queue
[03:05:50-432.578] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-432.584] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-432.591] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-432.595] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-432.599] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-432.603] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-432.610] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-432.614] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.622] [TRACE] [8] (etcp.c:786) etcp_conn_input()
[03:05:50-432.626] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-432.630] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.634] [DEBUG] [8] (etcp.c:830) etcp_conn_input() [3441→6882] set ack_timer for delayed ACK send
[03:05:50-432.638] [DEBUG] [8] (etcp.c:834) etcp_conn_input() [3441→6882] adding packet seq=1 to recv_q (last_delivered_id=0)
[03:05:50-432.643] [DEBUG] [8] (etcp.c:855) etcp_conn_input() [3441→6882] packet seq=1 added to recv_q, calling assembly (last_delivered_id=0)
[03:05:50-432.647] [TRACE] [8] (etcp.c:666) etcp_output_try_assembly()
[03:05:50-432.651] [TRACE] [8] (etcp.c:695) etcp_output_try_assembly() [3441→6882] moved packet id=1 to output_queue
[03:05:50-432.655] [DEBUG] [8] (etcp.c:710) etcp_output_try_assembly() [3441→6882] delivered 1 contiguous packets (100 bytes), last_delivered_id=1, output_queue_count=1
[03:05:50-432.660] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-433.725] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-434.794] [TRACE] [8] (etcp.c:654) ack_response_timer_cb()
[03:05:50-434.801] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-434.805] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-434.808] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-434.811] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-434.814] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-434.818] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-434.821] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-434.824] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-434.827] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-434.830] [DEBUG] [8] (etcp.c:605) etcp_request_pkt() [3441→6882] add ACK N1 dTS=22
[03:05:50-434.833] [DEBUG] [8] (etcp.c:626) etcp_request_pkt() [3441→6882] only ACK packet with 0 bytes total
[03:05:50-434.836] [TRACE] [4] (etcp_connections.c:471) etcp_encrypt_send()
[03:05:50-434.839] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-434.842] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-434.846] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-434.853] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-434.865] [TRACE] [8] (etcp_loadbalancer.c:115) etcp_loadbalancer_send() [3441→6882] unlimited bandwidth, skipping shaper update
[03:05:50-434.868] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-434.872] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-434.875] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-434.878] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-434.881] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-434.885] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-434.890] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-434.893] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-434.896] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-434.899] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-434.904] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-434.908] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-434.911] [TRACE] [8] (etcp.c:786) etcp_conn_input()
[03:05:50-434.914] [TRACE] [8] (etcp.c:716) etcp_ack_recv()
[03:05:50-434.917] [TRACE] [8] (etcp.c:61) timestamp_diff()
[03:05:50-434.920] [DEBUG] [8] (etcp.c:770) etcp_ack_recv() [6882→3441] removed packet seq=1 from wait_ack, unacked_bytes now 4294967196 total acked=1
[03:05:50-434.923] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-434.926] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-434.934] [TRACE] [8] (etcp.c:716) etcp_ack_recv()
[03:05:50-434.937] [TRACE] [8] (etcp.c:730) etcp_ack_recv() etcp_ack_recv: packet seq=1 not found in wait_ack queue
[03:05:50-434.940] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-436.007] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-437.078] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-255.495] [DEBUG] [8] (test_etcp_simple_traffic.c:202) send_test_packet() send_test_packet: etcp_int_send returned 0
[03:30:18-255.500] [INFO] [8] (test_etcp_simple_traffic.c:210) send_test_packet() send_test_packet: SUCCESS - Test packet sent via etcp_int_send (100 bytes)
[03:30:18-255.504] [TRACE] [8] (test_etcp_simple_traffic.c:215) check_packet_received() check_packet_received: ENTERING
[03:30:18-255.508] [DEBUG] [8] (test_etcp_simple_traffic.c:233) check_packet_received() check_packet_received: Checking server connection 0x62cb67d222b0
[03:30:18-255.512] [DEBUG] [8] (test_etcp_simple_traffic.c:234) check_packet_received() check_packet_received: Server output_queue count: 0
[03:30:18-255.516] [TRACE] [8] (test_etcp_simple_traffic.c:266) check_packet_received() check_packet_received: No packet found in output queue
[03:30:18-255.519] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-255.525] [TRACE] [4] (etcp_connections.c:529) etcp_connections_read_callback_socket()
[03:30:18-255.530] [TRACE] [4] (etcp_connections.c:226) etcp_link_find_by_addr()
[03:30:18-255.533] [TRACE] [4] (etcp_connections.c:142) sockaddr_hash()
[03:30:18-255.537] [TRACE] [4] (etcp_connections.c:149) find_link_index()
[03:30:18-255.540] [INFO] [8] (etcp_connections.c:687) etcp_connections_read_callback_socket() Decrypt start
[03:30:18-255.549] [INFO] [8] (etcp_connections.c:696) etcp_connections_read_callback_socket() Decrypt end
[03:30:18-255.552] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.556] [TRACE] [8] (etcp.c:786) etcp_conn_input()
[03:30:18-255.559] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-255.562] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-255.566] [DEBUG] [8] (etcp.c:830) etcp_conn_input() [3441→6882] set ack_timer for delayed ACK send
[03:30:18-255.569] [DEBUG] [8] (etcp.c:834) etcp_conn_input() [3441→6882] adding packet seq=1 to recv_q (last_delivered_id=0)
[03:30:18-255.573] [DEBUG] [8] (etcp.c:855) etcp_conn_input() [3441→6882] packet seq=1 added to recv_q, calling assembly (last_delivered_id=0)
[03:30:18-255.576] [TRACE] [8] (etcp.c:666) etcp_output_try_assembly()
[03:30:18-255.579] [TRACE] [8] (etcp.c:695) etcp_output_try_assembly() [3441→6882] moved packet id=1 to output_queue
[03:30:18-255.582] [DEBUG] [8] (etcp.c:710) etcp_output_try_assembly() [3441→6882] delivered 1 contiguous packets (100 bytes), last_delivered_id=1, output_queue_count=1
[03:30:18-255.586] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-256.653] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.735] [TRACE] [8] (etcp.c:654) ack_response_timer_cb()
[03:30:18-257.744] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:30:18-257.747] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-257.751] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-257.754] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-257.757] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:30:18-257.760] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-257.763] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-257.767] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-257.770] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-257.773] [DEBUG] [8] (etcp.c:605) etcp_request_pkt() [3441→6882] add ACK N1 dTS=22
[03:30:18-257.776] [DEBUG] [8] (etcp.c:626) etcp_request_pkt() [3441→6882] only ACK packet with 0 bytes total
[03:30:18-257.779] [TRACE] [4] (etcp_connections.c:473) etcp_encrypt_send()
[03:30:18-257.782] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:30:18-257.785] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-257.789] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt start
[03:30:18-257.796] [INFO] [8] (etcp_connections.c:489) etcp_encrypt_send() Encrypt end
[03:30:18-257.808] [TRACE] [8] (etcp_loadbalancer.c:115) etcp_loadbalancer_send() [3441→6882] unlimited bandwidth, skipping shaper update
[03:30:18-257.812] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:30:18-257.815] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-257.818] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-257.821] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:30:18-257.824] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.829] [TRACE] [4] (etcp_connections.c:529) etcp_connections_read_callback_socket()
[03:30:18-257.834] [TRACE] [4] (etcp_connections.c:226) etcp_link_find_by_addr()
[03:30:18-257.837] [TRACE] [4] (etcp_connections.c:142) sockaddr_hash()
[03:30:18-257.840] [TRACE] [4] (etcp_connections.c:149) find_link_index()
[03:30:18-257.843] [INFO] [8] (etcp_connections.c:687) etcp_connections_read_callback_socket() Decrypt start
[03:30:18-257.848] [INFO] [8] (etcp_connections.c:696) etcp_connections_read_callback_socket() Decrypt end
[03:30:18-257.851] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:30:18-257.854] [TRACE] [8] (etcp.c:786) etcp_conn_input()
[03:30:18-257.858] [TRACE] [8] (etcp.c:716) etcp_ack_recv()
[03:30:18-257.861] [TRACE] [8] (etcp.c:61) timestamp_diff()
[03:30:18-257.864] [DEBUG] [8] (etcp.c:770) etcp_ack_recv() [6882→3441] removed packet seq=1 from wait_ack, unacked_bytes now 4294967196 total acked=1
[03:30:18-257.872] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:30:18-257.875] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=0, input_len=0
[03:30:18-257.878] [TRACE] [8] (etcp.c:716) etcp_ack_recv()
[03:30:18-257.881] [TRACE] [8] (etcp.c:730) etcp_ack_recv() etcp_ack_recv: packet seq=1 not found in wait_ack queue
Starting connection and packet transmission...
[03:05:50-438.149 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.159 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.163 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.167 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.171 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.175 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05 :50-438. 179] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.183 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05 :50-438. 187] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.192 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-438.196 ] [TRACE] [8] (test_etcp_simple_traffic.c:215) check_packet_received() check_packet_received: ENTERING
[03:05:50-438.200 ] [DEBUG] [8] (test_etcp_simple_traffic.c:233) check_packet_received() check_packet_received: Checking server connection 0x60fa30d04 2b0
[03:05:50-438.204 ] [DEBUG] [8] (test_etcp_simple_traffic.c:234) check_packet_received() check_packet_received: Server output_queue count: 1
[03:05:50-438.20 8] [DEBUG] [8] (test_etcp_simple_traffic.c:242) check_packet_received() check_packet_received: Found packet in output queue
[03:05:50-438.212 ] [DEBUG] [8] (test_etcp_simple_traffic.c:248) check_packet_received() check_packet_received: Packet size=100, expected=100
[03:05:50-438.216 ] [DEBUG] [8] (test_etcp_simple_traffic.c:249) check_packet_received() check_packet_received: First byte received=00, expected=00
[03:05:50-438.220 ] [INFO] [8] (test_etcp_simple_traffic.c:255) check_packet_received() check_packet_received: SUCCESS - Packet received in server output queue (100 bytes), data matches
[03:30:18-257.885] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.888] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.892 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.895 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.898 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.902 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:3 0:18-25 7. 905 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.908 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:3 0:18-25 7.911 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.915 ] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:30:18-257.918 ] [TRACE] [8] (test_etcp_simple_traffic.c:215) check_packet_received() check_packet_received: ENTERING
[03:30:18-257.921 ] [DEBUG] [8] (test_etcp_simple_traffic.c:233) check_packet_received() check_packet_received: Checking server connection 0x62cb67d22 2b0
[03:30:18-257.925 ] [DEBUG] [8] (test_etcp_simple_traffic.c:234) check_packet_received() check_packet_received: Server output_queue count: 1
[03:30:18-257.92 8] [DEBUG] [8] (test_etcp_simple_traffic.c:242) check_packet_received() check_packet_received: Found packet in output queue
[03:30:18-257.931 ] [DEBUG] [8] (test_etcp_simple_traffic.c:248) check_packet_received() check_packet_received: Packet size=100, expected=100
[03:30:18-257.934 ] [DEBUG] [8] (test_etcp_simple_traffic.c:249) check_packet_received() check_packet_received: First byte received=00, expected=00
[03:30:18-257.937 ] [INFO] [8] (test_etcp_simple_traffic.c:255) check_packet_received() check_packet_received: SUCCESS - Packet received in server output queue (100 bytes), data matches
[TEST] Packet received, exiting early after 50 ms
Cleaning up...
[03:05:50-438.225 ] [INFO] [32] (utun_instance.c:153) utun_instance_destroy() [INSTANCE_DESTROY] Starting cleanup for instance 0x60fa30cb7 4e0
[03:30:18-257.941 ] [INFO] [32] (utun_instance.c:153) utun_instance_destroy() [INSTANCE_DESTROY] Starting cleanup for instance 0x62cb67cd5 4e0
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x60fa30cb7 4e0
Instance: 0x62cb67cd5 4e0
Node ID: 1229782938247303441
UA instance: 0x60fa30cb6 4d0
UA instance: 0x62cb67cd4 4d0
Running: 0
📊 STRUCTURE COUNTS:
@ -400,8 +400,8 @@ Cleaning up...
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x60fa30d04 2b0
ETCP Sockets list: 0x60fa30cb8 4d0
Connections list: 0x62cb67d22 2b0
ETCP Sockets list: 0x62cb67cd6 4d0
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
@ -414,52 +414,52 @@ Cleaning up...
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-438.232 ] [INFO] [32] (utun_instance.c:162) utun_instance_destroy() [INSTANCE_DESTROY] Cleaning up ETCP sockets and connections
[03:05:50-438.236] [INFO] [32] (utun_instance.c:166) utun_instance_destroy() [INSTANCE_DESTROY] Removing socket 0x60fa30cb8 4d0, fd=6
[03:05:50-438.240] [TRACE] [4] (etcp_connections.c:370 ) etcp_socket_remove()
[03:05:50-438.244] [INFO] [8] (etcp_connections.c:373) etcp_socket_remove() [ETCP] Removing socket 0x60fa30cb84d0, socket_id=0x60fa30cb6 580
[03:05:50-438.248] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x60fa30cb74e0, ua=0x60fa30cb6 4d0
[03:05:50-438.257] [INFO] [8] (etcp_connections.c:380 ) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:05:50-438.271] [INFO] [8] (etcp_connections.c:385 ) etcp_socket_remove() [ETCP] Closed socket
[03:05:50-438.275] [TRACE] [4] (etcp_connections.c:446 ) etcp_link_close()
[03:05:50-438.302] [TRACE] [4] (etcp_connections.c:208 ) remove_link()
[03:05:50-438.312] [TRACE] [4] (etcp_connections.c:147 ) find_link_index()
[03:05 :50-438.3 18] [INFO] [32] (utun_instance.c:171) utun_instance_destroy() [INSTANCE_DESTROY] ETCP sockets cleanup complete
[03:05:50-438.325 ] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x60fa30d04 2b0
[03:05:50-438.33 0] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:05:50-438.334 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-438.340] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x60fa30d04 2b0 from senders_list
[03:05:50-438.345 ] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x60fa30d04 2b0 to all peers
[03:05:50-438.349] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x60fa30d04 2b0 removed from senders_list
[03:05:50-438.353] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x60fa30d04 2b0
[03:05:50-438.358 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-438.362] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d03 950, head=(nil), tail=(nil), count=0
[03:05:50-438.366] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d03 9e0, head=(nil), tail=(nil), count=0
[03:05:50-438.371] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d04 420, head=(nil), tail=(nil), count=0
[03:05:50-438.375] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d04 4b0, head=(nil), tail=(nil), count=0
[03:05:50-438.379] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d04 540, head=(nil), tail=(nil), count=0
[03:05:50-438.383] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d03 160, head=(nil), tail=(nil), count=0
[03:05:50-438.387] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d02 ea0, head=(nil), tail=(nil), count=0
[03:05:50-438.391] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d03 2d0, head=(nil), tail=(nil), count=0
[03:05:50-438.396 ] [INFO] [32] (utun_instance.c:184) utun_instance_destroy() [INSTANCE_DESTROY] ETCP connections cleanup complete
[03:05:50-438.399 ] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:05:50-438.404] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 0 for instance 0x60fa30cb7 4e0
[03:05:50-438.409 ] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:05:50-438.413] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 1 for instance 0x60fa30cb7 4e0
[03:05:50-438.417] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cb8 830, head=(nil), tail=(nil), count=0
[03:05:50-438.421 ] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
[03:05:50-438.42 4] [INFO] [32] (utun_instance.c:205) utun_instance_destroy() [INSTANCE_DESTROY] Freeing configuration
[03:05:50-438.429 ] [INFO] [32] (utun_instance.c:212) utun_instance_destroy() [INSTANCE_DESTROY] Destroying packet pool
[03:05:50-438.433 ] [INFO] [32] (utun_instance.c:219) utun_instance_destroy() [INSTANCE_DESTROY] Destroying ack pool
[03:05:50-438.437 ] [INFO] [32] (utun_instance.c:226) utun_instance_destroy() [INSTANCE_DESTROY] Destroying data pool
[03:05:50-438.440 ] [INFO] [32] (utun_instance.c:241) utun_instance_destroy() [INSTANCE_DESTROY] Freeing instance memory
[03:05:50-438.444 ] [INFO] [32] (utun_instance.c:243) utun_instance_destroy() [INSTANCE_DESTROY] Instance destroyed completely
[03:05:50-438.448 ] [INFO] [32] (utun_instance.c:153) utun_instance_destroy() [INSTANCE_DESTROY] Starting cleanup for instance 0x60fa30cbb 490
[03:30:18-257.947 ] [INFO] [32] (utun_instance.c:162) utun_instance_destroy() [INSTANCE_DESTROY] Cleaning up ETCP sockets and connections
[03:30:18-257.950] [INFO] [32] (utun_instance.c:166) utun_instance_destroy() [INSTANCE_DESTROY] Removing socket 0x62cb67cd6 4d0, fd=6
[03:30:18-257.953] [TRACE] [4] (etcp_connections.c:372 ) etcp_socket_remove()
[03:30:18-257.957] [INFO] [8] (etcp_connections.c:375) etcp_socket_remove() [ETCP] Removing socket 0x62cb67cd64d0, socket_id=0x62cb67cd4 580
[03:30:18-257.960] [INFO] [8] (etcp_connections.c:379) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x62cb67cd54e0, ua=0x62cb67cd4 4d0
[03:30:18-257.966] [INFO] [8] (etcp_connections.c:382 ) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:30:18-257.978] [INFO] [8] (etcp_connections.c:387 ) etcp_socket_remove() [ETCP] Closed socket
[03:30:18-257.982] [TRACE] [4] (etcp_connections.c:448 ) etcp_link_close()
[03:30:18-257.988] [TRACE] [4] (etcp_connections.c:210 ) remove_link()
[03:30:18-257.991] [TRACE] [4] (etcp_connections.c:149 ) find_link_index()
[03:3 0:18-257.994 ] [INFO] [32] (utun_instance.c:171) utun_instance_destroy() [INSTANCE_DESTROY] ETCP sockets cleanup complete
[03:30:18-257.997 ] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x62cb67d22 2b0
[03:30:18-258.00 0] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:30:18-258.003 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:30:18-258.007] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x62cb67d22 2b0 from senders_list
[03:30:18-258.010 ] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x62cb67d22 2b0 to all peers
[03:30:18-258.014] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x62cb67d22 2b0 removed from senders_list
[03:30:18-258.017] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x62cb67d22 2b0
[03:30:18-258.021 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:30:18-258.024] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d21 950, head=(nil), tail=(nil), count=0
[03:30:18-258.028] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d21 9e0, head=(nil), tail=(nil), count=0
[03:30:18-258.031] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d22 420, head=(nil), tail=(nil), count=0
[03:30:18-258.034] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d22 4b0, head=(nil), tail=(nil), count=0
[03:30:18-258.037] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d22 540, head=(nil), tail=(nil), count=0
[03:30:18-258.041] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d21 160, head=(nil), tail=(nil), count=0
[03:30:18-258.044] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d20 ea0, head=(nil), tail=(nil), count=0
[03:30:18-258.047] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67d21 2d0, head=(nil), tail=(nil), count=0
[03:30:18-258.051 ] [INFO] [32] (utun_instance.c:184) utun_instance_destroy() [INSTANCE_DESTROY] ETCP connections cleanup complete
[03:30:18-258.054 ] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:30:18-258.057] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 0 for instance 0x62cb67cd5 4e0
[03:30:18-258.061 ] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:30:18-258.064] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 1 for instance 0x62cb67cd5 4e0
[03:30:18-258.067] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67cd6 830, head=(nil), tail=(nil), count=0
[03:30:18-258.070 ] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
[03:30:18-258.07 4] [INFO] [32] (utun_instance.c:205) utun_instance_destroy() [INSTANCE_DESTROY] Freeing configuration
[03:30:18-258.077 ] [INFO] [32] (utun_instance.c:212) utun_instance_destroy() [INSTANCE_DESTROY] Destroying packet pool
[03:30:18-258.080 ] [INFO] [32] (utun_instance.c:219) utun_instance_destroy() [INSTANCE_DESTROY] Destroying ack pool
[03:30:18-258.083 ] [INFO] [32] (utun_instance.c:226) utun_instance_destroy() [INSTANCE_DESTROY] Destroying data pool
[03:30:18-258.086 ] [INFO] [32] (utun_instance.c:241) utun_instance_destroy() [INSTANCE_DESTROY] Freeing instance memory
[03:30:18-258.090 ] [INFO] [32] (utun_instance.c:243) utun_instance_destroy() [INSTANCE_DESTROY] Instance destroyed completely
[03:30:18-258.093 ] [INFO] [32] (utun_instance.c:153) utun_instance_destroy() [INSTANCE_DESTROY] Starting cleanup for instance 0x62cb67cd9 490
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x60fa30cbb 490
Instance: 0x62cb67cd9 490
Node ID: 2459565876494606882
UA instance: 0x60fa30cb6 4d0
UA instance: 0x62cb67cd4 4d0
Running: 0
📊 STRUCTURE COUNTS:
@ -471,8 +471,8 @@ Cleaning up...
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x60fa30cb8 eb0
ETCP Sockets list: 0x60fa30cbc 840
Connections list: 0x62cb67cd6 eb0
ETCP Sockets list: 0x62cb67cda 840
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
@ -485,63 +485,63 @@ Cleaning up...
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-438.454 ] [INFO] [32] (utun_instance.c:162) utun_instance_destroy() [INSTANCE_DESTROY] Cleaning up ETCP sockets and connections
[03:05:50-438.462] [INFO] [32] (utun_instance.c:166) utun_instance_destroy() [INSTANCE_DESTROY] Removing socket 0x60fa30cbc 840, fd=7
[03:05:50-438.466] [TRACE] [4] (etcp_connections.c:370 ) etcp_socket_remove()
[03:05:50-438.471] [INFO] [8] (etcp_connections.c:373) etcp_socket_remove() [ETCP] Removing socket 0x60fa30cbc840, socket_id=0x60fa30cb6 5c8
[03:05:50-438.475] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x60fa30cbb490, ua=0x60fa30cb6 4d0
[03:05:50-438.481] [INFO] [8] (etcp_connections.c:380 ) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:05:50-438.489] [INFO] [8] (etcp_connections.c:385 ) etcp_socket_remove() [ETCP] Closed socket
[03:05:50-438.493] [TRACE] [4] (etcp_connections.c:446 ) etcp_link_close()
[03:05:50-438.497] [TRACE] [4] (etcp_connections.c:208 ) remove_link()
[03:05:50-438.501] [TRACE] [4] (etcp_connections.c:147 ) find_link_index()
[03:05:50-438.505 ] [INFO] [32] (utun_instance.c:171) utun_instance_destroy() [INSTANCE_DESTROY] ETCP sockets cleanup complete
[03:05:50-438.509 ] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x60fa30cb8 eb0
[03:05:50-438.512 ] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:05:50-438.516 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-438.520] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x60fa30cb8 eb0 from senders_list
[03:05:50-438.524 ] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x60fa30cb8 eb0 to all peers
[03:05:50-438.528] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x60fa30cb8 eb0 removed from senders_list
[03:05:50-438.532] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x60fa30cb8 eb0
[03:05:50-438.536 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-438.540] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc5 570, head=(nil), tail=(nil), count=0
[03:05:50-438.544] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc5 600, head=(nil), tail=(nil), count=0
[03:05:50-438.548] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cb7 330, head=(nil), tail=(nil), count=0
[03:05:50-438.552] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cb8 a80, head=(nil), tail=(nil), count=0
[03:05:50-438.556] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cbf 300, head=(nil), tail=(nil), count=0
[03:05:50-438.560] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc1 3a0, head=(nil), tail=(nil), count=0
[03:05:50-438.565] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc5 4e0, head=(nil), tail=(nil), count=0
[03:05:50-438.569] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc3 440, head=(nil), tail=(nil), count=0
[03:05:50-438.573 ] [INFO] [32] (utun_instance.c:184) utun_instance_destroy() [INSTANCE_DESTROY] ETCP connections cleanup complete
[03:05:50-438.577 ] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:05:50-438.585] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 0 for instance 0x60fa30cbb 490
[03:05:50-438.589 ] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:05:50-438.593] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 1 for instance 0x60fa30cbb 490
[03:05:50-438.597] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cbc a20, head=(nil), tail=(nil), count=0
[03:05:50-438.601 ] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
[03:05:50-438.605 ] [INFO] [32] (utun_instance.c:205) utun_instance_destroy() [INSTANCE_DESTROY] Freeing configuration
[03:05:50-438.609 ] [INFO] [32] (utun_instance.c:212) utun_instance_destroy() [INSTANCE_DESTROY] Destroying packet pool
[03:05:50-438.612 ] [INFO] [32] (utun_instance.c:219) utun_instance_destroy() [INSTANCE_DESTROY] Destroying ack pool
[03:05:50-438.616 ] [INFO] [32] (utun_instance.c:226) utun_instance_destroy() [INSTANCE_DESTROY] Destroying data pool
[03:05:50-438.621 ] [INFO] [32] (utun_instance.c:241) utun_instance_destroy() [INSTANCE_DESTROY] Freeing instance memory
[03:05:50-438.625 ] [INFO] [32] (utun_instance.c:243) utun_instance_destroy() [INSTANCE_DESTROY] Instance destroyed completely
[03:05:50-438.628] [DEBUG] [1024] (u_async.c:1000) uasync_destroy() uasync_destroy: starting cleanup for ua=0x60fa30cb6 4d0
[03:30:18-258.097 ] [INFO] [32] (utun_instance.c:162) utun_instance_destroy() [INSTANCE_DESTROY] Cleaning up ETCP sockets and connections
[03:30:18-258.103] [INFO] [32] (utun_instance.c:166) utun_instance_destroy() [INSTANCE_DESTROY] Removing socket 0x62cb67cda 840, fd=7
[03:30:18-258.106] [TRACE] [4] (etcp_connections.c:372 ) etcp_socket_remove()
[03:30:18-258.109] [INFO] [8] (etcp_connections.c:375) etcp_socket_remove() [ETCP] Removing socket 0x62cb67cda840, socket_id=0x62cb67cd4 5c8
[03:30:18-258.112] [INFO] [8] (etcp_connections.c:379) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x62cb67cd9490, ua=0x62cb67cd4 4d0
[03:30:18-258.116] [INFO] [8] (etcp_connections.c:382 ) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:30:18-258.122] [INFO] [8] (etcp_connections.c:387 ) etcp_socket_remove() [ETCP] Closed socket
[03:30:18-258.125] [TRACE] [4] (etcp_connections.c:448 ) etcp_link_close()
[03:30:18-258.128] [TRACE] [4] (etcp_connections.c:210 ) remove_link()
[03:30:18-258.131] [TRACE] [4] (etcp_connections.c:149 ) find_link_index()
[03:30:18-258.134 ] [INFO] [32] (utun_instance.c:171) utun_instance_destroy() [INSTANCE_DESTROY] ETCP sockets cleanup complete
[03:30:18-258.137 ] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x62cb67cd6 eb0
[03:30:18-258.140 ] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:30:18-258.144 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:30:18-258.147] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x62cb67cd6 eb0 from senders_list
[03:30:18-258.150 ] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x62cb67cd6 eb0 to all peers
[03:30:18-258.153] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x62cb67cd6 eb0 removed from senders_list
[03:30:18-258.156] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x62cb67cd6 eb0
[03:30:18-258.159 ] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:30:18-258.163] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67ce3 570, head=(nil), tail=(nil), count=0
[03:30:18-258.166] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67ce3 600, head=(nil), tail=(nil), count=0
[03:30:18-258.169] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67cd5 330, head=(nil), tail=(nil), count=0
[03:30:18-258.172] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67cd6 a80, head=(nil), tail=(nil), count=0
[03:30:18-258.176] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67cdd 300, head=(nil), tail=(nil), count=0
[03:30:18-258.179] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67cdf 3a0, head=(nil), tail=(nil), count=0
[03:30:18-258.182] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67ce3 4e0, head=(nil), tail=(nil), count=0
[03:30:18-258.186] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67ce1 440, head=(nil), tail=(nil), count=0
[03:30:18-258.189 ] [INFO] [32] (utun_instance.c:184) utun_instance_destroy() [INSTANCE_DESTROY] ETCP connections cleanup complete
[03:30:18-258.192 ] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:30:18-258.198] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 0 for instance 0x62cb67cd9 490
[03:30:18-258.201 ] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:30:18-258.604] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 1 for instance 0x62cb67cd9 490
[03:30:18-258.610] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x62cb67cda a20, head=(nil), tail=(nil), count=0
[03:30:18-258.613 ] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
[03:30:18-258.617 ] [INFO] [32] (utun_instance.c:205) utun_instance_destroy() [INSTANCE_DESTROY] Freeing configuration
[03:30:18-258.620 ] [INFO] [32] (utun_instance.c:212) utun_instance_destroy() [INSTANCE_DESTROY] Destroying packet pool
[03:30:18-258.624 ] [INFO] [32] (utun_instance.c:219) utun_instance_destroy() [INSTANCE_DESTROY] Destroying ack pool
[03:30:18-258.627 ] [INFO] [32] (utun_instance.c:226) utun_instance_destroy() [INSTANCE_DESTROY] Destroying data pool
[03:30:18-258.630 ] [INFO] [32] (utun_instance.c:241) utun_instance_destroy() [INSTANCE_DESTROY] Freeing instance memory
[03:30:18-258.634 ] [INFO] [32] (utun_instance.c:243) utun_instance_destroy() [INSTANCE_DESTROY] Instance destroyed completely
[03:30:18-258.637] [DEBUG] [1024] (u_async.c:1000) uasync_destroy() uasync_destroy: starting cleanup for ua=0x62cb67cd4 4d0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x60fa30cb6 4d0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x62cb67cd4 4d0
Timer Statistics: allocated=6, freed=3, active=3
Socket Statistics: allocated=2, freed=2, active=0
Timer: node=0x60fa30d04220, expires=1771113950533 ms, cancelled=0
Timer: node=0x62cb67d22220, expires=1771115418356 ms, cancelled=0
Active timers in heap: 1
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-438.634 ] [ERROR] [32] (u_async.c:1007) uasync_destroy() Memory leaks detected before cleanup: timers 6/3, sockets 2/2
[03:05:50-438.638 ] [ERROR] [1024] (u_async.c:1009) uasync_destroy() Timer leak: allocated=6, freed=3, diff=3
[03:05:50-438.642 ] [ERROR] [1024] (u_async.c:1012) uasync_destroy() Socket leak: allocated=2, freed=2, diff=0
[03:05:50-438.647 ] [DEBUG] [32] (u_async.c:1048) uasync_destroy() Freed 0 socket nodes in destroy
[03:05:50-438.664 ] [DEBUG] [1024] (u_async.c:1081) uasync_destroy() uasync_destroy: completed successfully for ua=0x60fa30cb6 4d0
[03:05:50-438.670 ] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:30:18-258.641 ] [ERROR] [32] (u_async.c:1007) uasync_destroy() Memory leaks detected before cleanup: timers 6/3, sockets 2/2
[03:30:18-258.645 ] [ERROR] [1024] (u_async.c:1009) uasync_destroy() Timer leak: allocated=6, freed=3, diff=3
[03:30:18-258.648 ] [ERROR] [1024] (u_async.c:1012) uasync_destroy() Socket leak: allocated=2, freed=2, diff=0
[03:30:18-258.651 ] [DEBUG] [32] (u_async.c:1048) uasync_destroy() Freed 0 socket nodes in destroy
[03:30:18-258.666 ] [DEBUG] [1024] (u_async.c:1081) uasync_destroy() uasync_destroy: completed successfully for ua=0x62cb67cd4 4d0
[03:30:18-258.669 ] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
=== TEST PASSED ===
✅ Packet successfully transmitted from client input queue to server output queue