Browse Source

Fix Windows build: add sa_family_t typedef, replace arpa/inet.h, fix ll_queue warnings

- Add sa_family_t typedef for Windows in platform_compat.h
- Add forward declaration of struct ll_queue in ll_queue.h to fix warnings
- Replace arpa/inet.h includes with platform_compat.h in:
  tun_linux.c, etcp_connections.c, route_lib.c, route_bgp.c,
  utun_instance.c, routing.c, utun.c, packet_dump.h, config_parser.c
- All 22 tests pass on Linux
nodeinfo-routing-update
Evgeny 8 months ago
parent
commit
c83fdeeaad
  1. 130
      build_win.log
  2. 3
      lib/ll_queue.h
  3. 5
      lib/platform_compat.h
  4. 2
      src/config_parser.c
  5. 2
      src/etcp_connections.c
  6. 2
      src/packet_dump.h
  7. 2
      src/route_bgp.c
  8. 41
      src/route_bgp.txt
  9. 2
      src/route_lib.c
  10. 2
      src/routing.c
  11. 2
      src/tun_linux.c
  12. 2
      src/utun.c
  13. 2
      src/utun_instance.c
  14. BIN
      tests/bench_timeout_heap
  15. BIN
      tests/bench_uasync_timeouts
  16. 24
      tests/logs/bench_timeout_heap.log
  17. 149
      tests/logs/bench_uasync_timeouts.log
  18. 226
      tests/logs/test_bgp_route_exchange.log
  19. 16
      tests/logs/test_config_debug.log
  20. 6
      tests/logs/test_crypto.log
  21. 8
      tests/logs/test_debug_categories.log
  22. 19
      tests/logs/test_ecc_encrypt.log
  23. 3385
      tests/logs/test_etcp_100_packets.log
  24. 171
      tests/logs/test_etcp_api.log
  25. 6
      tests/logs/test_etcp_crypto.log
  26. 46
      tests/logs/test_etcp_minimal.log
  27. 548
      tests/logs/test_etcp_simple_traffic.log
  28. 528
      tests/logs/test_etcp_two_instances.log
  29. 44
      tests/logs/test_intensive_memory_pool.log
  30. 104
      tests/logs/test_ll_queue.log
  31. 26
      tests/logs/test_memory_pool_and_config.log
  32. 3
      tests/logs/test_packet_dump.log
  33. 188
      tests/logs/test_pkt_normalizer_etcp.log
  34. 29
      tests/logs/test_pkt_normalizer_standalone.log
  35. 3182
      tests/logs/test_route_lib.log
  36. 115
      tests/logs/test_u_async_comprehensive.log
  37. 59
      tests/logs/test_u_async_performance.log
  38. BIN
      tests/test_bgp_route_exchange
  39. BIN
      tests/test_config_debug
  40. BIN
      tests/test_crypto
  41. BIN
      tests/test_debug_categories
  42. BIN
      tests/test_ecc_encrypt
  43. BIN
      tests/test_etcp_100_packets
  44. BIN
      tests/test_etcp_api
  45. BIN
      tests/test_etcp_crypto
  46. BIN
      tests/test_etcp_minimal
  47. BIN
      tests/test_etcp_simple_traffic
  48. BIN
      tests/test_etcp_two_instances
  49. BIN
      tests/test_intensive_memory_pool
  50. BIN
      tests/test_ll_queue
  51. BIN
      tests/test_memory_pool_and_config
  52. BIN
      tests/test_packet_dump
  53. BIN
      tests/test_pkt_normalizer_etcp
  54. BIN
      tests/test_pkt_normalizer_standalone
  55. BIN
      tests/test_route_lib
  56. BIN
      tests/test_u_async_comprehensive
  57. BIN
      tests/test_u_async_performance

130
build_win.log

@ -0,0 +1,130 @@
make all-recursive
make[1]: Entering directory '/c/ARM/_uTun/utun2'
Making all in lib
make[2]: Entering directory '/c/ARM/_uTun/utun2/lib'
gcc -DHAVE_CONFIG_H -I. -I.. -D_ISOC99_SOURCE -DDEBUG_OUTPUT_STDERR -I../src -I../lib -g -O2 -MT libuasync_a-u_async.o -MD -MP -MF .deps/libuasync_a-u_async.Tpo -c -o libuasync_a-u_async.o `test -f 'u_async.c' || echo './'`u_async.c
gcc -DHAVE_CONFIG_H -I. -I.. -D_ISOC99_SOURCE -DDEBUG_OUTPUT_STDERR -I../src -I../lib -g -O2 -MT libuasync_a-ll_queue.o -MD -MP -MF .deps/libuasync_a-ll_queue.Tpo -c -o libuasync_a-ll_queue.o `test -f 'll_queue.c' || echo './'`ll_queue.c
gcc -DHAVE_CONFIG_H -I. -I.. -D_ISOC99_SOURCE -DDEBUG_OUTPUT_STDERR -I../src -I../lib -g -O2 -MT libuasync_a-debug_config.o -MD -MP -MF .deps/libuasync_a-debug_config.Tpo -c -o libuasync_a-debug_config.o `test -f 'debug_config.c' || echo './'`debug_config.c
In file included from ll_queue.c:6:
ll_queue.h:69:42: warning: 'struct ll_queue' declared inside parameter list will not be visible outside of this definition or declaration
69 | typedef void (*queue_callback_fn)(struct ll_queue* q, void* arg);
| ^~~~~~~~
ll_queue.h:77:52: warning: 'struct ll_queue' declared inside parameter list will not be visible outside of this definition or declaration
77 | typedef void (*queue_threshold_callback_fn)(struct ll_queue* q, void* arg);
| ^~~~~~~~
ll_queue.c: In function 'queue_resume_timeout_cb':
ll_queue.c:98:21: warning: passing argument 1 of 'q->callback' from incompatible pointer type [-Wincompatible-pointer-types]
98 | q->callback(q, q->callback_arg);
| ^
| |
| struct ll_queue *
ll_queue.c:98:21: note: expected 'struct ll_queue *' but argument is of type 'struct ll_queue *'
ll_queue.c: In function 'check_waiters':
ll_queue.c:219:30: warning: passing argument 1 of 'waiter->callback' from incompatible pointer type [-Wincompatible-pointer-types]
219 | waiter->callback(q, waiter->callback_arg);
| ^
| |
| struct ll_queue *
ll_queue.c:219:30: note: expected 'struct ll_queue *' but argument is of type 'struct ll_queue *'
ll_queue.c: In function 'queue_data_put':
ll_queue.c:259:21: warning: passing argument 1 of 'q->callback' from incompatible pointer type [-Wincompatible-pointer-types]
259 | q->callback(q, q->callback_arg);
| ^
| |
| struct ll_queue *
ll_queue.c:259:21: note: expected 'struct ll_queue *' but argument is of type 'struct ll_queue *'
ll_queue.c: In function 'queue_data_put_first':
ll_queue.c:299:21: warning: passing argument 1 of 'q->callback' from incompatible pointer type [-Wincompatible-pointer-types]
299 | q->callback(q, q->callback_arg);
| ^
| |
| struct ll_queue *
ll_queue.c:299:21: note: expected 'struct ll_queue *' but argument is of type 'struct ll_queue *'
ll_queue.c: In function 'queue_wait_threshold':
ll_queue.c:351:18: warning: passing argument 1 of 'callback' from incompatible pointer type [-Wincompatible-pointer-types]
351 | callback(q, arg);
| ^
| |
| struct ll_queue *
ll_queue.c:351:18: note: expected 'struct ll_queue *' but argument is of type 'struct ll_queue *'
u_async.c: In function 'uasync_poll':
u_async.c:780:15: warning: implicit declaration of function 'poll' [-Wimplicit-function-declaration]
780 | int ret = poll(ua->poll_fds, ua->poll_fds_count, timeout_ms);
| ^~~~
mv -f .deps/libuasync_a-ll_queue.Tpo .deps/libuasync_a-ll_queue.Po
mv -f .deps/libuasync_a-debug_config.Tpo .deps/libuasync_a-debug_config.Po
mv -f .deps/libuasync_a-u_async.Tpo .deps/libuasync_a-u_async.Po
rm -f libuasync.a
ar cru libuasync.a libuasync_a-u_async.o libuasync_a-ll_queue.o libuasync_a-debug_config.o libuasync_a-timeout_heap.o libuasync_a-memory_pool.o libuasync_a-sha256.o libuasync_a-socket_compat.o
C:\msys64\ucrt64\bin\ar.exe: `u' modifier ignored since `D' is the default (see `U')
ranlib libuasync.a
make[2]: Leaving directory '/c/ARM/_uTun/utun2/lib'
Making all in src
make[2]: Entering directory '/c/ARM/_uTun/utun2/src'
gcc -DHAVE_CONFIG_H -I. -I.. -I../lib -I../tinycrypt/lib/include -I../tinycrypt/lib/source -g -O2 -MT utun-utun.o -MD -MP -MF .deps/utun-utun.Tpo -c -o utun-utun.o `test -f 'utun.c' || echo './'`utun.c
gcc -DHAVE_CONFIG_H -I. -I.. -I../lib -I../tinycrypt/lib/include -I../tinycrypt/lib/source -g -O2 -MT utun-utun_instance.o -MD -MP -MF .deps/utun-utun_instance.Tpo -c -o utun-utun_instance.o `test -f 'utun_instance.c' || echo './'`utun_instance.c
gcc -DHAVE_CONFIG_H -I. -I.. -I../lib -I../tinycrypt/lib/include -I../tinycrypt/lib/source -g -O2 -MT utun-config_parser.o -MD -MP -MF .deps/utun-config_parser.Tpo -c -o utun-config_parser.o `test -f 'config_parser.c' || echo './'`config_parser.c
gcc -DHAVE_CONFIG_H -I. -I.. -I../lib -I../tinycrypt/lib/include -I../tinycrypt/lib/source -g -O2 -MT utun-config_updater.o -MD -MP -MF .deps/utun-config_updater.Tpo -c -o utun-config_updater.o `test -f 'config_updater.c' || echo './'`config_updater.c
In file included from etcp_api.h:19,
from utun_instance.h:9,
from utun_instance.c:2:
../lib/ll_queue.h:69:42: warning: 'struct ll_queue' declared inside parameter list will not be visible outside of this definition or declaration
69 | typedef void (*queue_callback_fn)(struct ll_queue* q, void* arg);
| ^~~~~~~~
../lib/ll_queue.h:77:52: warning: 'struct ll_queue' declared inside parameter list will not be visible outside of this definition or declaration
77 | typedef void (*queue_threshold_callback_fn)(struct ll_queue* q, void* arg);
| ^~~~~~~~
In file included from config_updater.c:4:
config_parser.h:18:5: error: unknown type name 'sa_family_t'
18 | sa_family_t family;
| ^~~~~~~~~~~
In file included from utun_instance.c:3:
config_parser.h:18:5: error: unknown type name 'sa_family_t'
18 | sa_family_t family;
| ^~~~~~~~~~~
utun_instance.c:18:10: fatal error: arpa/inet.h: No such file or directory
18 | #include <arpa/inet.h>
| ^~~~~~~~~~~~~
compilation terminated.
make[2]: *** [Makefile:623: utun-utun_instance.o] Error 1
make[2]: *** Waiting for unfinished jobs....
In file included from utun.c:4:
config_parser.h:18:5: error: unknown type name 'sa_family_t'
18 | sa_family_t family;
| ^~~~~~~~~~~
make[2]: *** [Makefile:651: utun-config_updater.o] Error 1
In file included from etcp_api.h:19,
from utun_instance.h:9,
from etcp_connections.h:7,
from utun.c:5:
../lib/ll_queue.h:69:42: warning: 'struct ll_queue' declared inside parameter list will not be visible outside of this definition or declaration
69 | typedef void (*queue_callback_fn)(struct ll_queue* q, void* arg);
| ^~~~~~~~
../lib/ll_queue.h:77:52: warning: 'struct ll_queue' declared inside parameter list will not be visible outside of this definition or declaration
77 | typedef void (*queue_threshold_callback_fn)(struct ll_queue* q, void* arg);
| ^~~~~~~~
In file included from config_parser.c:3:
config_parser.h:18:5: error: unknown type name 'sa_family_t'
18 | sa_family_t family;
| ^~~~~~~~~~~
utun.c:22:10: fatal error: arpa/inet.h: No such file or directory
22 | #include <arpa/inet.h>
| ^~~~~~~~~~~~~
compilation terminated.
config_parser.c:10:10: fatal error: arpa/inet.h: No such file or directory
10 | #include <arpa/inet.h>
| ^~~~~~~~~~~~~
compilation terminated.
make[2]: *** [Makefile:609: utun-utun.o] Error 1
make[2]: *** [Makefile:637: utun-config_parser.o] Error 1
make[2]: Leaving directory '/c/ARM/_uTun/utun2/src'
make[1]: *** [Makefile:379: all-recursive] Error 1
make[1]: Leaving directory '/c/ARM/_uTun/utun2'
make: *** [Makefile:320: all] Error 2
make[1]: Leaving directory '/c/ARM/_uTun/utun2'
make: *** [Makefile:320: all] Error 2
Build completed successfully!
Binary: src/utun.exe
Make sure wintun.dll is in the same directory as utun.exe

3
lib/ll_queue.h

@ -32,6 +32,9 @@
* - dgram освобождается отдельно через queue_dgram_free() или кастомную dgram_free_fn
*/
// Forward declaration
struct ll_queue;
/**
* @struct ll_entry
* @brief Элемент очереди (переменного размера).

5
lib/platform_compat.h

@ -104,6 +104,11 @@
// nanosleep already defined in pthread_time.h on MSYS2
// poll() and pollfd already defined in winsock2.h on MSYS2
// sa_family_t might not be defined on some Windows setups
#ifndef sa_family_t
typedef unsigned short sa_family_t;
#endif
#else
// POSIX - include standard headers
#include <sys/time.h>

2
src/config_parser.c

@ -7,7 +7,7 @@
#include <strings.h>
#include "../lib/debug_config.h"
#include <ctype.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#include <errno.h>
#include <netdb.h>
#include <ifaddrs.h>

2
src/etcp_connections.c

@ -1,6 +1,6 @@
#include "etcp_connections.h"
#include "../lib/socket_compat.h"
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#include <net/if.h>
#include <unistd.h>
#include <string.h>

2
src/packet_dump.h

@ -1,7 +1,7 @@
#include <stdio.h>
#include <stdint.h>
#include <string.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#include <netinet/in.h>
// Packet dump function for debugging

2
src/route_bgp.c

@ -10,7 +10,7 @@
#include <stdlib.h>
#include <string.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#include "route_bgp.h"
#include "route_lib.h"

41
src/route_bgp.txt

@ -0,0 +1,41 @@
подсистема роутинга
utun - это сеть узлов. у каждого узла есть собственные локальные подсети.
глобальная задача: создать у каждого узла полную таблицу маршрутизации.
Узлы преимущественно создают связь напрямую друг с другом. Но если это не получается отправляют трафик транзитом через доступные узлы.
Иногда бывает что через транзитные узлы метрики лучше чем напрямую. Используем приоритетно узлы с лучшей метриков, при нехватке bandwidth используем разные каналы (агрегируем).
Динамически обновлем метрики каналов чтобы при отказе быстро переключаться на другие и не фризить обмен из-за отказов.
и узлы обмениваются таблицой маршрутов между собой так чтобы у каждого была актуальная таблица подсетей всех узлов.
маршрутами меняются клиенты, подключения которых которые взяты из конфига. и сервера принявшие подключения если клиент инициировал обмен маршрутами.
инициируется подключение, клиент отправляет свою таблицу. когда сервер принимает таблицу - сервер помечает что по этому маршруту надо обмениваться маршрутами, далее;
- добавляет узел в список рассылки обновлений маршрутов
- отправляет свою таблицу
- добавляет в свою таблицу отсутствующие маршруты
- если что-то добавил:
- рассылает измененные маршруты по списку рассылки
- список рассылки - это linked-list очередей (также на базе ll_queue - каждый элемент = подписчик). один маршрут = одна отправленная кодограмма
при подключении узла или изменении таблицы: узел шлёт свою таблицу
формат кодограммы: [0x01 - routing module] [subcmd] [data]
subcmd:
1 [route] - отправка маршрута
2, без данных - больше данных нет
если сервер получил кодограмму маршрута - он помечает флаг в etcp что с узлом надо обмениваться маршрутами (etcp_conn->routing_exchange_active=2) и добавляет в очередь рассылки маршрутов
=========================================
механизм инкрементальной синхронизации (реализация - потом, пока мысли)
1. вычисляем хеш каждой записи в роутинг таблице. используем ip+mask+node_uid
2. потом из этих хешей создаем хеш таблицу (старшие n бит номер ячейки). далее вычисляются хеши каждой ячейки.
на первом этапе n=16, на втором - n=16*16 на третьем n=16*16*16.
отправляем хеши удаленному узлу в формате: [n, 1 байт] ([индекс хеша 2 байта - используется n старших бит][хеш - 8 байт])
удаленный узел считает свои хеши и сравнивает. где не совпало смотрит сколько записей.
если записей не много - передает эти записи.
если записей много - добавляет 4 бита к хеш таблице и строит субтаблицу для

2
src/route_lib.c

@ -9,7 +9,7 @@
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#include <time.h>
#define INITIAL_ROUTE_CAPACITY 100

2
src/routing.c

@ -10,7 +10,7 @@
#include "../lib/debug_config.h"
#include <string.h>
#include <stdlib.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#define IPv4_VERSION 4
#define IPv6_VERSION 6

2
src/tun_linux.c

@ -14,7 +14,7 @@
#include <sys/stat.h>
#include <net/if.h>
#include <netinet/in.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
#include <linux/if.h>
#include <linux/if_tun.h>
#include <errno.h>

2
src/utun.c

@ -19,7 +19,7 @@
#include <signal.h>
#include <getopt.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"
/*
Архитектура:

2
src/utun_instance.c

@ -15,7 +15,7 @@
#include <string.h>
#include <errno.h>
#include <unistd.h>
#include <arpa/inet.h>
#include "../lib/platform_compat.h"

BIN
tests/bench_timeout_heap

Binary file not shown.

BIN
tests/bench_uasync_timeouts

Binary file not shown.

24
tests/logs/bench_timeout_heap.log

@ -0,0 +1,24 @@
=== timeout_heap benchmark ===
Operations: 100 each
Push 100 items:
Total time: 0.002 ms
Average per push: 0.016 us
Heap size after: 100
Cancel 50 items:
Total time: 0.001 ms
Average per cancel: 0.022 us
Heap size: 100 (deleted marked)
Pop 50 items:
Total time: 0.002 ms
Average per pop: 0.047 us
Heap size after: 0
=== Summary ===
Push: 0.002 ms total, 0.016 us/op
Cancel: 0.001 ms total, 0.022 us/op
Pop: 0.002 ms total, 0.047 us/op
Total operations: 250

149
tests/logs/bench_uasync_timeouts.log

@ -0,0 +1,149 @@
=================================================
uasync timeout benchmark: with vs without sockets
=================================================
=== Test 1: Zero timeouts WITHOUT sockets ===
Set 100 zero timeouts: 0.008 ms (0.076 us/op)
Mainloop 100 iterations: 0.021 ms (0.205 us/iter)
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a83c47852b0
Timer Statistics: allocated=100, freed=100, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
=== Test 2: Zero timeouts WITH 100 sockets ===
Created 100 sockets
Set 100 zero timeouts: 0.004 ms (0.043 us/op)
Mainloop 100 iterations: 0.020 ms (0.197 us/iter)
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a83c4785360
Timer Statistics: allocated=100, freed=100, active=0
Socket Statistics: allocated=100, freed=0, active=100
Active timers in heap: 0
Socket array capacity: 128, active: 100
Socket: fd=6, active=1
Socket: fd=7, active=1
Socket: fd=8, active=1
Socket: fd=9, active=1
Socket: fd=10, active=1
Socket: fd=11, active=1
Socket: fd=12, active=1
Socket: fd=13, active=1
Socket: fd=14, active=1
Socket: fd=15, active=1
Socket: fd=16, active=1
Socket: fd=17, active=1
Socket: fd=18, active=1
Socket: fd=19, active=1
Socket: fd=20, active=1
Socket: fd=21, active=1
Socket: fd=22, active=1
Socket: fd=23, active=1
Socket: fd=24, active=1
Socket: fd=25, active=1
Socket: fd=26, active=1
Socket: fd=27, active=1
Socket: fd=28, active=1
Socket: fd=29, active=1
Socket: fd=30, active=1
Socket: fd=31, active=1
Socket: fd=32, active=1
Socket: fd=33, active=1
Socket: fd=34, active=1
Socket: fd=35, active=1
Socket: fd=36, active=1
Socket: fd=37, active=1
Socket: fd=38, active=1
Socket: fd=39, active=1
Socket: fd=40, active=1
Socket: fd=41, active=1
Socket: fd=42, active=1
Socket: fd=43, active=1
Socket: fd=44, active=1
Socket: fd=45, active=1
Socket: fd=46, active=1
Socket: fd=47, active=1
Socket: fd=48, active=1
Socket: fd=49, active=1
Socket: fd=50, active=1
Socket: fd=51, active=1
Socket: fd=52, active=1
Socket: fd=53, active=1
Socket: fd=54, active=1
Socket: fd=55, active=1
Socket: fd=56, active=1
Socket: fd=57, active=1
Socket: fd=58, active=1
Socket: fd=59, active=1
Socket: fd=60, active=1
Socket: fd=61, active=1
Socket: fd=62, active=1
Socket: fd=63, active=1
Socket: fd=64, active=1
Socket: fd=65, active=1
Socket: fd=66, active=1
Socket: fd=67, active=1
Socket: fd=68, active=1
Socket: fd=69, active=1
Socket: fd=70, active=1
Socket: fd=71, active=1
Socket: fd=72, active=1
Socket: fd=73, active=1
Socket: fd=74, active=1
Socket: fd=75, active=1
Socket: fd=76, active=1
Socket: fd=77, active=1
Socket: fd=78, active=1
Socket: fd=79, active=1
Socket: fd=80, active=1
Socket: fd=81, active=1
Socket: fd=82, active=1
Socket: fd=83, active=1
Socket: fd=84, active=1
Socket: fd=85, active=1
Socket: fd=86, active=1
Socket: fd=87, active=1
Socket: fd=88, active=1
Socket: fd=89, active=1
Socket: fd=90, active=1
Socket: fd=91, active=1
Socket: fd=92, active=1
Socket: fd=93, active=1
Socket: fd=94, active=1
Socket: fd=95, active=1
Socket: fd=96, active=1
Socket: fd=97, active=1
Socket: fd=98, active=1
Socket: fd=99, active=1
Socket: fd=100, active=1
Socket: fd=101, active=1
Socket: fd=102, active=1
Socket: fd=103, active=1
Socket: fd=104, active=1
Socket: fd=105, active=1
Total active sockets: 100
🔚 BEFORE_DESTROY: End of resource report
=================================================
COMPARISON
=================================================
Set 100 timeouts:
Without sockets: 0.008 ms (0.076 us/op)
With 100 sockets: 0.004 ms (0.043 us/op)
Difference: -43.31%
Mainloop 100 iterations:
Without sockets: 0.021 ms (0.205 us/iter)
With 100 sockets: 0.020 ms (0.197 us/iter)
Difference: -4.00%
=================================================

226
tests/logs/test_bgp_route_exchange.log

@ -0,0 +1,226 @@
=== BGP Route Exchange Test ===
[03:05:50-854.046] [INFO] [8] (test_bgp_route_exchange.c:321) main() Creating server instance...
[CONFIG DEBUG] Opening config file: /tmp/utun_bgp_test_BzwJMx/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_bgp_test_BzwJMx/server.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-854.164] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:05:50-854.169] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:05:50-854.174] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.11.168.192/24 (LOCAL)
[03:05:50-854.178] [INFO] [512] (utun_instance.c:110) utun_instance_create() Added local route: 192.168.11.0/24
[03:05:50-854.181] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.10.168.192/24 (LOCAL)
[03:05:50-854.185] [INFO] [512] (utun_instance.c:110) utun_instance_create() Added local route: 192.168.10.0/24
[03:05:50-854.188] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:05:50-854.192] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:05:50-854.195] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
DEBUG: utun_instance_init() calling init_connections() for instance 0x5a72b6bb9cd0
[03:05:50-854.218] [INFO] [8] (etcp_connections.c:340) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:05:50-854.224] [INFO] [8] (etcp_connections.c:364) etcp_socket_add() [ETCP] Socket 0x5a72b6bbb530 registered and active
DEBUG: init_connections() returned: 0
DEBUG: Connections initialized successfully, count=0
[03:05:50-854.230] [INFO] [8] (test_bgp_route_exchange.c:335) main() Server instance ready (node_id=1111111111111111, bgp=0x5a72b6bb9c90)
[03:05:50-854.234] [INFO] [8] (test_bgp_route_exchange.c:339) main() Creating client instance...
[CONFIG DEBUG] Opening config file: /tmp/utun_bgp_test_BzwJMx/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_bgp_test_BzwJMx/client.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-854.390] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:05:50-854.400] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:05:50-854.404] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.21.168.192/24 (LOCAL)
[03:05:50-854.408] [INFO] [512] (utun_instance.c:110) utun_instance_create() Added local route: 192.168.21.0/24
[03:05:50-854.411] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.20.168.192/24 (LOCAL)
[03:05:50-854.415] [INFO] [512] (utun_instance.c:110) utun_instance_create() Added local route: 192.168.20.0/24
[03:05:50-854.418] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:05:50-854.421] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:05:50-854.424] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
DEBUG: utun_instance_init() calling init_connections() for instance 0x5a72b6bbe4f0
[03:05:50-854.437] [INFO] [8] (etcp_connections.c:340) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:05:50-854.447] [INFO] [8] (etcp_connections.c:364) etcp_socket_add() [ETCP] Socket 0x5a72b6bbf8a0 registered and active
[03:05:50-854.854] [INFO] [8] (etcp_connections.c:88) etcp_link_send_init() [ETCP] INIT sending to 127.0.0.1:39011, link=0x5a72b6bd78f0
[03:05:50-854.860] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-855.654] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
DEBUG: init_connections() returned: 0
DEBUG: Connections initialized successfully, count=1
[03:05:50-855.761] [INFO] [8] (test_bgp_route_exchange.c:353) main() Client instance ready (node_id=2222222222222222, bgp=0x5a72b6bbc060)
[03:05:50-855.766] [INFO] [8] (test_bgp_route_exchange.c:357) main() Waiting for server initialization...
[03:05:50-855.854] [INFO] [8] (etcp_connections.c:669) etcp_connections_read_callback_socket() [ETCP DEBUG] Send INIT RESPONSE
[03:05:50-855.859] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-855.866] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-855.876] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x5a72b6c06520 now ready, notifying ETCP_CONN
[03:05:50-855.881] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x5a72b6c072a0 to senders_list
[03:05:50-855.885] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (2 routes) to connection
[03:05:50-855.894] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-855.899] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-855.903] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x5a72b6bd78f0 now ready, notifying ETCP_CONN
[03:05:50-855.906] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x5a72b6bc0040 to senders_list
[03:05:50-855.910] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (2 routes) to connection
[03:05:50-857.281] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-857.329] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-857.354] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-857.361] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-857.373] [INFO] [4096] (route_bgp.c:67) route_bgp_receive_cbk() Received BGP packet: subcmd=1, network=000ba8c0/24, node_id=1111111111111111
[03:05:50-857.378] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.11.168.192/24 (LEARNED)
[03:05:50-857.382] [INFO] [4096] (route_bgp.c:101) route_bgp_receive_cbk() Added learned route: 000ba8c0/24 via node 1111111111111111 (hops=1)
[03:05:50-857.386] [INFO] [4096] (route_bgp.c:67) route_bgp_receive_cbk() Received BGP packet: subcmd=1, network=000aa8c0/24, node_id=1111111111111111
[03:05:50-857.389] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.10.168.192/24 (LEARNED)
[03:05:50-857.393] [INFO] [4096] (route_bgp.c:101) route_bgp_receive_cbk() Added learned route: 000aa8c0/24 via node 1111111111111111 (hops=1)
[03:05:50-857.397] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-857.402] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-857.413] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-857.418] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-857.422] [INFO] [4096] (route_bgp.c:67) route_bgp_receive_cbk() Received BGP packet: subcmd=1, network=0015a8c0/24, node_id=2222222222222222
[03:05:50-857.426] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.21.168.192/24 (LEARNED)
[03:05:50-857.430] [INFO] [4096] (route_bgp.c:101) route_bgp_receive_cbk() Added learned route: 0015a8c0/24 via node 2222222222222222 (hops=1)
[03:05:50-857.440] [INFO] [4096] (route_bgp.c:67) route_bgp_receive_cbk() Received BGP packet: subcmd=1, network=0014a8c0/24, node_id=2222222222222222
[03:05:50-857.444] [INFO] [512] (route_lib.c:379) route_table_insert() Route inserted: 0.20.168.192/24 (LEARNED)
[03:05:50-857.447] [INFO] [4096] (route_bgp.c:101) route_bgp_receive_cbk() Added learned route: 0014a8c0/24 via node 2222222222222222 (hops=1)
[03:05:50-859.571] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-859.588] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-859.603] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-859.609] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-914.496] [INFO] [8] (test_bgp_route_exchange.c:363) main() Starting connection monitoring...
[03:05:50-914.578] [INFO] [8] (test_bgp_route_exchange.c:368) main() Running event loop...
[03:05:50-924.649] [INFO] [8] (test_bgp_route_exchange.c:245) monitor_connections() === Connection established! Waiting for BGP exchange... ===
[03:05:50-944.759] [INFO] [512] (test_bgp_route_exchange.c:255) monitor_connections() === Checking BGP route exchange ===
[03:05:50-944.814] [INFO] [512] (test_bgp_route_exchange.c:199) verify_bgp_exchange()
=== Verifying BGP Route Exchange ===
[03:05:50-944.819] [INFO] [512] (test_bgp_route_exchange.c:150) print_routing_table()
=== SERVER Routing Table (4 routes) ===
[03:05:50-944.824] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 1: 0.11.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.828] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 2: 0.10.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.832] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 3: 0.21.168.192/24 [LEARNED] node_id=2222222222222222 hops=1
[03:05:50-944.835] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 4: 0.20.168.192/24 [LEARNED] node_id=2222222222222222 hops=1
[03:05:50-944.838] [INFO] [512] (test_bgp_route_exchange.c:172) print_routing_table() =====================================
[03:05:50-944.841] [INFO] [512] (test_bgp_route_exchange.c:150) print_routing_table()
=== CLIENT Routing Table (4 routes) ===
[03:05:50-944.845] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 1: 0.21.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.848] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 2: 0.20.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.851] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 3: 0.11.168.192/24 [LEARNED] node_id=1111111111111111 hops=1
[03:05:50-944.855] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 4: 0.10.168.192/24 [LEARNED] node_id=1111111111111111 hops=1
[03:05:50-944.858] [INFO] [512] (test_bgp_route_exchange.c:172) print_routing_table() =====================================
[03:05:50-944.861] [INFO] [512] (test_bgp_route_exchange.c:206) verify_bgp_exchange() Checking server learned client's routes...
[03:05:50-944.864] [INFO] [512] (test_bgp_route_exchange.c:212) verify_bgp_exchange() PASS: Server has learned route 192.168.20.0/24
[03:05:50-944.867] [INFO] [512] (test_bgp_route_exchange.c:219) verify_bgp_exchange() PASS: Server has learned route 192.168.21.0/24
[03:05:50-944.870] [INFO] [512] (test_bgp_route_exchange.c:225) verify_bgp_exchange() Checking client learned server's routes (disabled - server->client not implemented)...
[03:05:50-944.873] [INFO] [512] (test_bgp_route_exchange.c:260) monitor_connections() === BGP ROUTE EXCHANGE SUCCESS ===
[03:05:50-944.876] [INFO] [8] (test_bgp_route_exchange.c:375) main()
Cleaning up...
[03:05:50-944.880] [INFO] [512] (test_bgp_route_exchange.c:150) print_routing_table()
=== SERVER (final) Routing Table (4 routes) ===
[03:05:50-944.900] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 1: 0.11.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.903] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 2: 0.10.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.907] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 3: 0.21.168.192/24 [LEARNED] node_id=2222222222222222 hops=1
[03:05:50-944.910] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 4: 0.20.168.192/24 [LEARNED] node_id=2222222222222222 hops=1
[03:05:50-944.913] [INFO] [512] (test_bgp_route_exchange.c:172) print_routing_table() =====================================
[03:05:50-944.916] [INFO] [512] (test_bgp_route_exchange.c:150) print_routing_table()
=== CLIENT (final) Routing Table (4 routes) ===
[03:05:50-944.919] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 1: 0.21.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.922] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 2: 0.20.168.192/24 [LOCAL] node_id=0000000000000000 hops=0
[03:05:50-944.926] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 3: 0.11.168.192/24 [LEARNED] node_id=1111111111111111 hops=1
[03:05:50-944.929] [INFO] [512] (test_bgp_route_exchange.c:167) print_routing_table() Route 4: 0.10.168.192/24 [LEARNED] node_id=1111111111111111 hops=1
[03:05:50-944.932] [INFO] [512] (test_bgp_route_exchange.c:172) print_routing_table() =====================================
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x5a72b6bb9cd0
Node ID: 1229782938247303441
UA instance: 0x5a72b6bb9490
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x5a72b6c072a0
ETCP Sockets list: 0x5a72b6bbb530
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-944.940] [INFO] [8] (etcp_connections.c:373) etcp_socket_remove() [ETCP] Removing socket 0x5a72b6bbb530, socket_id=0x5a72b6bb9540
[03:05:50-944.943] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x5a72b6bb9cd0, ua=0x5a72b6bb9490
[03:05:50-944.953] [INFO] [8] (etcp_connections.c:380) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:05:50-944.973] [INFO] [8] (etcp_connections.c:385) etcp_socket_remove() [ETCP] Closed socket
[03:05:50-944.978] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x5a72b6c072a0 from senders_list
[03:05:50-944.981] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x5a72b6c072a0 to all peers
[03:05:50-944.986] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x5a72b6c072a0 removed from senders_list
[03:05:50-944.989] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 2 routes for connection 0x5a72b6c072a0
[03:05:50-944.996] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:05:50-945.000] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:05:50-945.003] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x5a72b6bbe4f0
Node ID: 2459565876494606882
UA instance: 0x5a72b6bb9490
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x5a72b6bc0040
ETCP Sockets list: 0x5a72b6bbf8a0
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-945.009] [INFO] [8] (etcp_connections.c:373) etcp_socket_remove() [ETCP] Removing socket 0x5a72b6bbf8a0, socket_id=0x5a72b6bb9588
[03:05:50-945.016] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x5a72b6bbe4f0, ua=0x5a72b6bb9490
[03:05:50-945.020] [INFO] [8] (etcp_connections.c:380) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:05:50-945.028] [INFO] [8] (etcp_connections.c:385) etcp_socket_remove() [ETCP] Closed socket
[03:05:50-945.031] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x5a72b6bc0040 from senders_list
[03:05:50-945.034] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x5a72b6bc0040 to all peers
[03:05:50-945.038] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x5a72b6bc0040 removed from senders_list
[03:05:50-945.041] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 2 routes for connection 0x5a72b6bc0040
[03:05:50-945.047] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:05:50-945.050] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:05:50-945.053] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a72b6bb9490
Timer Statistics: allocated=12, freed=9, active=3
Socket Statistics: allocated=2, freed=2, active=0
Timer: node=0x5a72b6c06040, expires=1771113950958 ms, cancelled=0
Timer: node=0x5a72b6c06100, expires=1771113950958 ms, cancelled=0
Active timers in heap: 2
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
=== TEST PASSED ===
BGP route exchange working (client -> server direction)

16
tests/logs/test_config_debug.log

@ -0,0 +1,16 @@
[03:05:50-837.191] [ERROR] [128] (test_config_debug.c:77) main() 1. До загрузки конфигурации:
[03:05:50-837.212] [ERROR] [128] (test_config_debug.c:78) main() ERROR сообщение до загрузки конфигурации
[03:05:50-837.217] [ERROR] [128] (test_config_debug.c:82) main() 2. Загрузка конфигурации из файла: /tmp/utun_test_ve46Ka/test.conf
[CONFIG DEBUG] Opening config file: /tmp/utun_test_ve46Ka/test.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-837.245] [ERROR] [128] (test_config_debug.c:90) main() ✅ Конфигурация загружена успешно
[03:05:50-837.249] [ERROR] [128] (test_config_debug.c:91) main() Log file: /tmp/utun_debug.log
[03:05:50-837.252] [ERROR] [128] (test_config_debug.c:92) main() Debug level: debug
[03:05:50-837.255] [ERROR] [128] (test_config_debug.c:93) main() Debug categories: 0x2A
[03:05:50-837.267] [ERROR] [128] (test_config_debug.c:94) main() Enable timestamp: 1
[03:05:50-837.270] [ERROR] [128] (test_config_debug.c:95) main() Enable colors: 1
[03:05:50-837.273] [ERROR] [128] (test_config_debug.c:98) main() 4. Тестирование после применения настроек:
[03:05:50-837.277] [ERROR] [8] (test_config_debug.c:99) main() ERROR от ETCP (должен выводиться)
[03:05:50-837.280] [ERROR] [128] (test_config_debug.c:108) main() 5. Проверка вывода в файл:
[03:05:50-837.347] [ERROR] [128] (test_config_debug.c:117) main() === Тест завершен ===
[03:05:50-837.354] [ERROR] [128] (test_config_debug.c:118) main() Проверьте файл /tmp/utun_debug.log для записанных сообщений

6
tests/logs/test_crypto.log

@ -0,0 +1,6 @@
[03:05:50-314.146] [INFO] [16] (test_crypto.c:16) main() === Basic Crypto Test ===
[03:05:50-314.202] [INFO] [16] (test_crypto.c:27) main() AES key setup successful
[03:05:50-314.209] [INFO] [16] (test_crypto.c:38) main() CCM config successful
[03:05:50-314.218] [INFO] [16] (test_crypto.c:50) main() Encryption successful
[03:05:50-314.224] [INFO] [16] (test_crypto.c:58) main() Decryption successful
[03:05:50-314.228] [INFO] [16] (test_crypto.c:61) main() Crypto test PASSED

8
tests/logs/test_debug_categories.log

@ -0,0 +1,8 @@
[03:05:50-836.314] [INFO] [18446744073709551615] (test_debug_categories.c:87) main() === Тестовые сообщения ===
[03:05:50-836.358] [INFO] [8] (test_debug_categories.c:90) main() Сообщение от ETCP категории
[03:05:50-836.363] [INFO] [2] (test_debug_categories.c:91) main() Сообщение от LL_QUEUE категории
[03:05:50-836.367] [INFO] [32] (test_debug_categories.c:92) main() Сообщение от MEMORY категории
[03:05:50-836.370] [INFO] [4] (test_debug_categories.c:93) main() Сообщение от CONNECTION категории
[03:05:50-836.373] [INFO] [16] (test_debug_categories.c:94) main() Сообщение от CRYPTO категории
[03:05:50-836.376] [INFO] [18446744073709551615] (test_debug_categories.c:96) main() === Информация о текущих настройках ===
[03:05:50-836.379] [INFO] [18446744073709551615] (test_debug_categories.c:107) main() Активные категории: NONE

19
tests/logs/test_ecc_encrypt.log

@ -0,0 +1,19 @@
[03:05:50-802.156] [INFO] [16] (test_ecc_encrypt.c:182) main() Performing client-server key exchange and encryption test:
[03:05:50-802.217] [INFO] [16] (test_ecc_encrypt.c:90) test_key_exchange_and_encrypt() Generating client key pair...
[03:05:50-803.153] [INFO] [16] (test_ecc_encrypt.c:96) test_key_exchange_and_encrypt() Generating server key pair...
[03:05:50-803.840] [INFO] [16] (test_ecc_encrypt.c:103) test_key_exchange_and_encrypt() Computing shared secret on client side...
[03:05:50-804.554] [INFO] [16] (test_ecc_encrypt.c:110) test_key_exchange_and_encrypt() Computing shared secret on server side...
[03:05:50-805.204] [INFO] [16] (test_ecc_encrypt.c:123) test_key_exchange_and_encrypt() Shared secrets match.
[03:05:50-805.208] [INFO] [16] (test_ecc_encrypt.c:145) test_key_exchange_and_encrypt() Encrypting plaintext...
[03:05:50-805.213] [INFO] [16] (test_ecc_encrypt.c:155) test_key_exchange_and_encrypt() Decrypting ciphertext...
[03:05:50-805.218] [INFO] [16] (test_ecc_encrypt.c:169) test_key_exchange_and_encrypt() Decryption successful. Test passed.
[03:05:50-805.221] [INFO] [16] (test_ecc_encrypt.c:189) main() Result: PASS
[03:05:50-805.224] [INFO] [16] (test_ecc_encrypt.c:190) main() Test SUCCESSFUL

3385
tests/logs/test_etcp_100_packets.log

File diff suppressed because it is too large Load Diff

171
tests/logs/test_etcp_api.log

@ -0,0 +1,171 @@
=== ETCP API Test (etcp_send, etcp_bind) ===
Testing with 100 packets of random sizes (10-500 bytes)
Total data to transfer: 26572 bytes (0.26 KB average per packet)
Creating server...
[CONFIG DEBUG] Opening config file: /tmp/utun_test_zn3Iwx/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_zn3Iwx/server.conf
[CONFIG DEBUG] Successfully opened config file
Server created, waiting for connection...
Creating client...
[CONFIG DEBUG] Opening config file: /tmp/utun_test_zn3Iwx/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_zn3Iwx/client.conf
[CONFIG DEBUG] Successfully opened config file
Client created
[03:05:50-624.456] [WARN] [1] (etcp_api.c:34) etcp_bind() etcp_bind: ID 0 already bound, overwriting
[03:05:50-624.501] [WARN] [1] (etcp_api.c:34) etcp_bind() etcp_bind: ID 0 already bound, overwriting
Callbacks registered for ID=0 (server=0x5ffed6475900, client=0x5ffed6475790)
Sending 100 packets in each direction via etcp_send...
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connection check: client=1, server=1
Connections ready: client=0x5ffedf9e5290, server=0x5ffedfa2a270
Starting forward transfer (client -> server) via etcp_send...
Starting backward transfer (server -> client) via etcp_send...
Backward transfer completed: 100/100 packets in 7.83 ms
=== SUCCESS: Bidirectional transfer via etcp_api completed! ===
Forward (client->server): 100/100 packets in -24869699.91 ms
Backward (server->client): 100/100 packets in 7.83 ms
Total time: 14.68 ms
Cleaning up...
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x5ffedf9dcc90
Node ID: 1229782938247303441
UA instance: 0x5ffedf9dc490
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x5ffedfa2a270
ETCP Sockets list: 0x5ffedf9de330
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-797.892] [WARN] [1] (etcp_api.c:56) etcp_unbind() etcp_unbind: ID 0 not bound
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x5ffedf9e1420
Node ID: 2459565876494606882
UA instance: 0x5ffedf9dc490
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x5ffedf9e5290
ETCP Sockets list: 0x5ffedf9e27d0
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-797.941] [WARN] [1] (etcp_api.c:56) etcp_unbind() etcp_unbind: ID 0 not bound
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5ffedf9dc490
Timer Statistics: allocated=281, freed=274, active=7
Socket Statistics: allocated=2, freed=2, active=0
Timer: node=0x5ffedfa2a150, expires=1771113950884 ms, cancelled=0
Timer: node=0x5ffedfa36810, expires=1771113950887 ms, cancelled=0
Timer: node=0x5ffedfa39d20, expires=1771113950891 ms, cancelled=0
Timer: node=0x5ffedfa2a240, expires=1771113950896 ms, cancelled=0
Timer: node=0x5ffedfa36ff0, expires=1771113950889 ms, cancelled=0
Timer: node=0x5ffedfa327f0, expires=1771113950894 ms, cancelled=0
Active timers in heap: 6
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-797.949] [ERROR] [32] (u_async.c:1007) uasync_destroy() Memory leaks detected before cleanup: timers 281/274, sockets 2/2
[03:05:50-797.953] [ERROR] [1024] (u_async.c:1009) uasync_destroy() Timer leak: allocated=281, freed=274, diff=7
[03:05:50-797.956] [ERROR] [1024] (u_async.c:1012) uasync_destroy() Socket leak: allocated=2, freed=2, diff=0
=== TEST PASSED ===
All 100 packets transmitted in each direction via etcp_api

6
tests/logs/test_etcp_crypto.log

@ -0,0 +1,6 @@
[03:05:50-311.973] [INFO] [16] (test_etcp_crypto.c:17) main() === ETCP Crypto Test ===
[03:05:50-312.252] [ERROR] [16] (secure_channel.c:211) sc_set_peer_public_key() sc_set_peer_public_key: invalid key
[03:05:50-312.271] [ERROR] [16] (secure_channel.c:211) sc_set_peer_public_key() sc_set_peer_public_key: invalid key
[03:05:50-312.275] [INFO] [16] (test_etcp_crypto.c:54) main() Crypto contexts initialized
[03:05:50-313.172] [INFO] [16] (test_etcp_crypto.c:77) main() Client->Server encryption/decryption: PASSED
[03:05:50-313.182] [INFO] [16] (test_etcp_crypto.c:78) main() ETCP crypto test PASSED

46
tests/logs/test_etcp_minimal.log

@ -0,0 +1,46 @@
=== Minimal ETCP Traffic Flow Debugging ===
=== Testing Basic Packet Analysis ===
Test packet: 00 00 06 00 01 48 65 6C 6C 6F
Section type: 0x00
Section length: 6
Total packet size: 10
This is a PAYLOAD section
Packet ID: 1
Payload size: 4 bytes
Payload data: 48 65 6C 6C
Payload as text: Hell
=== Testing Multi-Section Packet ===
Multi-section packet: 06 00 02 12 34 01 00 09 02 00 01 56 78 00 02 56 79 00 00 08 00 03 48 65 6C 6C 6F 21
Section 0 at position 0:
Type: 0x06 (TIMESTAMP)
Length: 2 bytes
Timestamp: 4660
Section 1 at position 5:
Type: 0x01 (ACK)
Length: 9 bytes
ACK count: 2
ACK[0]: id=1, ts=22136
ACK[1]: id=2, ts=22137
Section 2 at position 17:
Type: 0x00 (PAYLOAD)
Length: 8 bytes
Packet ID: 3
Payload: Hello!
Total sections parsed: 3
=== Testing Connection Establishment Packets ===
INIT_REQUEST packet:
Node ID: 0x2222222222222222
MTU: 1500
Keepalive: 100
INIT_RESPONSE packet:
Node ID: 0x1111111111111111
MTU: 1500
=== Test completed ===

548
tests/logs/test_etcp_simple_traffic.log

@ -0,0 +1,548 @@
=== ETCP Simple Traffic Test (Queue-based) ===
[03:05:50-380.206] [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
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
[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] 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 0x60fa30cb74e0
[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 0x60fa30cb8830, 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 0x60fa30cb74e0
[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
ℹ️ 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 0x60fa30cb84d0 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=0x60fa30cb7db0, 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=0x60fa30cb84d0, 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] 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] 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 0x60fa30cbb490
[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 0x60fa30cbca20, 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 0x60fa30cbb490
[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
ℹ️ 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 0x60fa30cbc840 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=0x60fa30cbc640, connections_count=0
[03:05:50-380.617] [INFO] [4] (etcp_connections.c:846) init_connections() Client test_client - keepalive=1, links=0x60fa30cbc7a0, 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 0x60fa30cb7330, hash_size=0
[03:05:50-380.627] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cb8a80, hash_size=0
[03:05:50-380.634] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cbf300, hash_size=1024
[03:05:50-380.641] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc13a0, hash_size=1024
[03:05:50-380.648] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc3440, hash_size=1024
[03:05:50-380.651] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc54e0, hash_size=0
[03:05:50-380.655] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[6882→????] init 0x60fa30cb8eb0, mtu=1500
[03:05:50-380.658] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc5570, hash_size=0
[03:05:50-380.662] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x60fa30cc5600, 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=0x60fa30cb8eb0 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=0x60fa30cd4780, 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=0x60fa30cd4780
[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=0x60fa30cbc840
[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 0x60fa30cb8eb0 to instance, total count: 1
[03:05:50-382.524] [INFO] [4] (etcp_connections.c:1018) init_connections() Initialized 1 connections
init_connections() returned: 0
Client connections initialized: sockets=0x60fa30cbc840, connections=0x60fa30cb8eb0, count=1
✅ Client instance initialized successfully (node_id=2222222222222222)
Client instance ready (node_id=2222222222222222)
=== Connection Debug ===
Client connection 0x60fa30cb8eb0: peer_node_id=1
Link 0x60fa30cd4780: 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
[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 0x60fa30cb74e0
[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 0x60fa30d042b0
[03:05:50-432.265] [DEBUG] [8] (test_etcp_simple_traffic.c:129) is_connection_established() is_connection_established: Checking connection 0x60fa30d042b0
[DEBUG] is_connection_established: Link 0x60fa30d035d0 - 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 0x60fa30d035d0 - 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 0x60fa30cbb490
[03:05:50-432.295] [TRACE] [8] (test_etcp_simple_traffic.c:114) is_connection_established() is_connection_established: Checking instance 0x60fa30cbb490
[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 0x60fa30cb8eb0
[03:05:50-432.308] [DEBUG] [8] (test_etcp_simple_traffic.c:129) is_connection_established() is_connection_established: Checking connection 0x60fa30cb8eb0
[DEBUG] is_connection_established: Link 0x60fa30cd4780 - 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 0x60fa30cd4780 - 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!
[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)
[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 0x60fa30cb8eb0
[03:05:50-432.338] [DEBUG] [8] (test_etcp_simple_traffic.c:171) send_test_packet() send_test_packet: Found connection 0x60fa30cb8eb0
[DEBUG] send_test_packet: connection input_queue=0x60fa30cb7330
[03:05:50-432.343] [DEBUG] [8] (test_etcp_simple_traffic.c:174) send_test_packet() send_test_packet: connection input_queue=0x60fa30cb7330
[DEBUG] send_test_packet: connection output_queue=0x60fa30cb8a80
[03:05:50-432.348] [DEBUG] [8] (test_etcp_simple_traffic.c:177) send_test_packet() send_test_packet: connection output_queue=0x60fa30cb8a80
[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
[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.367] [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 0x60fa30d0ac20 (len=100)
[03:05:50-432.385] [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.394] [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.406] [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.418] [TRACE] [8] (etcp.c:464) ack_timeout_check()
[03:05:50-432.422] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.426] [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.507] [TRACE] [8] (etcp_loadbalancer.c:115) etcp_loadbalancer_send() [6882→3441] unlimited bandwidth, skipping shaper update
[03:05:50-432.512] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-432.516] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.520] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-432.524] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=100, input_len=0
[03:05:50-432.528] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-432.532] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-432.536] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-432.540] [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
[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
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 0x60fa30d042b0
[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.208] [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
[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 0x60fa30cb74e0
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x60fa30cb74e0
Node ID: 1229782938247303441
UA instance: 0x60fa30cb64d0
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x60fa30d042b0
ETCP Sockets list: 0x60fa30cb84d0
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ 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 0x60fa30cb84d0, 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=0x60fa30cb6580
[03:05:50-438.248] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x60fa30cb74e0, ua=0x60fa30cb64d0
[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.318] [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 0x60fa30d042b0
[03:05:50-438.330] [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 0x60fa30d042b0 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 0x60fa30d042b0 to all peers
[03:05:50-438.349] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x60fa30d042b0 removed from senders_list
[03:05:50-438.353] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x60fa30d042b0
[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 0x60fa30d03950, head=(nil), tail=(nil), count=0
[03:05:50-438.366] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d039e0, head=(nil), tail=(nil), count=0
[03:05:50-438.371] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d04420, head=(nil), tail=(nil), count=0
[03:05:50-438.375] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d044b0, head=(nil), tail=(nil), count=0
[03:05:50-438.379] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d04540, head=(nil), tail=(nil), count=0
[03:05:50-438.383] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d03160, head=(nil), tail=(nil), count=0
[03:05:50-438.387] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d02ea0, head=(nil), tail=(nil), count=0
[03:05:50-438.391] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30d032d0, 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 0x60fa30cb74e0
[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 0x60fa30cb74e0
[03:05:50-438.417] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cb8830, 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.424] [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 0x60fa30cbb490
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x60fa30cbb490
Node ID: 2459565876494606882
UA instance: 0x60fa30cb64d0
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x60fa30cb8eb0
ETCP Sockets list: 0x60fa30cbc840
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ 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 0x60fa30cbc840, 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=0x60fa30cb65c8
[03:05:50-438.475] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x60fa30cbb490, ua=0x60fa30cb64d0
[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 0x60fa30cb8eb0
[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 0x60fa30cb8eb0 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 0x60fa30cb8eb0 to all peers
[03:05:50-438.528] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x60fa30cb8eb0 removed from senders_list
[03:05:50-438.532] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x60fa30cb8eb0
[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 0x60fa30cc5570, head=(nil), tail=(nil), count=0
[03:05:50-438.544] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc5600, head=(nil), tail=(nil), count=0
[03:05:50-438.548] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cb7330, head=(nil), tail=(nil), count=0
[03:05:50-438.552] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cb8a80, head=(nil), tail=(nil), count=0
[03:05:50-438.556] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cbf300, head=(nil), tail=(nil), count=0
[03:05:50-438.560] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc13a0, head=(nil), tail=(nil), count=0
[03:05:50-438.565] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc54e0, head=(nil), tail=(nil), count=0
[03:05:50-438.569] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cc3440, 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 0x60fa30cbb490
[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 0x60fa30cbb490
[03:05:50-438.597] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x60fa30cbca20, 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=0x60fa30cb64d0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x60fa30cb64d0
Timer Statistics: allocated=6, freed=3, active=3
Socket Statistics: allocated=2, freed=2, active=0
Timer: node=0x60fa30d04220, expires=1771113950533 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=0x60fa30cb64d0
[03:05:50-438.670] [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
✅ ETCP connection and queue mechanisms verified

528
tests/logs/test_etcp_two_instances.log

@ -0,0 +1,528 @@
[03:05:50-315.460] [INFO] [8] (test_etcp_two_instances.c:253) main() === ETCP Two-Instance Connection Test ===
[03:05:50-315.481] [INFO] [256] (utun_instance.c:34) utun_instance_set_tun_init_enabled() TUN initialization disabled
[03:05:50-315.486] [INFO] [8] (test_etcp_two_instances.c:259) main() Creating server instance...
[03:05:50-315.490] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-315.502] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[CONFIG DEBUG] Opening config file: /tmp/utun_test_al45hN/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_al45hN/server.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-315.542] [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-315.593] [INFO] [16] (secure_channel.c:188) sc_init_local_keys() sc_init_local_keys: keys initialized successfully
[03:05:50-315.603] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 0 to callback 0x57c7c6255110 for instance 0x57c7fa35f4e0
[03:05:50-315.608] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:05:50-315.611] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:05:50-315.615] [INFO] [256] (utun_instance.c:133) utun_instance_create() TUN initialization disabled - skipping TUN device setup
[03:05:50-315.618] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa360830, hash_size=0
[03:05:50-315.622] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 1 to callback 0x57c7c62541c0 for instance 0x57c7fa35f4e0
[03:05:50-315.625] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:05:50-315.629] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:05:50-315.632] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
[03:05:50-315.635] [TRACE] [4] (etcp_connections.c:807) init_connections()
[03:05:50-315.639] [TRACE] [4] (etcp_connections.c:269) etcp_socket_add()
[03:05:50-315.650] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 6
[03:05:50-315.663] [INFO] [8] (etcp_connections.c:340) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:05:50-315.668] [INFO] [4] (etcp_connections.c:362) etcp_socket_add() Registered ETCP socket with uasync
[03:05:50-315.672] [INFO] [8] (etcp_connections.c:364) etcp_socket_add() [ETCP] Socket 0x57c7fa3604d0 registered and active
[03:05:50-315.676] [INFO] [4] (etcp_connections.c:835) init_connections() Initialized server test on 127.0.0.1:9011 (links: 0)
[03:05:50-315.679] [DEBUG] [4] (etcp_connections.c:842) init_connections() init_connections called, instance=0x57c7fa35f4e0, config=0x57c7fa35fdb0, clients=(nil), connections_count=0
[03:05:50-315.683] [INFO] [4] (etcp_connections.c:1018) init_connections() Initialized 0 connections
DEBUG: utun_instance_init() calling init_connections() for instance 0x57c7fa35f4e0
[03:05:50-315.688] [TRACE] [4] (etcp_connections.c:807) init_connections()
[03:05:50-315.691] [TRACE] [4] (etcp_connections.c:269) etcp_socket_add()
[03:05:50-315.697] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 7
[03:05:50-315.705] [ERROR] [8] (etcp_connections.c:327) etcp_socket_add() [ETCP] Failed to bind socket to address family 2: Address already in use
[03:05:50-315.709] [ERROR] [8] (etcp_connections.c:333) etcp_socket_add() [ETCP] Failed to bind to 127.0.0.1:9011
[03:05:50-315.718] [ERROR] [8] (etcp_connections.c:818) init_connections() Failed to create socket for server test
[03:05:50-315.726] [DEBUG] [4] (etcp_connections.c:842) init_connections() init_connections called, instance=0x57c7fa35f4e0, config=0x57c7fa35fdb0, clients=(nil), connections_count=0
[03:05:50-315.730] [INFO] [4] (etcp_connections.c:1018) init_connections() Initialized 0 connections
DEBUG: init_connections() returned: 0
DEBUG: Connections initialized successfully, count=0
[03:05:50-315.735] [INFO] [8] (test_etcp_two_instances.c:280) main() Server instance ready (node_id=1111111111111111)
[03:05:50-315.739] [INFO] [8] (test_etcp_two_instances.c:283) main() Creating client instance...
[CONFIG DEBUG] Opening config file: /tmp/utun_test_al45hN/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_al45hN/client.conf
[CONFIG DEBUG] Successfully opened config file
[03:05:50-315.767] [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-315.790] [INFO] [16] (secure_channel.c:188) sc_init_local_keys() sc_init_local_keys: keys initialized successfully
[03:05:50-315.797] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 0 to callback 0x57c7c6255110 for instance 0x57c7fa363560
[03:05:50-315.800] [INFO] [512] (routing.c:272) routing_create() Routing module initialized for instance
[03:05:50-315.804] [INFO] [512] (utun_instance.c:91) utun_instance_create() Routing module created
[03:05:50-315.807] [INFO] [256] (utun_instance.c:133) utun_instance_create() TUN initialization disabled - skipping TUN device setup
[03:05:50-315.810] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa364af0, hash_size=0
[03:05:50-315.813] [INFO] [1] (etcp_api.c:39) etcp_bind() etcp_bind: Bound ID 1 to callback 0x57c7c62541c0 for instance 0x57c7fa363560
[03:05:50-315.817] [INFO] [4096] (route_bgp.c:382) route_bgp_init() Route change callback registered
[03:05:50-315.820] [INFO] [4096] (route_bgp.c:385) route_bgp_init() BGP module initialized
[03:05:50-315.823] [INFO] [4096] (utun_instance.c:143) utun_instance_create() BGP module initialized
[03:05:50-315.826] [TRACE] [4] (etcp_connections.c:807) init_connections()
[03:05:50-315.829] [TRACE] [4] (etcp_connections.c:269) etcp_socket_add()
[03:05:50-315.836] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 7
[03:05:50-315.843] [INFO] [8] (etcp_connections.c:340) etcp_socket_add() [ETCP] Successfully bound socket to local address, family=2
[03:05:50-315.848] [INFO] [4] (etcp_connections.c:362) etcp_socket_add() Registered ETCP socket with uasync
[03:05:50-315.851] [INFO] [8] (etcp_connections.c:364) etcp_socket_add() [ETCP] Socket 0x57c7fa364910 registered and active
[03:05:50-315.855] [INFO] [4] (etcp_connections.c:835) init_connections() Initialized server test on 127.0.0.1:9012 (links: 0)
[03:05:50-315.858] [DEBUG] [4] (etcp_connections.c:842) init_connections() init_connections called, instance=0x57c7fa363560, config=0x57c7fa364230, clients=0x57c7fa364710, connections_count=0
[03:05:50-315.862] [INFO] [4] (etcp_connections.c:846) init_connections() Client test_client - keepalive=1, links=0x57c7fa364870, peer_key_len=128
[03:05:50-315.865] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:05:50-315.869] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa35e320, hash_size=0
[03:05:50-315.872] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa360a80, hash_size=0
[03:05:50-315.882] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3673d0, hash_size=1024
[03:05:50-315.898] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa369470, hash_size=1024
[03:05:50-315.909] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa36b510, hash_size=1024
[03:05:50-315.912] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa36d5b0, hash_size=0
[03:05:50-315.916] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[6882→????] init 0x57c7fa360eb0, mtu=1500
[03:05:50-315.920] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa36d640, hash_size=0
[03:05:50-315.923] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa36d6d0, hash_size=0
[03:05:50-315.926] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:05:50-315.929] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [6882→????] connection initialized. ETCP=0x57c7fa360eb0 mtu=1500, next_tx_id=1
[03:05:50-315.933] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-315.937] [INFO] [16] (etcp_connections.c:873) init_connections() init_connections: setting peer public key for client test_client
[03:05:50-316.327] [INFO] [16] (etcp_connections.c:878) init_connections() init_connections: successfully set peer public key for client test_client
[03:05:50-316.337] [TRACE] [4] (etcp_connections.c:398) etcp_link_new()
[03:05:50-316.341] [TRACE] [4] (etcp_connections.c:234) etcp_find_free_local_link_id()
[03:05:50-316.345] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-316.348] [TRACE] [4] (etcp_connections.c:184) insert_link()
[03:05:50-316.352] [TRACE] [4] (etcp_connections.c:169) realloc_links()
[03:05:50-316.355] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-316.358] [INFO] [4] (etcp_connections.c:438) etcp_link_new() etcp_link_new: client link, calling etcp_link_send_init
[03:05:50-316.361] [TRACE] [4] (etcp_connections.c:42) etcp_link_send_init()
[03:05:50-316.365] [INFO] [4] (etcp_connections.c:43) etcp_link_send_init() etcp_link_send_init link=0x57c7fa37c850, is_server=0
[03:05:50-316.369] [INFO] [4] (etcp_connections.c:81) etcp_link_send_init() Sending INIT request to link, node_id=2459565876494606882, retry=0
[03:05:50-316.373] [INFO] [8] (etcp_connections.c:88) etcp_link_send_init() [ETCP] INIT sending to 127.0.0.1:9011, link=0x57c7fa37c850
[03:05:50-316.376] [TRACE] [4] (etcp_connections.c:471) etcp_encrypt_send()
[03:05:50-316.382] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-316.386] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-316.389] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-317.072] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-317.101] [INFO] [4] (etcp_connections.c:927) init_connections() Created link 0x57c7fa37c850 for client test_client, socket=0x57c7fa364910
[03:05:50-317.105] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-317.109] [INFO] [16] (etcp_connections.c:946) init_connections() init_connections: setting peer public key for client test_client
[03:05:50-317.186] [INFO] [16] (etcp_connections.c:951) init_connections() init_connections: successfully set peer public key for client test_client
[03:05:50-317.190] [INFO] [4] (etcp_connections.c:1007) init_connections() Added connection 0x57c7fa360eb0 to instance, total count: 1
[03:05:50-317.194] [INFO] [4] (etcp_connections.c:1018) init_connections() Initialized 1 connections
DEBUG: utun_instance_init() calling init_connections() for instance 0x57c7fa363560
[03:05:50-317.198] [TRACE] [4] (etcp_connections.c:807) init_connections()
[03:05:50-317.202] [TRACE] [4] (etcp_connections.c:269) etcp_socket_add()
[03:05:50-317.210] [DEBUG] [8192] (socket_compat.c:97) socket_create_udp() Created UDP socket: 8
[03:05:50-317.218] [ERROR] [8] (etcp_connections.c:327) etcp_socket_add() [ETCP] Failed to bind socket to address family 2: Address already in use
[03:05:50-317.221] [ERROR] [8] (etcp_connections.c:333) etcp_socket_add() [ETCP] Failed to bind to 127.0.0.1:9012
[03:05:50-317.228] [ERROR] [8] (etcp_connections.c:818) init_connections() Failed to create socket for server test
[03:05:50-317.236] [DEBUG] [4] (etcp_connections.c:842) init_connections() init_connections called, instance=0x57c7fa363560, config=0x57c7fa364230, clients=0x57c7fa364710, connections_count=1
[03:05:50-317.239] [INFO] [4] (etcp_connections.c:846) init_connections() Client test_client - keepalive=1, links=0x57c7fa364870, peer_key_len=128
[03:05:50-317.243] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:05:50-317.246] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3abe20, hash_size=0
[03:05:50-317.249] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3abeb0, hash_size=0
[03:05:50-317.256] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3abf40, hash_size=1024
[03:05:50-317.263] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3ab150, hash_size=1024
[03:05:50-317.270] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3aadc0, hash_size=1024
[03:05:50-317.274] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3ab4e0, hash_size=0
[03:05:50-317.277] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[6882→????] init 0x57c7fa3abcb0, mtu=1500
[03:05:50-317.281] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3ab710, hash_size=0
[03:05:50-317.300] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3ab300, hash_size=0
[03:05:50-317.309] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:05:50-317.312] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [6882→????] connection initialized. ETCP=0x57c7fa3abcb0 mtu=1500, next_tx_id=1
[03:05:50-317.316] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-317.319] [INFO] [16] (etcp_connections.c:873) init_connections() init_connections: setting peer public key for client test_client
[03:05:50-317.394] [INFO] [16] (etcp_connections.c:878) init_connections() init_connections: successfully set peer public key for client test_client
[03:05:50-317.398] [TRACE] [4] (etcp_connections.c:398) etcp_link_new()
[03:05:50-317.401] [TRACE] [4] (etcp_connections.c:234) etcp_find_free_local_link_id()
[03:05:50-317.405] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-317.408] [TRACE] [4] (etcp_connections.c:184) insert_link()
[03:05:50-317.411] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-317.414] [INFO] [4] (etcp_connections.c:438) etcp_link_new() etcp_link_new: client link, calling etcp_link_send_init
[03:05:50-317.417] [TRACE] [4] (etcp_connections.c:42) etcp_link_send_init()
[03:05:50-317.420] [INFO] [4] (etcp_connections.c:43) etcp_link_send_init() etcp_link_send_init link=0x57c7fa3b2520, is_server=0
[03:05:50-317.424] [INFO] [4] (etcp_connections.c:81) etcp_link_send_init() Sending INIT request to link, node_id=2459565876494606882, retry=0
[03:05:50-317.428] [INFO] [8] (etcp_connections.c:88) etcp_link_send_init() [ETCP] INIT sending to 127.0.0.1:9011, link=0x57c7fa3b2520
[03:05:50-317.431] [TRACE] [4] (etcp_connections.c:471) etcp_encrypt_send()
[03:05:50-317.434] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-317.437] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-317.441] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-317.447] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-317.458] [INFO] [4] (etcp_connections.c:927) init_connections() Created link 0x57c7fa3b2520 for client test_client, socket=0x57c7fa364910
[03:05:50-317.461] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-317.465] [INFO] [16] (etcp_connections.c:946) init_connections() init_connections: setting peer public key for client test_client
[03:05:50-317.532] [INFO] [16] (etcp_connections.c:951) init_connections() init_connections: successfully set peer public key for client test_client
[03:05:50-317.536] [INFO] [4] (etcp_connections.c:1007) init_connections() Added connection 0x57c7fa3abcb0 to instance, total count: 2
[03:05:50-317.539] [INFO] [4] (etcp_connections.c:1018) init_connections() Initialized 2 connections
DEBUG: init_connections() returned: 0
DEBUG: Connections initialized successfully, count=2
[03:05:50-317.548] [INFO] [8] (test_etcp_two_instances.c:306) main() Client instance ready (node_id=2222222222222222)
[03:05:50-317.553] [INFO] [8] (test_etcp_two_instances.c:315) main() [TEST] Client socket bound to port 9012 (expected NAT port)
[03:05:50-317.556] [INFO] [8] (test_etcp_two_instances.c:321) main() Starting connection monitoring...
[03:05:50-317.559] [INFO] [8] (test_etcp_two_instances.c:326) main() Running event loop...
[03:05:50-317.562] [INFO] [8] (test_etcp_two_instances.c:329) main() Waiting 0.5 seconds for server initialization...
[03:05:50-317.566] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-317.570] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-317.576] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-317.580] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-317.583] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-317.652] [TRACE] [8] (etcp.c:70) etcp_connection_create()
[03:05:50-317.656] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3b2e80, hash_size=0
[03:05:50-317.660] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3b2f10, hash_size=0
[03:05:50-317.667] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3b2fa0, hash_size=1024
[03:05:50-317.674] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3ab9f0, hash_size=1024
[03:05:50-317.681] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3b2400, hash_size=1024
[03:05:50-317.684] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3ab390, hash_size=0
[03:05:50-317.688] [DEBUG] [8] (pkt_normalizer.c:35) pn_init() pn_init:[3441→????] init 0x57c7fa3b2d10, mtu=1500
[03:05:50-317.691] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3b2120, hash_size=0
[03:05:50-317.694] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x57c7fa3b21b0, hash_size=0
[03:05:50-317.698] [DEBUG] [512] (routing.c:297) routing_add_conn() routing_add_conn: deprecated, no action taken
[03:05:50-317.701] [DEBUG] [8] (etcp.c:128) etcp_connection_create() [3441→????] connection initialized. ETCP=0x57c7fa3b2d10 mtu=1500, next_tx_id=1
[03:05:50-317.704] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-317.708] [DEBUG] [4] (etcp_connections.c:624) etcp_connections_read_callback_socket() New connection from 127.0.0.1:9012 peer_id=2459565876494606882 etcp=0x57c7fa3b2d10
[03:05:50-317.712] [INFO] [4] (etcp_connections.c:629) etcp_connections_read_callback_socket() Added incoming connection 0x57c7fa3b2d10 to instance, total count: 1
[03:05:50-317.715] [TRACE] [4] (etcp_connections.c:398) etcp_link_new()
[03:05:50-317.719] [TRACE] [4] (etcp_connections.c:234) etcp_find_free_local_link_id()
[03:05:50-317.722] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-317.725] [TRACE] [4] (etcp_connections.c:184) insert_link()
[03:05:50-317.728] [TRACE] [4] (etcp_connections.c:169) realloc_links()
[03:05:50-317.731] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-317.734] [TRACE] [8] (etcp.c:258) etcp_conn_reset()
[03:05:50-317.737] [DEBUG] [4] (etcp_connections.c:668) etcp_connections_read_callback_socket() Sending INIT RESPONSE, link=0x57c7fa3b9060, local_link_id=0, remote_link_id=0
[03:05:50-317.741] [INFO] [8] (etcp_connections.c:669) etcp_connections_read_callback_socket() [ETCP DEBUG] Send INIT RESPONSE
[03:05:50-317.744] [TRACE] [4] (etcp_connections.c:471) etcp_encrypt_send()
[03:05:50-317.748] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-317.751] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-317.754] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-317.759] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-317.772] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x57c7fa3b9060 now ready, notifying ETCP_CONN
[03:05:50-317.776] [TRACE] [8] (etcp.c:637) etcp_link_ready_callback()
[03:05:50-317.779] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-317.782] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-317.785] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-317.789] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-317.792] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [3441→6882] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-317.795] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x57c7fa3b2d10 to senders_list
[03:05:50-317.799] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (0 routes) to connection
[03:05:50-317.803] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-317.807] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-317.812] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-317.815] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-317.818] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-317.821] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-317.829] [ERROR] [16] (etcp_connections.c:687) etcp_connections_read_callback_socket() etcp_connections_read_callback: failed to decrypt packet from node 1229782938247303441 len=105
[03:05:50-317.833] [ERROR] [8] (etcp_connections.c:799) etcp_connections_read_callback_socket() etcp_connections_read_callback: error 6
[03:05:50-317.836] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-317.841] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-317.844] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-317.847] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-317.850] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-317.854] [INFO] [8] (etcp_connections.c:694) etcp_connections_read_callback_socket() Decrypt end
[03:05:50-317.858] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-317.861] [TRACE] [8] (etcp.c:258) etcp_conn_reset()
[03:05:50-317.864] [INFO] [4] (etcp_connections.c:734) etcp_connections_read_callback_socket() [6882→0001] NAT address initialized: 127.0.0.1:9012
[03:05:50-317.868] [TRACE] [8] (etcp.c:268) etcp_update_log_name()
[03:05:50-317.871] [INFO] [8] (etcp_loadbalancer.c:156) loadbalancer_link_ready() loadbalancer_link_ready: link=0x57c7fa37c850 now ready, notifying ETCP_CONN
[03:05:50-317.874] [TRACE] [8] (etcp.c:637) etcp_link_ready_callback()
[03:05:50-317.877] [TRACE] [8] (etcp.c:645) etcp_conn_process_send_queue()
[03:05:50-317.880] [TRACE] [8] (etcp.c:535) etcp_request_pkt()
[03:05:50-317.883] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-317.887] [TRACE] [8] (etcp.c:342) input_queue_try_resume()
[03:05:50-317.898] [DEBUG] [8] (etcp.c:350) input_queue_try_resume() [6882→3441] resume callbacks: inflight_bytes=0, input_len=0
[03:05:50-317.901] [INFO] [4096] (route_bgp.c:452) route_bgp_new_conn() Added connection 0x57c7fa360eb0 to senders_list
[03:05:50-317.905] [INFO] [4096] (route_bgp.c:338) route_bgp_send_table_to_conn_internal() Sending full routing table (0 routes) to connection
[03:05:50-317.908] [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-317.911] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-318.979] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-320.052] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-321.126] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-322.202] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-323.283] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-324.385] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-325.459] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-326.546] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-327.643] [INFO] [8] (test_etcp_two_instances.c:129) monitor_connections() [SERVER] Link: peer=2222222222222222 initialized=1 type=server
[03:05:50-327.658] [INFO] [8] (test_etcp_two_instances.c:147) monitor_connections() [CLIENT] Link: peer=1 initialized=0 timer=active retry=1
[03:05:50-327.665] [INFO] [8] (test_etcp_two_instances.c:147) monitor_connections() [CLIENT] Link: peer=1111111111111111 initialized=1 timer=null retry=1
[03:05:50-327.670] [INFO] [8] (test_etcp_two_instances.c:156) monitor_connections() [CLIENT] Checking NAT fields...
[03:05:50-327.677] [INFO] [8] (test_etcp_two_instances.c:174) monitor_connections() [CLIENT] PASS: NAT address is set: 127.0.0.1:9012
[03:05:50-327.682] [INFO] [8] (test_etcp_two_instances.c:176) monitor_connections() [CLIENT] PASS: nat_changes_count=0, nat_hits_count=0
[03:05:50-327.687] [INFO] [8] (test_etcp_two_instances.c:196) monitor_connections() [CLIENT] PASS: NAT IP and port match exactly (127.0.0.1:9012)
[03:05:50-327.692] [INFO] [8] (test_etcp_two_instances.c:208) monitor_connections()
=== SUCCESS: Client connection established! ===
[03:05:50-327.697] [INFO] [8] (test_etcp_two_instances.c:212) monitor_connections() [TEST] Cancelling test timeout for immediate exit
[03:05:50-327.703] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-328.785] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-329.879] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-330.959] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-332.038] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-333.130] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-335.084] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-336.169] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-337.240] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-338.306] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-339.386] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-340.466] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-341.544] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-343.778] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-344.861] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-346.343] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-347.417] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-348.486] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-351.295] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-352.366] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-353.432] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-354.497] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-355.572] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-356.645] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-357.726] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-358.874] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-360.312] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-361.951] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-363.048] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-364.172] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-366.638] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-367.744] [TRACE] [4] (etcp_connections.c:110) etcp_link_init_timer_cbk()
[03:05:50-367.757] [TRACE] [4] (etcp_connections.c:42) etcp_link_send_init()
[03:05:50-367.761] [INFO] [4] (etcp_connections.c:43) etcp_link_send_init() etcp_link_send_init link=0x57c7fa3b2520, is_server=0
[03:05:50-367.767] [INFO] [4] (etcp_connections.c:81) etcp_link_send_init() Sending INIT request to link, node_id=2459565876494606882, retry=1
[03:05:50-367.789] [INFO] [8] (etcp_connections.c:88) etcp_link_send_init() [ETCP] INIT sending to 127.0.0.1:9011, link=0x57c7fa3b2520
[03:05:50-367.792] [TRACE] [4] (etcp_connections.c:471) etcp_encrypt_send()
[03:05:50-367.797] [TRACE] [8] (etcp.c:53) get_current_timestamp()
[03:05:50-367.801] [TRACE] [8] (etcp.c:43) get_current_time_units()
[03:05:50-367.804] [INFO] [8] (etcp_connections.c:485) etcp_encrypt_send() Encrypt start
[03:05:50-367.838] [INFO] [8] (etcp_connections.c:487) etcp_encrypt_send() Encrypt end
[03:05:50-367.863] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-367.869] [TRACE] [4] (etcp_connections.c:527) etcp_connections_read_callback_socket()
[03:05:50-367.876] [TRACE] [4] (etcp_connections.c:224) etcp_link_find_by_addr()
[03:05:50-367.879] [TRACE] [4] (etcp_connections.c:140) sockaddr_hash()
[03:05:50-367.882] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-367.886] [INFO] [8] (etcp_connections.c:685) etcp_connections_read_callback_socket() Decrypt start
[03:05:50-367.892] [ERROR] [16] (etcp_connections.c:687) etcp_connections_read_callback_socket() etcp_connections_read_callback: failed to decrypt packet from node 1229782938247303441 len=105
[03:05:50-367.896] [ERROR] [8] (etcp_connections.c:799) etcp_connections_read_callback_socket() etcp_connections_read_callback: error 6
[03:05:50-367.900] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-368.964] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-370.033] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-371.104] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-372.175] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-373.246] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-374.301] [DEBUG] [1024] (u_async.c:684) uasync_poll() poll
[03:05:50-375.369] [INFO] [8] (test_etcp_two_instances.c:333) main() Starting connection attempts...
[03:05:50-375.376] [INFO] [8] (test_etcp_two_instances.c:350) main()
Cleaning up...
[03:05:50-375.380] [INFO] [8] (test_etcp_two_instances.c:351) main() [CLEANUP] ua=0x57c7fa35d4c0
[03:05:50-375.383] [INFO] [8] (test_etcp_two_instances.c:352) main() [CLEANUP] server_instance=0x57c7fa35f4e0, client_instance=0x57c7fa363560
[03:05:50-375.387] [INFO] [8] (test_etcp_two_instances.c:353) main() [CLEANUP] monitor_timeout_id=0x57c7fa3b2300, test_timeout_id=(nil)
[03:05:50-375.391] [INFO] [8] (test_etcp_two_instances.c:357) main() [CLEANUP] Canceling monitor timeout on valid uasync
[03:05:50-375.394] [DEBUG] [1024] (u_async.c:426) uasync_cancel_timeout() uasync_cancel_timeout: not found in heap: ua=0x57c7fa35d4c0, t_id=0x57c7fa3b2300, node=0x57c7fa3b2300, expires=1771113950327 ms
[03:05:50-375.398] [INFO] [8] (test_etcp_two_instances.c:366) main() [CLEANUP] Timeouts canceled
[03:05:50-375.401] [INFO] [8] (test_etcp_two_instances.c:370) main() [CLEANUP] Shared uasync resources before destroy:
🔍 SHARED: UASYNC Resource Report for 0x57c7fa35d4c0
Timer Statistics: allocated=5, freed=3, active=2
Socket Statistics: allocated=2, freed=0, active=2
Timer: node=0x57c7fa3aae80, expires=1771113950417 ms, cancelled=0
Active timers in heap: 1
Socket array capacity: 16, active: 2
Socket: fd=6, active=1
Socket: fd=7, active=1
Total active sockets: 2
🔚 SHARED: End of resource report
[03:05:50-375.406] [INFO] [8] (test_etcp_two_instances.c:377) main() [CLEANUP] Destroying server instance 0x57c7fa35f4e0
[03:05:50-375.410] [INFO] [32] (utun_instance.c:153) utun_instance_destroy() [INSTANCE_DESTROY] Starting cleanup for instance 0x57c7fa35f4e0
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x57c7fa35f4e0
Node ID: 1229782938247303441
UA instance: 0x57c7fa35d4c0
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x57c7fa3b2d10
ETCP Sockets list: 0x57c7fa3604d0
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-375.416] [INFO] [32] (utun_instance.c:162) utun_instance_destroy() [INSTANCE_DESTROY] Cleaning up ETCP sockets and connections
[03:05:50-375.428] [INFO] [32] (utun_instance.c:166) utun_instance_destroy() [INSTANCE_DESTROY] Removing socket 0x57c7fa3604d0, fd=6
[03:05:50-375.432] [TRACE] [4] (etcp_connections.c:370) etcp_socket_remove()
[03:05:50-375.435] [INFO] [8] (etcp_connections.c:373) etcp_socket_remove() [ETCP] Removing socket 0x57c7fa3604d0, socket_id=0x57c7fa35d570
[03:05:50-375.438] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x57c7fa35f4e0, ua=0x57c7fa35d4c0
[03:05:50-375.444] [INFO] [8] (etcp_connections.c:380) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:05:50-375.453] [INFO] [8] (etcp_connections.c:385) etcp_socket_remove() [ETCP] Closed socket
[03:05:50-375.457] [TRACE] [4] (etcp_connections.c:446) etcp_link_close()
[03:05:50-375.460] [TRACE] [4] (etcp_connections.c:208) remove_link()
[03:05:50-375.463] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-375.467] [INFO] [32] (utun_instance.c:171) utun_instance_destroy() [INSTANCE_DESTROY] ETCP sockets cleanup complete
[03:05:50-375.470] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x57c7fa3b2d10
[03:05:50-375.473] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:05:50-375.477] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-375.480] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x57c7fa3b2d10 from senders_list
[03:05:50-375.484] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x57c7fa3b2d10 to all peers
[03:05:50-375.488] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x57c7fa3b2d10 removed from senders_list
[03:05:50-375.491] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x57c7fa3b2d10
[03:05:50-375.495] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-375.498] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3b2120, head=(nil), tail=(nil), count=0
[03:05:50-375.502] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3b21b0, head=(nil), tail=(nil), count=0
[03:05:50-375.506] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3b2e80, head=(nil), tail=(nil), count=0
[03:05:50-375.509] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3b2f10, head=(nil), tail=(nil), count=0
[03:05:50-375.512] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3b2fa0, head=(nil), tail=(nil), count=0
[03:05:50-375.516] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3ab9f0, head=(nil), tail=(nil), count=0
[03:05:50-375.520] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3ab390, head=(nil), tail=(nil), count=0
[03:05:50-375.523] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3b2400, head=(nil), tail=(nil), count=0
[03:05:50-375.526] [INFO] [32] (utun_instance.c:184) utun_instance_destroy() [INSTANCE_DESTROY] ETCP connections cleanup complete
[03:05:50-375.530] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:05:50-375.533] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 0 for instance 0x57c7fa35f4e0
[03:05:50-375.537] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:05:50-375.540] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 1 for instance 0x57c7fa35f4e0
[03:05:50-375.547] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa360830, head=(nil), tail=(nil), count=0
[03:05:50-375.550] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
[03:05:50-375.553] [INFO] [32] (utun_instance.c:205) utun_instance_destroy() [INSTANCE_DESTROY] Freeing configuration
[03:05:50-375.557] [INFO] [32] (utun_instance.c:212) utun_instance_destroy() [INSTANCE_DESTROY] Destroying packet pool
[03:05:50-375.560] [INFO] [32] (utun_instance.c:219) utun_instance_destroy() [INSTANCE_DESTROY] Destroying ack pool
[03:05:50-375.564] [INFO] [32] (utun_instance.c:226) utun_instance_destroy() [INSTANCE_DESTROY] Destroying data pool
[03:05:50-375.567] [INFO] [32] (utun_instance.c:241) utun_instance_destroy() [INSTANCE_DESTROY] Freeing instance memory
[03:05:50-375.570] [INFO] [32] (utun_instance.c:243) utun_instance_destroy() [INSTANCE_DESTROY] Instance destroyed completely
[03:05:50-375.573] [INFO] [8] (test_etcp_two_instances.c:382) main() [CLEANUP] Destroying client instance 0x57c7fa363560
[03:05:50-375.576] [INFO] [32] (utun_instance.c:153) utun_instance_destroy() [INSTANCE_DESTROY] Starting cleanup for instance 0x57c7fa363560
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x57c7fa363560
Node ID: 2459565876494606882
UA instance: 0x57c7fa35d4c0
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 2 active
ETCP Links: 3 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x57c7fa3abcb0
ETCP Sockets list: 0x57c7fa364910
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 2 ETCP connections still allocated
❌ 3 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
[03:05:50-375.581] [INFO] [32] (utun_instance.c:162) utun_instance_destroy() [INSTANCE_DESTROY] Cleaning up ETCP sockets and connections
[03:05:50-375.584] [INFO] [32] (utun_instance.c:166) utun_instance_destroy() [INSTANCE_DESTROY] Removing socket 0x57c7fa364910, fd=7
[03:05:50-375.588] [TRACE] [4] (etcp_connections.c:370) etcp_socket_remove()
[03:05:50-375.591] [INFO] [8] (etcp_connections.c:373) etcp_socket_remove() [ETCP] Removing socket 0x57c7fa364910, socket_id=0x57c7fa35d5b8
[03:05:50-375.594] [INFO] [8] (etcp_connections.c:377) etcp_socket_remove() [ETCP] Removing socket from uasync, instance=0x57c7fa363560, ua=0x57c7fa35d4c0
[03:05:50-375.598] [INFO] [8] (etcp_connections.c:380) etcp_socket_remove() [ETCP] Unregistered socket from uasync
[03:05:50-375.604] [INFO] [8] (etcp_connections.c:385) etcp_socket_remove() [ETCP] Closed socket
[03:05:50-375.607] [TRACE] [4] (etcp_connections.c:446) etcp_link_close()
[03:05:50-375.610] [TRACE] [4] (etcp_connections.c:208) remove_link()
[03:05:50-375.614] [TRACE] [4] (etcp_connections.c:147) find_link_index()
[03:05:50-375.617] [INFO] [32] (utun_instance.c:171) utun_instance_destroy() [INSTANCE_DESTROY] ETCP sockets cleanup complete
[03:05:50-375.620] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x57c7fa3abcb0
[03:05:50-375.623] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:05:50-375.626] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-375.629] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x57c7fa3abcb0 from senders_list
[03:05:50-375.633] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x57c7fa3abcb0 to all peers
[03:05:50-375.636] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x57c7fa3abcb0
[03:05:50-375.639] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-375.642] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3ab710, head=(nil), tail=(nil), count=0
[03:05:50-375.648] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3ab300, head=(nil), tail=(nil), count=0
[03:05:50-375.652] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3abe20, head=(nil), tail=(nil), count=0
[03:05:50-375.655] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3abeb0, head=(nil), tail=(nil), count=0
[03:05:50-375.658] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3abf40, head=(nil), tail=(nil), count=0
[03:05:50-375.662] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3ab150, head=(nil), tail=(nil), count=0
[03:05:50-375.665] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3ab4e0, head=(nil), tail=(nil), count=0
[03:05:50-375.669] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3aadc0, head=(nil), tail=(nil), count=0
[03:05:50-375.672] [TRACE] [4] (etcp_connections.c:446) etcp_link_close()
[03:05:50-375.675] [TRACE] [4] (etcp_connections.c:208) remove_link()
[03:05:50-375.679] [INFO] [32] (utun_instance.c:177) utun_instance_destroy() [INSTANCE_DESTROY] Closing connection 0x57c7fa360eb0
[03:05:50-375.682] [TRACE] [8] (etcp.c:136) etcp_connection_close()
[03:05:50-375.685] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-375.688] [INFO] [4096] (route_bgp.c:471) route_bgp_remove_conn() Removing connection 0x57c7fa360eb0 from senders_list
[03:05:50-375.691] [INFO] [4096] (route_bgp.c:200) route_bgp_send_withdraw_for_conn() Sending withdraw for routes via conn 0x57c7fa360eb0 to all peers
[03:05:50-375.694] [INFO] [4096] (route_bgp.c:484) route_bgp_remove_conn() Connection 0x57c7fa360eb0 removed from senders_list
[03:05:50-375.698] [INFO] [512] (route_lib.c:425) route_table_delete() Removed 0 routes for connection 0x57c7fa360eb0
[03:05:50-375.701] [DEBUG] [512] (routing.c:304) routing_del_conn() routing_del_conn: deprecated, no action taken
[03:05:50-375.704] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa36d640, head=(nil), tail=(nil), count=0
[03:05:50-375.707] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa36d6d0, head=(nil), tail=(nil), count=0
[03:05:50-375.711] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa35e320, head=(nil), tail=(nil), count=0
[03:05:50-375.714] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa360a80, head=(nil), tail=(nil), count=0
[03:05:50-375.718] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa3673d0, head=(nil), tail=(nil), count=0
[03:05:50-375.721] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa369470, head=(nil), tail=(nil), count=0
[03:05:50-375.725] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa36d5b0, head=(nil), tail=(nil), count=0
[03:05:50-375.728] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa36b510, head=(nil), tail=(nil), count=0
[03:05:50-375.731] [INFO] [32] (utun_instance.c:184) utun_instance_destroy() [INSTANCE_DESTROY] ETCP connections cleanup complete
[03:05:50-375.734] [INFO] [512] (routing.c:281) routing_destroy() Destroying routing module
[03:05:50-375.738] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 0 for instance 0x57c7fa363560
[03:05:50-375.741] [INFO] [4096] (utun_instance.c:198) utun_instance_destroy() Destroying BGP module
[03:05:50-375.744] [INFO] [1] (etcp_api.c:62) etcp_unbind() etcp_unbind: Unbound ID 1 for instance 0x57c7fa363560
[03:05:50-375.752] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x57c7fa364af0, head=(nil), tail=(nil), count=0
[03:05:50-375.757] [INFO] [4096] (route_bgp.c:418) route_bgp_destroy() BGP module destroyed
[03:05:50-375.762] [INFO] [32] (utun_instance.c:205) utun_instance_destroy() [INSTANCE_DESTROY] Freeing configuration
[03:05:50-375.772] [INFO] [32] (utun_instance.c:212) utun_instance_destroy() [INSTANCE_DESTROY] Destroying packet pool
[03:05:50-375.777] [INFO] [32] (utun_instance.c:219) utun_instance_destroy() [INSTANCE_DESTROY] Destroying ack pool
[03:05:50-375.781] [INFO] [32] (utun_instance.c:226) utun_instance_destroy() [INSTANCE_DESTROY] Destroying data pool
[03:05:50-375.784] [INFO] [32] (utun_instance.c:241) utun_instance_destroy() [INSTANCE_DESTROY] Freeing instance memory
[03:05:50-375.787] [INFO] [32] (utun_instance.c:243) utun_instance_destroy() [INSTANCE_DESTROY] Instance destroyed completely
[03:05:50-375.790] [DEBUG] [1024] (u_async.c:1000) uasync_destroy() uasync_destroy: starting cleanup for ua=0x57c7fa35d4c0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x57c7fa35d4c0
Timer Statistics: allocated=5, freed=3, active=2
Socket Statistics: allocated=2, freed=2, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-375.795] [ERROR] [32] (u_async.c:1007) uasync_destroy() Memory leaks detected before cleanup: timers 5/3, sockets 2/2
[03:05:50-375.798] [ERROR] [1024] (u_async.c:1009) uasync_destroy() Timer leak: allocated=5, freed=3, diff=2
[03:05:50-375.801] [ERROR] [1024] (u_async.c:1012) uasync_destroy() Socket leak: allocated=2, freed=2, diff=0
[03:05:50-375.805] [DEBUG] [32] (u_async.c:1048) uasync_destroy() Freed 0 socket nodes in destroy
[03:05:50-375.818] [DEBUG] [1024] (u_async.c:1081) uasync_destroy() uasync_destroy: completed successfully for ua=0x57c7fa35d4c0
[03:05:50-375.821] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-375.944] [INFO] [8] (test_etcp_two_instances.c:396) main()
=== TEST PASSED ===

44
tests/logs/test_intensive_memory_pool.log

@ -0,0 +1,44 @@
[03:05:50-806.564] [INFO] [32] (test_intensive_memory_pool.c:127) main() === Интенсивный тест пулов памяти ===
[03:05:50-806.616] [INFO] [32] (test_intensive_memory_pool.c:128) main() Тестируется производительность с пулами vs без пулов
[03:05:50-806.621] [INFO] [32] (test_intensive_memory_pool.c:132) main() Запуск теста без пулов памяти...
[03:05:50-806.627] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-806.643] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[03:05:50-806.649] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x5d04434eecc0, hash_size=0
[03:05:50-806.979] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x5d04434eecc0, head=(nil), tail=(nil), count=0
[03:05:50-806.982] [DEBUG] [1024] (u_async.c:1000) uasync_destroy() uasync_destroy: starting cleanup for ua=0x5d04434ee4c0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5d04434ee4c0
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-806.987] [DEBUG] [32] (u_async.c:1048) uasync_destroy() Freed 0 socket nodes in destroy
[03:05:50-806.998] [DEBUG] [1024] (u_async.c:1081) uasync_destroy() uasync_destroy: completed successfully for ua=0x5d04434ee4c0
[03:05:50-807.001] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-807.008] [INFO] [32] (test_intensive_memory_pool.c:134) main() Время без пулов: 0.000 сек
[03:05:50-807.019] [INFO] [32] (test_intensive_memory_pool.c:135) main() Waiter callbacks: 32000
[03:05:50-807.022] [INFO] [32] (test_intensive_memory_pool.c:139) main() Запуск теста с пулами памяти...
[03:05:50-807.026] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-807.033] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[03:05:50-807.037] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x5d04434ef230, hash_size=0
[03:05:50-807.361] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x5d04434ef230, head=(nil), tail=(nil), count=0
[03:05:50-807.368] [DEBUG] [1024] (u_async.c:1000) uasync_destroy() uasync_destroy: starting cleanup for ua=0x5d04434eecc0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5d04434eecc0
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-807.372] [DEBUG] [32] (u_async.c:1048) uasync_destroy() Freed 0 socket nodes in destroy
[03:05:50-807.381] [DEBUG] [1024] (u_async.c:1081) uasync_destroy() uasync_destroy: completed successfully for ua=0x5d04434eecc0
[03:05:50-807.384] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-807.388] [INFO] [32] (test_intensive_memory_pool.c:141) main() Время с пулами: 0.000 сек
[03:05:50-807.391] [INFO] [32] (test_intensive_memory_pool.c:142) main() Waiter callbacks: 32000
[03:05:50-807.395] [INFO] [32] (test_intensive_memory_pool.c:146) main() Результат: пулы памяти дали 1.09x ускорение
[03:05:50-807.398] [INFO] [32] (test_intensive_memory_pool.c:148) main() ✅ Пулы памяти эффективны!

104
tests/logs/test_ll_queue.log

@ -0,0 +1,104 @@
TEST: basic creation / free [03:05:50-799.553] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b35ab0, hash_size=0
[03:05:50-799.583] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b35d60, hash_size=16
[03:05:50-799.588] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b35ab0, head=(nil), tail=(nil), count=0
[03:05:50-799.592] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b35d60, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b352b0
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: FIFO ordering [03:05:50-799.609] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b354c0, hash_size=0
[03:05:50-799.614] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b354c0, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b35360
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: put_first (LIFO priority) [03:05:50-799.629] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b36bd0, hash_size=0
[03:05:50-799.632] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b36bd0, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b35e80
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: callback serial processing [03:05:50-799.646] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b35ef0, hash_size=0
[03:05:50-799.650] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b35ef0, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b36c60
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: wait_threshold + cancel [03:05:50-799.663] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b35ff0, hash_size=0
[03:05:50-799.667] [DEBUG] [2] (ll_queue.c:216) check_waiters() check_waiters: condition met, calling callback, count=2<=2, bytes=0<=0 (max_bytes_check=disabled)
[03:05:50-799.674] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b35ff0, head=0x637c97b36310, tail=0x637c97b356f0, count=2
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b35f80
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: size limit + hash find/remove [03:05:50-799.687] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b360f0, hash_size=16
[03:05:50-799.691] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b360f0, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b36080
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: memory_pool integration + reuse [03:05:50-799.704] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b36160, hash_size=0
[03:05:50-799.712] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b36160, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b360f0
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
TEST: stress 10k ops [03:05:50-799.728] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x637c97b36d70, hash_size=64
[03:05:50-800.874] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x637c97b36d70, head=(nil), tail=(nil), count=0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x637c97b36160
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
PASS
=== SUMMARY ===
run=8 passed=8 failed=0
callbacks: queue=5 waiter=2
ops=10000 time=1.39 ms

26
tests/logs/test_memory_pool_and_config.log

@ -0,0 +1,26 @@
[03:05:50-808.132] [INFO] [32] (test_memory_pool_and_config.c:33) main() === Memory Pool and Config File Test ===
[03:05:50-808.176] [INFO] [32] (test_memory_pool_and_config.c:36) main() Test 1: Memory pool optimization...
[03:05:50-808.181] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-808.190] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[03:05:50-808.195] [DEBUG] [2] (ll_queue.c:37) queue_new() queue_new: created queue 0x5e1dfdbb3cc0, hash_size=0
[03:05:50-808.200] [INFO] [32] (test_memory_pool_and_config.c:82) main() Pool statistics: allocations=0, reuse_count=0
[03:05:50-808.203] [INFO] [32] (test_memory_pool_and_config.c:83) main() Pool efficiency: 0.0%
[03:05:50-808.211] [DEBUG] [2] (ll_queue.c:62) queue_free() queue_free: freeing queue 0x5e1dfdbb3cc0, head=(nil), tail=(nil), count=0
[03:05:50-808.215] [DEBUG] [1024] (u_async.c:1000) uasync_destroy() uasync_destroy: starting cleanup for ua=0x5e1dfdbb34c0
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5e1dfdbb34c0
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-808.219] [DEBUG] [32] (u_async.c:1048) uasync_destroy() Freed 0 socket nodes in destroy
[03:05:50-808.228] [DEBUG] [1024] (u_async.c:1081) uasync_destroy() uasync_destroy: completed successfully for ua=0x5e1dfdbb34c0
[03:05:50-808.231] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-808.234] [INFO] [32] (test_memory_pool_and_config.c:89) main() Memory pool test: PASS
[03:05:50-808.245] [INFO] [128] (test_memory_pool_and_config.c:92) main() Test 2: Configuration file support...
[03:05:50-808.311] [ERROR] [128] (test_memory_pool_and_config.c:125) main() Failed to parse configuration
[03:05:50-808.344] [INFO] [128] (test_memory_pool_and_config.c:133) main() Configuration file test: PASS
[03:05:50-808.348] [INFO] [32] (test_memory_pool_and_config.c:135) main() === All tests completed successfully ===

3
tests/logs/test_packet_dump.log

@ -0,0 +1,3 @@
[03:05:50-809.037] [INFO] [8] (test_packet_dump.c:23) main() === Testing single-line packet dump ===
[03:05:50-809.079] [INFO] [8] (test_packet_dump.c:14) test_packet_dump() TEST_SEND: len=6 hex=021122334455
[03:05:50-809.084] [INFO] [8] (test_packet_dump.c:15) test_packet_dump() TEST_COMPACT: link=NULL type=0x02 ts=0 len=6

188
tests/logs/test_pkt_normalizer_etcp.log

@ -0,0 +1,188 @@
=== PKT Normalizer + ETCP Test ===
Testing with 100 packets of random sizes (10-2000 bytes)
Total data to transfer: 99424 bytes (0.97 KB average per packet)
Creating server...
[CONFIG DEBUG] Opening config file: /tmp/utun_test_bE4dFl/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_bE4dFl/server.conf
[CONFIG DEBUG] Successfully opened config file
Server created, waiting for connection...
Creating client...
[CONFIG DEBUG] Opening config file: /tmp/utun_test_bE4dFl/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_bE4dFl/client.conf
[CONFIG DEBUG] Successfully opened config file
Client created
Sending 100 packets in each direction via normalizer...
Connection check: client=1, server=1
Connections: client=0x556f3c579290, server=0x556f3c5be2d0
DEBUG: client_pn=(nil), client_instance->connections=0x556f3c579290
Creating client normalizer...
Client normalizer created (frag_size=1400)
DEBUG: server_pn=(nil), server_instance->connections=0x556f3c5be2d0
Creating server normalizer...
Server normalizer created (frag_size=1400)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=0/100
Starting forward transfer (client -> server) via normalizer...
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
DEBUG send_packets_fwd: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250, packets_sent_fwd=100/100
DEBUG send_packets_fwd: early return (instance=0x556f3c575420, pn=0x556f3c5bd250, sent=100)
Forward transfer completed: 100/100 packets in 22.27 ms
Starting backward transfer (server -> client) via normalizer...
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
DEBUG check_received_packets_back: client_instance=0x556f3c575420, client_pn=0x556f3c5bd250
Backward transfer completed: 100/100 packets in 22.23 ms
=== SUCCESS: Bidirectional transfer via normalizer completed! ===
Forward (client->server): 100/100 packets in 22.27 ms
Backward (server->client): 100/100 packets in 22.23 ms
Total time: 45.57 ms
Cleaning up...
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x556f3c570c90
Node ID: 1229782938247303441
UA instance: 0x556f3c570490
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x556f3c5be2d0
ETCP Sockets list: 0x556f3c572330
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
🔍 [UTUN_INSTANCE LEAK DIAGNOSIS] Phase: BEFORE_CLEANUP
Instance: 0x556f3c575420
Node ID: 2459565876494606882
UA instance: 0x556f3c570490
Running: 0
📊 STRUCTURE COUNTS:
ETCP Sockets: 1 active
ETCP Connections: 1 active
ETCP Links: 2 total
🔧 RESOURCE STATUS:
Memory Pool: ALLOCATED
TUN Interface: NULL
TUN FD: -1
Connections list: 0x556f3c579290
ETCP Sockets list: 0x556f3c5767d0
⚠️ POTENTIAL LEAKS:
❌ Memory Pool not freed
❌ 1 ETCP sockets still allocated
❌ 1 ETCP connections still allocated
❌ 2 ETCP links still allocated
📋 RECOMMENDATIONS:
→ Call memory_pool_destroy() before freeing instance
→ Iterate and call etcp_socket_remove() for each socket
→ Iterate and call etcp_connection_close() for each connection
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x556f3c570490
Timer Statistics: allocated=298, freed=279, active=19
Socket Statistics: allocated=2, freed=2, active=0
Timer: node=0x556f3c5bd0c0, expires=1771113950671 ms, cancelled=0
Timer: node=0x556f3c5db0d0, expires=1771113950674 ms, cancelled=0
Timer: node=0x556f3c5bd940, expires=1771113950676 ms, cancelled=0
Timer: node=0x556f3c5bd4a0, expires=1771113950686 ms, cancelled=0
Timer: node=0x556f3c5c86c0, expires=1771113950681 ms, cancelled=0
Timer: node=0x556f3c5cb900, expires=1771113950691 ms, cancelled=0
Timer: node=0x556f3c5d9e20, expires=1771113950678 ms, cancelled=0
Timer: node=0x556f3c5be240, expires=1771113950703 ms, cancelled=0
Timer: node=0x556f3c5d4290, expires=1771113950709 ms, cancelled=0
Timer: node=0x556f3c5e0f30, expires=1771113950711 ms, cancelled=0
Timer: node=0x556f3c5cb9d0, expires=1771113950683 ms, cancelled=0
Timer: node=0x556f3c5e4960, expires=1771113950694 ms, cancelled=0
Timer: node=0x556f3c5d42c0, expires=1771113950697 ms, cancelled=0
Timer: node=0x556f3c5bcd60, expires=1771113950688 ms, cancelled=0
Timer: node=0x556f3c5e3df0, expires=1771113950700 ms, cancelled=0
Timer: node=0x556f3c5dd320, expires=1771113950705 ms, cancelled=0
Timer: node=0x556f3c5ccc70, expires=1771113950707 ms, cancelled=0
Timer: node=0x556f3c5cd0e0, expires=1771113950713 ms, cancelled=0
Active timers in heap: 18
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-616.114] [ERROR] [32] (u_async.c:1007) uasync_destroy() Memory leaks detected before cleanup: timers 298/279, sockets 2/2
[03:05:50-616.169] [ERROR] [1024] (u_async.c:1009) uasync_destroy() Timer leak: allocated=298, freed=279, diff=19
[03:05:50-616.176] [ERROR] [1024] (u_async.c:1012) uasync_destroy() Socket leak: allocated=2, freed=2, diff=0
=== TEST PASSED ===
All 100 packets transmitted in each direction via normalizer

29
tests/logs/test_pkt_normalizer_standalone.log

@ -0,0 +1,29 @@
=== PKT Normalizer Standalone Test (Loopback) ===
MTU: 1500, Frag size: 1400
Testing with 100 packets of random sizes (10-3000 bytes)
Total data to transfer: 147790 bytes (1.44 KB average per packet)
Normalizer created (frag_size=1400)
Sending 100 packets...
All 100 packets queued to normalizer
=== SUCCESS: All packets received! ===
Sent: 100, Received: 100
Fragments: sent=106, received=100
Duration: 2.43 ms
Cleaning up...
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x6075d41742b0
Timer Statistics: allocated=104, freed=103, active=1
Socket Statistics: allocated=0, freed=0, active=0
Timer: node=0x6075d4174df0, expires=1771113951617 ms, cancelled=0
Active timers in heap: 1
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
=== TEST PASSED ===

3182
tests/logs/test_route_lib.log

File diff suppressed because it is too large Load Diff

115
tests/logs/test_u_async_comprehensive.log

@ -0,0 +1,115 @@
[03:05:50-809.881] [INFO] [1] (test_u_async_comprehensive.c:474) main() === lib Comprehensive Unit Tests ===
[03:05:50-809.929] [INFO] [1] (test_u_async_comprehensive.c:475) main() Testing race conditions, memory management, and error handling
[03:05:50-809.934] [INFO] [1] (test_u_async_comprehensive.c:144) test_basic_timers() TEST: Basic timer functionality...
[03:05:50-809.937] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-809.948] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1d4c0
Timer Statistics: allocated=3, freed=3, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-812.297] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-812.323] [INFO] [1] (test_u_async_comprehensive.c:172) test_basic_timers() PASS
[03:05:50-812.328] [INFO] [1] (test_u_async_comprehensive.c:177) test_timer_cancellation_races() TEST: Timer cancellation race conditions...
[03:05:50-812.331] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-812.346] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1d570
Timer Statistics: allocated=3, freed=3, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-822.475] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-822.539] [INFO] [1] (test_u_async_comprehensive.c:224) test_timer_cancellation_races() PASS
[03:05:50-822.544] [INFO] [1] (test_u_async_comprehensive.c:229) test_immediate_timeouts() TEST: Immediate timeout handling...
[03:05:50-822.548] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-822.579] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1e2d0
Timer Statistics: allocated=5, freed=5, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-822.594] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-822.598] [INFO] [1] (test_u_async_comprehensive.c:261) test_immediate_timeouts() PASS
[03:05:50-822.602] [INFO] [1] (test_u_async_comprehensive.c:266) test_memory_leak_detection() TEST: Memory leak detection...
[03:05:50-822.605] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-822.613] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1d5e0
Timer Statistics: allocated=10, freed=10, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-832.234] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-832.275] [INFO] [1] (test_u_async_comprehensive.c:293) test_memory_leak_detection() PASS
[03:05:50-832.296] [INFO] [1] (test_u_async_comprehensive.c:298) test_socket_management() TEST: Socket management efficiency...
[03:05:50-832.303] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-832.323] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1d790
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=10, freed=10, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-832.428] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-832.445] [INFO] [1] (test_u_async_comprehensive.c:340) test_socket_management() PASS
[03:05:50-832.449] [INFO] [1] (test_u_async_comprehensive.c:345) test_error_handling() TEST: Error injection and handling...
[03:05:50-832.453] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-832.463] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
[03:05:50-832.469] [ERROR] [1024] (u_async.c:410) uasync_cancel_timeout() uasync_cancel_timeout: invalid parameters ua=(nil), t_id=(nil), heap=(nil)
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1e430
Timer Statistics: allocated=1, freed=1, active=0
Socket Statistics: allocated=0, freed=0, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-832.480] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-832.484] [INFO] [1] (test_u_async_comprehensive.c:375) test_error_handling() PASS
[03:05:50-832.488] [INFO] [1] (test_u_async_comprehensive.c:380) test_concurrent_operations() TEST: Concurrent operations stress test...
[03:05:50-832.492] [INFO] [8192] (socket_compat.c:54) socket_platform_init() POSIX socket subsystem ready
[03:05:50-832.501] [INFO] [1] (u_async.c:930) uasync_create() Using epoll for socket monitoring
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x5a0d63c1d800
Timer Statistics: allocated=10, freed=2, active=8
Socket Statistics: allocated=2, freed=2, active=0
Active timers in heap: 0
Socket array capacity: 16, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
[03:05:50-832.637] [ERROR] [32] (u_async.c:1007) uasync_destroy() Memory leaks detected before cleanup: timers 10/2, sockets 2/2
[03:05:50-832.644] [ERROR] [1024] (u_async.c:1009) uasync_destroy() Timer leak: allocated=10, freed=2, diff=8
[03:05:50-832.648] [ERROR] [1024] (u_async.c:1012) uasync_destroy() Socket leak: allocated=2, freed=2, diff=0
[03:05:50-832.658] [INFO] [8192] (socket_compat.c:60) socket_platform_cleanup() POSIX socket cleanup completed
[03:05:50-832.662] [INFO] [1] (test_u_async_comprehensive.c:465) test_concurrent_operations() PASS
[03:05:50-832.666] [INFO] [1] (test_u_async_comprehensive.c:487) main() === Test Statistics ===
[03:05:50-832.670] [INFO] [1] (test_u_async_comprehensive.c:488) main() Tests run: 7
[03:05:50-832.674] [INFO] [1] (test_u_async_comprehensive.c:489) main() Tests passed: 7
[03:05:50-832.678] [INFO] [1] (test_u_async_comprehensive.c:490) main() Tests failed: 0
[03:05:50-832.682] [INFO] [1] (test_u_async_comprehensive.c:491) main() Timer callbacks: 14
[03:05:50-832.686] [INFO] [1] (test_u_async_comprehensive.c:492) main() Timer cancellations: 1
[03:05:50-832.689] [INFO] [1] (test_u_async_comprehensive.c:493) main() Immediate timeouts: 9
[03:05:50-832.693] [INFO] [1] (test_u_async_comprehensive.c:494) main() Socket events: 17
[03:05:50-832.697] [INFO] [1] (test_u_async_comprehensive.c:495) main() Race condition errors: 1
[03:05:50-832.701] [INFO] [1] (test_u_async_comprehensive.c:498) main() === Memory Leak Detection ===
[03:05:50-832.705] [INFO] [1] (test_u_async_comprehensive.c:499) main() No memory leaks detected during testing

59
tests/logs/test_u_async_performance.log

@ -0,0 +1,59 @@
lib Socket Management Performance Benchmark
================================================
=== Socket Management Benchmark ===
Testing with 25 sockets
DEBUG: Socket 0 has fd=6
Created 25 sockets
DEBUG: Total sockets added: 25
Add 25 sockets: 30 us (1.20 us per socket)
SKIPPING POLLING to test corruption
DEBUG: Removing sockets using lookup by FD
DEBUG: Attempting to remove socket 0 (fd=6, id=0x653e819a3b90)
DEBUG: Attempting to remove socket 1 (fd=7, id=0x653e819a3bd8)
DEBUG: Attempting to remove socket 2 (fd=8, id=0x653e819a3c20)
DEBUG: Attempting to remove socket 3 (fd=9, id=0x653e819a3c68)
DEBUG: Attempting to remove socket 4 (fd=10, id=0x653e819a3cb0)
DEBUG: Attempting to remove socket 5 (fd=11, id=0x653e819a3cf8)
DEBUG: Attempting to remove socket 6 (fd=12, id=0x653e819a3d40)
DEBUG: Attempting to remove socket 7 (fd=13, id=0x653e819a3d88)
DEBUG: Attempting to remove socket 8 (fd=14, id=0x653e819a3dd0)
DEBUG: Attempting to remove socket 9 (fd=15, id=0x653e819a3e18)
DEBUG: Attempting to remove socket 10 (fd=16, id=0x653e819a3e60)
DEBUG: Attempting to remove socket 11 (fd=17, id=0x653e819a3ea8)
DEBUG: Attempting to remove socket 12 (fd=18, id=0x653e819a3ef0)
DEBUG: Attempting to remove socket 13 (fd=19, id=0x653e819a3f38)
DEBUG: Attempting to remove socket 14 (fd=20, id=0x653e819a3f80)
DEBUG: Attempting to remove socket 15 (fd=21, id=0x653e819a3fc8)
DEBUG: Attempting to remove socket 16 (fd=22, id=0x653e819a4010)
DEBUG: Attempting to remove socket 17 (fd=23, id=0x653e819a4058)
DEBUG: Attempting to remove socket 18 (fd=24, id=0x653e819a40a0)
DEBUG: Attempting to remove socket 19 (fd=25, id=0x653e819a40e8)
DEBUG: Attempting to remove socket 20 (fd=26, id=0x653e819a4130)
DEBUG: Attempting to remove socket 21 (fd=27, id=0x653e819a4178)
DEBUG: Attempting to remove socket 22 (fd=28, id=0x653e819a41c0)
DEBUG: Attempting to remove socket 23 (fd=29, id=0x653e819a4208)
DEBUG: Attempting to remove socket 24 (fd=30, id=0x653e819a4250)
DEBUG: Actually removed 25 sockets, failed 0
Remove 25 sockets: 19 us (0.76 us per socket)
Total time: 49 us
Average per operation: 0.98 us
SKIPPING memory stats for corruption testing
🔍 BEFORE_DESTROY: UASYNC Resource Report for 0x653e819a32b0
Timer Statistics: allocated=0, freed=0, active=0
Socket Statistics: allocated=25, freed=25, active=0
Active timers in heap: 0
Socket array capacity: 32, active: 0
Total active sockets: 0
🔚 BEFORE_DESTROY: End of resource report
=== Benchmark Complete ===
Array-based socket management provides:
- O(1) add/remove operations (vs O(n) for linked list)
- Better cache locality for sequential socket processing
- Direct FD-to-index mapping for fast lookups
- Reduced memory allocations per operation

BIN
tests/test_bgp_route_exchange

Binary file not shown.

BIN
tests/test_config_debug

Binary file not shown.

BIN
tests/test_crypto

Binary file not shown.

BIN
tests/test_debug_categories

Binary file not shown.

BIN
tests/test_ecc_encrypt

Binary file not shown.

BIN
tests/test_etcp_100_packets

Binary file not shown.

BIN
tests/test_etcp_api

Binary file not shown.

BIN
tests/test_etcp_crypto

Binary file not shown.

BIN
tests/test_etcp_minimal

Binary file not shown.

BIN
tests/test_etcp_simple_traffic

Binary file not shown.

BIN
tests/test_etcp_two_instances

Binary file not shown.

BIN
tests/test_intensive_memory_pool

Binary file not shown.

BIN
tests/test_ll_queue

Binary file not shown.

BIN
tests/test_memory_pool_and_config

Binary file not shown.

BIN
tests/test_packet_dump

Binary file not shown.

BIN
tests/test_pkt_normalizer_etcp

Binary file not shown.

BIN
tests/test_pkt_normalizer_standalone

Binary file not shown.

BIN
tests/test_route_lib

Binary file not shown.

BIN
tests/test_u_async_comprehensive

Binary file not shown.

BIN
tests/test_u_async_performance

Binary file not shown.
Loading…
Cancel
Save