jeka
/
utun2
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity
Browse Source

Убрал DEBUG_CATEGORY_DEBUG: сообщения разбросаны по модульным категориям (+CHAT=25, MEDIA=23)

topo_upd
Evgeny 2 months ago
parent
869f7c60d5
commit
2cba839de4
18 changed files with 158 additions and 189 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Unified View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 2
      lib/debug_config.c
  2. 4
      lib/debug_config.h
  3. 2
      lib/u_async.c
  4. 4
      src/chat/chat_event.c
  5. 64
      src/chat/chat_whisper.c
  6. 20
      src/media_async/media_async.c
  7. 62
      src/media_delivery/media_delivery.c
  8. 56
      src/media_delivery/media_download.c
  9. 18
      src/media_delivery/media_index.c
  10. 2
      src/routing_layer/conn_mgr_core.c
  11. 32
      src/routing_layer/topo_group.c
  12. 27
      src/transport_layer/etcp.c
  13. 6
      src/transport_layer/etcp_api.c
  14. 8
      src/transport_layer/etcp_connect.c
  15. 10
      src/transport_layer/etcp_connections.c
  16. 2
      src/transport_layer/etcp_loadbalancer.c
  17. 20
      src/transport_layer/node_conn_direct.c
  18. 8
      tools/chatgui/src/debug_ui.h

2
lib/debug_config.c
Unescape View File

@ -114,6 +114,7 @@ static const struct {
{"routing", DEBUG_CATEGORY_ROUTING}, {"routing", DEBUG_CATEGORY_ROUTING},
{"timers", DEBUG_CATEGORY_TIMERS}, {"timers", DEBUG_CATEGORY_TIMERS},
{"bgp", DEBUG_CATEGORY_BGP}, {"bgp", DEBUG_CATEGORY_BGP},
{"chat", DEBUG_CATEGORY_CHAT},
{"socket", DEBUG_CATEGORY_SOCKET}, {"socket", DEBUG_CATEGORY_SOCKET},
{"control", DEBUG_CATEGORY_CONTROL}, {"control", DEBUG_CATEGORY_CONTROL},
{"dump", DEBUG_CATEGORY_DUMP}, {"dump", DEBUG_CATEGORY_DUMP},
@ -122,6 +123,7 @@ static const struct {
{"general", DEBUG_CATEGORY_GENERAL}, {"general", DEBUG_CATEGORY_GENERAL},
{"nat", DEBUG_CATEGORY_NAT}, {"nat", DEBUG_CATEGORY_NAT},
{"keepalive", DEBUG_CATEGORY_KEEPALIVE}, {"keepalive", DEBUG_CATEGORY_KEEPALIVE},
{"media", DEBUG_CATEGORY_MEDIA},
{"etcp_route", DEBUG_CATEGORY_ETCPROUTE}, {"etcp_route", DEBUG_CATEGORY_ETCPROUTE},
{"etcp_dump", DEBUG_CATEGORY_ETCP_DUMP}, {"etcp_dump", DEBUG_CATEGORY_ETCP_DUMP},
{"chat_sync", DEBUG_CATEGORY_CHAT_SYNC}, {"chat_sync", DEBUG_CATEGORY_CHAT_SYNC},

4
lib/debug_config.h
Unescape View File

@ -61,9 +61,9 @@ typedef int debug_category_t;
#define DEBUG_CATEGORY_NAT 20 // EIM NAT module #define DEBUG_CATEGORY_NAT 20 // EIM NAT module
#define DEBUG_CATEGORY_KEEPALIVE 21 // Keepalive periodic monitoring only #define DEBUG_CATEGORY_KEEPALIVE 21 // Keepalive periodic monitoring only
#define DEBUG_CATEGORY_ETCPROUTE 22 // ETCP routing #define DEBUG_CATEGORY_ETCPROUTE 22 // ETCP routing
// #define DEBUG_CATEGORY_BBR 23 (merged into ETCP) #define DEBUG_CATEGORY_MEDIA 23 // Media delivery + media async
#define DEBUG_CATEGORY_ETCP_DUMP 24 // ETCP packet dump #define DEBUG_CATEGORY_ETCP_DUMP 24 // ETCP packet dump
// #define DEBUG_CATEGORY_CONNECTIVITY 25 (unused, removed) #define DEBUG_CATEGORY_CHAT 25 // Chat modules (chat_core, whisper, etc.)
#define DEBUG_CATEGORY_CHAT_SYNC 26 // Message DB sync (INIT_SYNC, PUSH, chain hash, recalc) #define DEBUG_CATEGORY_CHAT_SYNC 26 // Message DB sync (INIT_SYNC, PUSH, chain hash, recalc)
#define DEBUG_CATEGORY_MEMBER_SYNC 27 // Member + address + merkle sync #define DEBUG_CATEGORY_MEMBER_SYNC 27 // Member + address + merkle sync
#define DEBUG_CATEGORY_PROXY 28 // Proxy modules (SOCKS5, TCP, UDP, ICMP) #define DEBUG_CATEGORY_PROXY 28 // Proxy modules (SOCKS5, TCP, UDP, ICMP)

2
lib/u_async.c
Unescape View File

@ -560,7 +560,7 @@ void* uasync_set_timeout(struct UASYNC* ua, int timeout_tb, void* arg, timeout_c
node->expiration_ms = timeval_to_ms(&now); node->expiration_ms = timeval_to_ms(&now);
if (name && strncmp(name, "ncd_connect", 11) == 0) { if (name && strncmp(name, "ncd_connect", 11) == 0) {
uint64_t exp_tb = (uint64_t)now.tv_sec * 10000ULL + (uint64_t)now.tv_usec / 100ULL; uint64_t exp_tb = (uint64_t)now.tv_sec * 10000ULL + (uint64_t)now.tv_usec / 100ULL;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[uasync] set_timeout: name=%s tb=%d now_tb=%llu exp_tb=%llu exp_ms=%llu delta_tb=%llu", DEBUG_DEBUG(DEBUG_CATEGORY_TIMERS, "[uasync] set_timeout: name=%s tb=%d now_tb=%llu exp_tb=%llu exp_ms=%llu delta_tb=%llu",
name, timeout_tb, (unsigned long long)now_tb, (unsigned long long)exp_tb, name, timeout_tb, (unsigned long long)now_tb, (unsigned long long)exp_tb,
(unsigned long long)node->expiration_ms, (unsigned long long)(exp_tb - now_tb)); (unsigned long long)node->expiration_ms, (unsigned long long)(exp_tb - now_tb));
} }

4
src/chat/chat_event.c
Unescape View File

@ -39,6 +39,6 @@ void chat_event_post(int type, const uint8_t* data, int len) {
[24]="MEMBER_UPDATED", [25]="MEMBER_REMOVED", [24]="MEMBER_UPDATED", [25]="MEMBER_REMOVED",
}; };
const char* n = (type >= 1 && type <= 25) ? names[type] : "?"; const char* n = (type >= 1 && type <= 25) ? names[type] : "?";
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "chat_event: %s(%d) data=%d bytes", n, type, len); DEBUG_DEBUG(DEBUG_CATEGORY_CHAT, "chat_event: %s(%d) data=%d bytes", n, type, len);
if (data && len > 0) log_dump(DEBUG_LEVEL_DEBUG, DEBUG_CATEGORY_DEBUG, " ", data, len); if (data && len > 0) log_dump(DEBUG_LEVEL_DEBUG, DEBUG_CATEGORY_CHAT, " ", data, len);
} }

64
src/chat/chat_whisper.c
Unescape View File

@ -64,12 +64,12 @@ static int read_u32_le(FILE* f, uint32_t* v) { return fread(v, 4, 1, f) == 1; }
static struct wav_pcm* wav_read(const char* path) { static struct wav_pcm* wav_read(const char* path) {
FILE* f = fopen(path, "rb"); FILE* f = fopen(path, "rb");
if (!f) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: cannot open %s", CW_ID, path); return NULL; } if (!f) { DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: cannot open %s", CW_ID, path); return NULL; }
char riff[4], wave[4]; char riff[4], wave[4];
if (fread(riff, 1, 4, f) != 4 || memcmp(riff, "RIFF", 4) != 0) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: no RIFF header", CW_ID); return NULL; } if (fread(riff, 1, 4, f) != 4 || memcmp(riff, "RIFF", 4) != 0) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: no RIFF header", CW_ID); return NULL; }
uint32_t file_size; read_u32_le(f, &file_size); uint32_t file_size; read_u32_le(f, &file_size);
if (fread(wave, 1, 4, f) != 4 || memcmp(wave, "WAVE", 4) != 0) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: no WAVE", CW_ID); return NULL; } if (fread(wave, 1, 4, f) != 4 || memcmp(wave, "WAVE", 4) != 0) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: no WAVE", CW_ID); return NULL; }
uint16_t audio_format = 0, channels = 0; uint16_t audio_format = 0, channels = 0;
uint32_t sample_rate = 0, byte_rate = 0, data_size = 0; uint32_t sample_rate = 0, byte_rate = 0, data_size = 0;
@ -93,10 +93,10 @@ static struct wav_pcm* wav_read(const char* path) {
} }
} }
if (audio_format != 1) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: not PCM (fmt=%u)", CW_ID, audio_format); return NULL; } if (audio_format != 1) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: not PCM (fmt=%u)", CW_ID, audio_format); return NULL; }
if (channels < 1 || channels > 2) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: bad channels %u", CW_ID, channels); return NULL; } if (channels < 1 || channels > 2) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: bad channels %u", CW_ID, channels); return NULL; }
if (bits_per_sample != 16) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: not 16-bit PCM", CW_ID); return NULL; } if (bits_per_sample != 16) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: not 16-bit PCM", CW_ID); return NULL; }
if (sample_rate < 8000 || sample_rate > 48000) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: bad sample_rate %u", CW_ID, sample_rate); return NULL; } if (sample_rate < 8000 || sample_rate > 48000) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: bad sample_rate %u", CW_ID, sample_rate); return NULL; }
int frame_size = (int)(bits_per_sample / 8) * channels; int frame_size = (int)(bits_per_sample / 8) * channels;
int total_frames = (int)(data_size / frame_size); int total_frames = (int)(data_size / frame_size);
@ -117,7 +117,7 @@ static struct wav_pcm* wav_read(const char* path) {
} }
fclose(f); fclose(f);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: wav_read %s: %d samples %dHz mono", CW_ID, path, pcm->n_samples, pcm->sample_rate); DEBUG_DEBUG(DEBUG_CATEGORY_CHAT, "%s: wav_read %s: %d samples %dHz mono", CW_ID, path, pcm->n_samples, pcm->sample_rate);
return pcm; return pcm;
} }
@ -139,16 +139,16 @@ struct opus_pcm {
static struct opus_pcm* opus_read(const char* path) { static struct opus_pcm* opus_read(const char* path) {
FILE* f = fopen(path, "rb"); FILE* f = fopen(path, "rb");
if (!f) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: cannot open %s", CW_ID, path); return NULL; } if (!f) { DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: cannot open %s", CW_ID, path); return NULL; }
char magic[4]; char magic[4];
if (fread(magic, 1, 4, f) != 4 || memcmp(magic, "OPUS", 4) != 0) { fclose(f); return NULL; } if (fread(magic, 1, 4, f) != 4 || memcmp(magic, "OPUS", 4) != 0) { fclose(f); return NULL; }
uint32_t sr, ch; uint32_t sr, ch;
if (fread(&sr, 4, 1, f) != 1 || fread(&ch, 4, 1, f) != 1) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: bad opus header", CW_ID); return NULL; } if (fread(&sr, 4, 1, f) != 1 || fread(&ch, 4, 1, f) != 1) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: bad opus header", CW_ID); return NULL; }
opus_codec_decoder_t* dec = opus_codec_decoder_create((int)sr, (int)ch); opus_codec_decoder_t* dec = opus_codec_decoder_create((int)sr, (int)ch);
if (!dec) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: opus decoder create failed", CW_ID); return NULL; } if (!dec) { fclose(f); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: opus decoder create failed", CW_ID); return NULL; }
int frame_samples = (int)sr * 20 / 1000; int frame_samples = (int)sr * 20 / 1000;
size_t alloc_samples = 0; size_t alloc_samples = 0;
@ -190,7 +190,7 @@ static struct opus_pcm* opus_read(const char* path) {
pcm->samples = buffer; pcm->samples = buffer;
pcm->n_samples = total_samples; pcm->n_samples = total_samples;
pcm->sample_rate = (int)sr; pcm->sample_rate = (int)sr;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: opus_read %s: %d samples %dHz", CW_ID, path, total_samples, (int)sr); DEBUG_DEBUG(DEBUG_CATEGORY_CHAT, "%s: opus_read %s: %d samples %dHz", CW_ID, path, total_samples, (int)sr);
return pcm; return pcm;
} }
@ -253,12 +253,12 @@ static void wh_work_fn(void* raw) {
struct wh_work_ctx* w = (struct wh_work_ctx*)raw; struct wh_work_ctx* w = (struct wh_work_ctx*)raw;
#ifndef HAVE_WHISPER #ifndef HAVE_WHISPER
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: whisper not compiled in", CW_ID); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: whisper not compiled in", CW_ID);
w->err = -1; w->err = -1;
return; return;
#else #else
if (!g_whisper_ctx) { if (!g_whisper_ctx) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: whisper not initialized", CW_ID); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: whisper not initialized", CW_ID);
w->err = -1; w->err = -1;
return; return;
} }
@ -282,7 +282,7 @@ static void wh_work_fn(void* raw) {
} }
if (!pcm_samples || pcm_n <= 0) { if (!pcm_samples || pcm_n <= 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: cannot decode %s", CW_ID, w->job.audio_path); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: cannot decode %s", CW_ID, w->job.audio_path);
w->err = -1; w->err = -1;
return; return;
} }
@ -292,12 +292,12 @@ static void wh_work_fn(void* raw) {
float* samples_16k = resample_16k(pcm_samples, pcm_n, pcm_rate, &n_16k); float* samples_16k = resample_16k(pcm_samples, pcm_n, pcm_rate, &n_16k);
u_free(pcm_samples); u_free(pcm_samples);
if (!samples_16k || n_16k <= 0) { if (!samples_16k || n_16k <= 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: resample failed", CW_ID); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: resample failed", CW_ID);
w->err = -1; w->err = -1;
return; return;
} }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: %d samples @ 16kHz, running whisper_full", CW_ID, n_16k); DEBUG_DEBUG(DEBUG_CATEGORY_CHAT, "%s: %d samples @ 16kHz, running whisper_full", CW_ID, n_16k);
/* 3. Whisper */ /* 3. Whisper */
struct whisper_full_params wparams = whisper_full_default_params(WHISPER_SAMPLING_GREEDY); struct whisper_full_params wparams = whisper_full_default_params(WHISPER_SAMPLING_GREEDY);
@ -310,7 +310,7 @@ static void wh_work_fn(void* raw) {
u_free(samples_16k); u_free(samples_16k);
if (ret != 0) { if (ret != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: whisper_full failed ret=%d", CW_ID, ret); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: whisper_full failed ret=%d", CW_ID, ret);
w->err = -1; w->err = -1;
return; return;
} }
@ -318,7 +318,7 @@ static void wh_work_fn(void* raw) {
/* 4. Collect text */ /* 4. Collect text */
int n_seg = whisper_full_n_segments(g_whisper_ctx); int n_seg = whisper_full_n_segments(g_whisper_ctx);
if (n_seg <= 0) { if (n_seg <= 0) {
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: whisper returned no segments", CW_ID); DEBUG_WARN(DEBUG_CATEGORY_CHAT, "%s: whisper returned no segments", CW_ID);
w->text = u_strdup(""); w->text = u_strdup("");
} else { } else {
size_t total = 0; size_t total = 0;
@ -333,7 +333,7 @@ static void wh_work_fn(void* raw) {
const char* seg = whisper_full_get_segment_text(g_whisper_ctx, i); const char* seg = whisper_full_get_segment_text(g_whisper_ctx, i);
if (seg) strcat(w->text, seg); if (seg) strcat(w->text, seg);
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: transcribed [%s]", CW_ID, w->text); DEBUG_INFO(DEBUG_CATEGORY_CHAT, "%s: transcribed [%s]", CW_ID, w->text);
} }
} }
@ -375,7 +375,7 @@ static int find_model_path(char* out, size_t out_sz) {
/* если путь относительный, не проверяем доступ — вернём как есть */ /* если путь относительный, не проверяем доступ — вернём как есть */
if (access(setting, R_OK) == 0) { snprintf(out, out_sz, "%s", setting); return 0; } if (access(setting, R_OK) == 0) { snprintf(out, out_sz, "%s", setting); return 0; }
/* если задан явно но не доступен — ошибка */ /* если задан явно но не доступен — ошибка */
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: model_path from setting not accessible: %s", CW_ID, setting); DEBUG_WARN(DEBUG_CATEGORY_CHAT, "%s: model_path from setting not accessible: %s", CW_ID, setting);
} }
const char* search_paths[] = { const char* search_paths[] = {
@ -402,31 +402,31 @@ int chat_whisper_init(void) {
g_initialized = 1; g_initialized = 1;
#ifndef HAVE_WHISPER #ifndef HAVE_WHISPER
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: compiled without whisper support", CW_ID); DEBUG_WARN(DEBUG_CATEGORY_CHAT, "%s: compiled without whisper support", CW_ID);
return -1; return -1;
#else #else
if (!chat_setting_get_int("whisper_enabled", 0)) { if (!chat_setting_get_int("whisper_enabled", 0)) {
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: whisper disabled in settings", CW_ID); DEBUG_INFO(DEBUG_CATEGORY_CHAT, "%s: whisper disabled in settings", CW_ID);
return -1; return -1;
} }
char model_path[512]; char model_path[512];
if (find_model_path(model_path, sizeof(model_path)) != 0) { if (find_model_path(model_path, sizeof(model_path)) != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: model not found (set whisper_model_path)", CW_ID); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: model not found (set whisper_model_path)", CW_ID);
return -1; return -1;
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: loading model %s..." , CW_ID, model_path); DEBUG_INFO(DEBUG_CATEGORY_CHAT, "%s: loading model %s..." , CW_ID, model_path);
struct whisper_context_params cparams = whisper_context_default_params(); struct whisper_context_params cparams = whisper_context_default_params();
cparams.use_gpu = 0; cparams.use_gpu = 0;
g_whisper_ctx = whisper_init_from_file_with_params(model_path, cparams); g_whisper_ctx = whisper_init_from_file_with_params(model_path, cparams);
if (!g_whisper_ctx) { if (!g_whisper_ctx) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: whisper_init_from_file failed for %s", CW_ID, model_path); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: whisper_init_from_file failed for %s", CW_ID, model_path);
return -1; return -1;
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: model loaded successfully", CW_ID); DEBUG_INFO(DEBUG_CATEGORY_CHAT, "%s: model loaded successfully", CW_ID);
g_chat_whisper_trigger = chat_whisper_transcribe_async; g_chat_whisper_trigger = chat_whisper_transcribe_async;
return 0; return 0;
#endif /* HAVE_WHISPER */ #endif /* HAVE_WHISPER */
@ -445,7 +445,7 @@ void chat_whisper_destroy(void) {
if (g_whisper_ctx) { if (g_whisper_ctx) {
whisper_free(g_whisper_ctx); whisper_free(g_whisper_ctx);
g_whisper_ctx = NULL; g_whisper_ctx = NULL;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: model unloaded", CW_ID); DEBUG_INFO(DEBUG_CATEGORY_CHAT, "%s: model unloaded", CW_ID);
} }
#endif #endif
/* отменяем ожидающие задачи */ /* отменяем ожидающие задачи */
@ -472,7 +472,7 @@ static void chat_whisper_transcribe_async_impl(
chat_whisper_done_fn done_cb, void* done_arg) chat_whisper_done_fn done_cb, void* done_arg)
{ {
if (!audio_path || !channel_id || !done_cb || !ma || !ua) { if (!audio_path || !channel_id || !done_cb || !ma || !ua) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "%s: invalid args", CW_ID); DEBUG_ERROR(DEBUG_CATEGORY_CHAT, "%s: invalid args", CW_ID);
if (done_cb) done_cb(done_arg, channel_id ? channel_id : "", NULL, -1, reply_to_ts, reply_to_node); if (done_cb) done_cb(done_arg, channel_id ? channel_id : "", NULL, -1, reply_to_ts, reply_to_node);
return; return;
} }
@ -480,7 +480,7 @@ static void chat_whisper_transcribe_async_impl(
if (!chat_whisper_available()) { if (!chat_whisper_available()) {
int rc = chat_whisper_init(); int rc = chat_whisper_init();
if (rc != 0) { if (rc != 0) {
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: whisper not available, skip transcription", CW_ID); DEBUG_WARN(DEBUG_CATEGORY_CHAT, "%s: whisper not available, skip transcription", CW_ID);
done_cb(done_arg, channel_id, NULL, -1, reply_to_ts, reply_to_node); done_cb(done_arg, channel_id, NULL, -1, reply_to_ts, reply_to_node);
return; return;
} }
@ -499,7 +499,7 @@ static void chat_whisper_transcribe_async_impl(
g_pending_job->done_arg = done_arg; g_pending_job->done_arg = done_arg;
g_pending_job->ma = ma; g_pending_job->ma = ma;
g_pending_job->ua = ua; g_pending_job->ua = ua;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: queued transcription for ch=%s", CW_ID, channel_id); DEBUG_DEBUG(DEBUG_CATEGORY_CHAT, "%s: queued transcription for ch=%s", CW_ID, channel_id);
return; return;
} }
@ -519,6 +519,6 @@ static void chat_whisper_transcribe_async_impl(
w->ua = ua; w->ua = ua;
w->err = 0; w->err = 0;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: starting transcription ch=%s file=%s", CW_ID, channel_id, audio_path); DEBUG_INFO(DEBUG_CATEGORY_CHAT, "%s: starting transcription ch=%s file=%s", CW_ID, channel_id, audio_path);
media_async_submit(ma, ua, wh_work_fn, w, wh_done_fn, w); media_async_submit(ma, ua, wh_work_fn, w, wh_done_fn, w);
} }

20
src/media_async/media_async.c
Unescape View File

@ -42,7 +42,7 @@ struct media_async* media_async_create(void) {
struct media_async* ma = u_malloc(sizeof(*ma)); struct media_async* ma = u_malloc(sizeof(*ma));
if (!ma) return NULL; if (!ma) return NULL;
ma->initialized = 1; ma->initialized = 1;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "media_async: created"); DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "media_async: created");
return ma; return ma;
} }
@ -50,7 +50,7 @@ void media_async_destroy(struct media_async* ma) {
if (!ma) return; if (!ma) return;
ma->initialized = 0; ma->initialized = 0;
u_free(ma); u_free(ma);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "media_async: destroyed"); DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "media_async: destroyed");
} }
void media_async_submit(struct media_async* ma, struct UASYNC* ua, void media_async_submit(struct media_async* ma, struct UASYNC* ua,
@ -71,7 +71,7 @@ void media_async_submit(struct media_async* ma, struct UASYNC* ua,
pthread_t tid; pthread_t tid;
int rc = pthread_create(&tid, NULL, ma_thread_entry, ctx); int rc = pthread_create(&tid, NULL, ma_thread_entry, ctx);
if (rc != 0) { if (rc != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_async: pthread_create failed rc=%d", rc); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_async: pthread_create failed rc=%d", rc);
u_free(ctx); u_free(ctx);
done(arg, -1); done(arg, -1);
return; return;
@ -83,7 +83,7 @@ void media_async_submit(struct media_async* ma, struct UASYNC* ua,
int ma_sha256_file(const char* path, uint8_t hash_out[32]) { int ma_sha256_file(const char* path, uint8_t hash_out[32]) {
FILE* f = fopen(path, "rb"); FILE* f = fopen(path, "rb");
if (!f) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_sha256_file: cannot open %s", path); return -1; } if (!f) { DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_sha256_file: cannot open %s", path); return -1; }
SHA256_CTX ctx; SHA256_CTX ctx;
SHA256_Init(&ctx); SHA256_Init(&ctx);
@ -99,13 +99,13 @@ int ma_sha256_file(const char* path, uint8_t hash_out[32]) {
int ma_sign_block(const uint8_t* ed25519_privkey, const uint8_t* data, size_t len, uint8_t sig_out[64]) { int ma_sign_block(const uint8_t* ed25519_privkey, const uint8_t* data, size_t len, uint8_t sig_out[64]) {
EVP_PKEY* pkey = EVP_PKEY_new_raw_private_key(EVP_PKEY_ED25519, NULL, ed25519_privkey, 32); EVP_PKEY* pkey = EVP_PKEY_new_raw_private_key(EVP_PKEY_ED25519, NULL, ed25519_privkey, 32);
if (!pkey) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_sign_block: EVP_PKEY_new_raw_private_key failed"); return -1; } if (!pkey) { DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_sign_block: EVP_PKEY_new_raw_private_key failed"); return -1; }
EVP_MD_CTX* mdctx = EVP_MD_CTX_new(); EVP_MD_CTX* mdctx = EVP_MD_CTX_new();
if (!mdctx) { EVP_PKEY_free(pkey); return -1; } if (!mdctx) { EVP_PKEY_free(pkey); return -1; }
if (EVP_DigestSignInit(mdctx, NULL, NULL, NULL, pkey) != 1) { if (EVP_DigestSignInit(mdctx, NULL, NULL, NULL, pkey) != 1) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_sign_block: EVP_DigestSignInit failed"); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_sign_block: EVP_DigestSignInit failed");
EVP_MD_CTX_free(mdctx); EVP_PKEY_free(pkey); return -1; EVP_MD_CTX_free(mdctx); EVP_PKEY_free(pkey); return -1;
} }
@ -115,7 +115,7 @@ int ma_sign_block(const uint8_t* ed25519_privkey, const uint8_t* data, size_t le
EVP_PKEY_free(pkey); EVP_PKEY_free(pkey);
if (rc != 1 || siglen != 64) { if (rc != 1 || siglen != 64) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_sign_block: EVP_DigestSign failed rc=%d len=%zu", rc, siglen); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_sign_block: EVP_DigestSign failed rc=%d len=%zu", rc, siglen);
return -1; return -1;
} }
return 0; return 0;
@ -126,16 +126,16 @@ int ma_copy_file(const char* src, const char* dst) {
if (strcmp(src, dst) == 0) return 0; if (strcmp(src, dst) == 0) return 0;
FILE* s = fopen(src, "rb"); FILE* s = fopen(src, "rb");
if (!s) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_copy_file: cannot open src %s", src); return -1; } if (!s) { DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_copy_file: cannot open src %s", src); return -1; }
FILE* d = fopen(dst, "wb"); FILE* d = fopen(dst, "wb");
if (!d) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_copy_file: cannot create dst %s", dst); fclose(s); return -1; } if (!d) { DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_copy_file: cannot create dst %s", dst); fclose(s); return -1; }
uint8_t buf[65536]; uint8_t buf[65536];
size_t rd; size_t rd;
while ((rd = fread(buf, 1, sizeof(buf), s)) > 0) { while ((rd = fread(buf, 1, sizeof(buf), s)) > 0) {
if (fwrite(buf, 1, rd, d) != rd) { if (fwrite(buf, 1, rd, d) != rd) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "ma_copy_file: write error at %s", dst); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "ma_copy_file: write error at %s", dst);
fclose(s); fclose(d); return -1; fclose(s); fclose(d); return -1;
} }
} }

62
src/media_delivery/media_delivery.c
Unescape View File

@ -106,7 +106,7 @@ static int md_ba_complete_block(sqlite3* db, const uint8_t* block_uuid,
int exists = (sqlite3_step(st) == SQLITE_ROW); int exists = (sqlite3_step(st) == SQLITE_ROW);
sqlite3_finalize(st); sqlite3_finalize(st);
if (exists) { if (exists) {
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: ba_complete_block: completed already exists for node=0x%016llx, skipping", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: ba_complete_block: completed already exists for node=0x%016llx, skipping",
MD_ID, (unsigned long long)node_id); MD_ID, (unsigned long long)node_id);
return 0; return 0;
} }
@ -293,7 +293,7 @@ int md_file_load_inc(struct media_delivery_ctx* md, const uint8_t* media_id, uin
if (fl->active_downloads < 10) if (fl->active_downloads < 10)
fl->downloader_ids[fl->active_downloads] = node_id; fl->downloader_ids[fl->active_downloads] = node_id;
fl->active_downloads++; fl->active_downloads++;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: file_load inc media=%02x%02x... node=0x%016llx count=%d", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: file_load inc media=%02x%02x... node=0x%016llx count=%d",
MD_ID, media_id[0], media_id[1], (unsigned long long)node_id, fl->active_downloads); MD_ID, media_id[0], media_id[1], (unsigned long long)node_id, fl->active_downloads);
return fl->active_downloads; return fl->active_downloads;
} }
@ -311,7 +311,7 @@ void md_file_load_dec(struct media_delivery_ctx* md, const uint8_t* media_id, ui
break; break;
} }
} }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: file_load dec media=%02x%02x... node=0x%016llx count=%d", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: file_load dec media=%02x%02x... node=0x%016llx count=%d",
MD_ID, media_id[0], media_id[1], (unsigned long long)node_id, fl->active_downloads); MD_ID, media_id[0], media_id[1], (unsigned long long)node_id, fl->active_downloads);
/* remove entry when count reaches 0 */ /* remove entry when count reaches 0 */
if (fl->active_downloads == 0 && md->file_loads) { if (fl->active_downloads == 0 && md->file_loads) {
@ -386,7 +386,7 @@ static void md_super_repl_send(struct media_delivery_ctx* md, struct media_super
if (md_send(md->inst, TOPO_GROUP_UTUN, peer->peer_node_id, pkt, (size_t)off) == 0) { if (md_send(md->inst, TOPO_GROUP_UTUN, peer->peer_node_id, pkt, (size_t)off) == 0) {
peer->inflight_count++; peer->inflight_count++;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: SUPER_REPL sent to 0x%016llx seq=%u entries=%d", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: SUPER_REPL sent to 0x%016llx seq=%u entries=%d",
MD_ID, (unsigned long long)peer->peer_node_id, seq, num_entries); MD_ID, (unsigned long long)peer->peer_node_id, seq, num_entries);
} else { } else {
DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: SUPER_REPL send failed to 0x%016llx", DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: SUPER_REPL send failed to 0x%016llx",
@ -442,7 +442,7 @@ static void md_handle_serve_reg(struct media_delivery_ctx* md, uint64_t from_nod
uint8_t ack[9] = { MEDIA_SUBCMD_SERVE_ACK, 0, 0 }; uint8_t ack[9] = { MEDIA_SUBCMD_SERVE_ACK, 0, 0 };
memcpy(ack + 1, &pkt->group_id, 8); memcpy(ack + 1, &pkt->group_id, 8);
(void)from_node; (void)from_node;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: SERVE_REG node=0x%016llx group=%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: SERVE_REG node=0x%016llx group=%016llx",
MD_ID, (unsigned long long)from_node, (unsigned long long)pkt->group_id); MD_ID, (unsigned long long)from_node, (unsigned long long)pkt->group_id);
} }
@ -492,7 +492,7 @@ static void md_handle_query(struct media_delivery_ctx* md, uint64_t from_node,
uint16_t nc = (uint16_t)count; uint16_t nc = (uint16_t)count;
memcpy(resp + num_pos, &nc, 2); memcpy(resp + num_pos, &nc, 2);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: QUERY from 0x%016llx → %d entries (super=%d)", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: QUERY from 0x%016llx → %d entries (super=%d)",
MD_ID, (unsigned long long)from_node, count, md->is_supernode); MD_ID, (unsigned long long)from_node, count, md->is_supernode);
md_send(md->inst, TOPO_GROUP_UTUN, from_node, resp, (size_t)off); md_send(md->inst, TOPO_GROUP_UTUN, from_node, resp, (size_t)off);
} }
@ -515,7 +515,7 @@ static void md_handle_have_block(struct media_delivery_ctx* md, uint64_t from_no
md_send(md->inst, TOPO_GROUP_UTUN, from_node, ack, sizeof(ack)); md_send(md->inst, TOPO_GROUP_UTUN, from_node, ack, sizeof(ack));
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: HAVE_BLOCK from 0x%016llx rc=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: HAVE_BLOCK from 0x%016llx rc=%d",
MD_ID, (unsigned long long)from_node, rc); MD_ID, (unsigned long long)from_node, rc);
if (rc == 0) { if (rc == 0) {
@ -541,11 +541,11 @@ static void md_handle_block_processing(struct media_delivery_ctx* md, uint64_t f
/* INSERT processing (status=0) with new id */ /* INSERT processing (status=0) with new id */
int rc = md_ba_insert(md->db, hb->block_id, hb->group_id, from_node, hb->chunk, hb->timestamp, 0); int rc = md_ba_insert(md->db, hb->block_id, hb->group_id, from_node, hb->chunk, hb->timestamp, 0);
if (rc != 0) { if (rc != 0) {
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_PROCESSING insert failed for node=0x%016llx (duplicate/constraint?)", DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_PROCESSING insert failed for node=0x%016llx (duplicate/constraint?)",
MD_ID, (unsigned long long)from_node); MD_ID, (unsigned long long)from_node);
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_PROCESSING from 0x%016llx block=%02x%02x...", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_PROCESSING from 0x%016llx block=%02x%02x...",
MD_ID, (unsigned long long)from_node, hb->block_id[0], hb->block_id[1]); MD_ID, (unsigned long long)from_node, hb->block_id[0], hb->block_id[1]);
/* replicate to connected super-peers */ /* replicate to connected super-peers */
@ -602,7 +602,7 @@ static void md_handle_super_repl(struct media_delivery_ctx* md, uint64_t from_no
sa->ack_seq = (uint32_t)max_id; sa->ack_seq = (uint32_t)max_id;
md_send(md->inst, TOPO_GROUP_UTUN, from_node, ack, sizeof(ack)); md_send(md->inst, TOPO_GROUP_UTUN, from_node, ack, sizeof(ack));
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: SUPER_REPL from 0x%016llx entries=%d max_id=%lld", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: SUPER_REPL from 0x%016llx entries=%d max_id=%lld",
MD_ID, (unsigned long long)from_node, num, (long long)max_id); MD_ID, (unsigned long long)from_node, num, (long long)max_id);
} }
@ -612,13 +612,13 @@ static void md_handle_super_ack(struct media_delivery_ctx* md, uint64_t from_nod
struct media_pkt_super_ack* sa = (struct media_pkt_super_ack*)data; struct media_pkt_super_ack* sa = (struct media_pkt_super_ack*)data;
struct media_super_peer* peer = md_super_peer_find(md, from_node); struct media_super_peer* peer = md_super_peer_find(md, from_node);
if (!peer) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: SUPER_ACK from unknown peer 0x%016llx", MD_ID, (unsigned long long)from_node); return; } if (!peer) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: SUPER_ACK from unknown peer 0x%016llx", MD_ID, (unsigned long long)from_node); return; }
peer->peer_last_recv_id = sa->ack_seq; peer->peer_last_recv_id = sa->ack_seq;
peer->inflight_count--; peer->inflight_count--;
peer->timeout_tb = MEDIA_REPL_TIMEOUT_TB; peer->timeout_tb = MEDIA_REPL_TIMEOUT_TB;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: SUPER_ACK from 0x%016llx seq=%u inflight=%d", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: SUPER_ACK from 0x%016llx seq=%u inflight=%d",
MD_ID, (unsigned long long)from_node, sa->ack_seq, peer->inflight_count); MD_ID, (unsigned long long)from_node, sa->ack_seq, peer->inflight_count);
md_super_repl_send(md, peer); md_super_repl_send(md, peer);
@ -644,7 +644,7 @@ static void md_handle_super_hello(struct media_delivery_ctx* md, uint64_t from_n
resp.last_recv_id = my_last_recv; resp.last_recv_id = my_last_recv;
md_send(md->inst, TOPO_GROUP_UTUN, from_node, (const uint8_t*)&resp, sizeof(resp)); md_send(md->inst, TOPO_GROUP_UTUN, from_node, (const uint8_t*)&resp, sizeof(resp));
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: SUPER_HELLO from 0x%016llx (peer_last_recv=%lld, my_last_recv=%lld)", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: SUPER_HELLO from 0x%016llx (peer_last_recv=%lld, my_last_recv=%lld)",
MD_ID, (unsigned long long)from_node, (long long)sh->last_recv_id, (long long)my_last_recv); MD_ID, (unsigned long long)from_node, (long long)sh->last_recv_id, (long long)my_last_recv);
/* start replication */ /* start replication */
@ -677,7 +677,7 @@ static void md_super_conn_cb(struct CONN_MGR_HANDLE* h, uint64_t node_id, uint64
hello.last_recv_id = my_last; hello.last_recv_id = my_last;
if (md_send(md->inst, TOPO_GROUP_UTUN, node_id, (const uint8_t*)&hello, sizeof(hello)) == 0) { if (md_send(md->inst, TOPO_GROUP_UTUN, node_id, (const uint8_t*)&hello, sizeof(hello)) == 0) {
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: SUPER_HELLO sent to 0x%016llx last_recv=%lld", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: SUPER_HELLO sent to 0x%016llx last_recv=%lld",
MD_ID, (unsigned long long)node_id, (long long)my_last); MD_ID, (unsigned long long)node_id, (long long)my_last);
} else { } else {
DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: SUPER_HELLO send failed to 0x%016llx", DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: SUPER_HELLO send failed to 0x%016llx",
@ -755,7 +755,7 @@ static void stream_send_chunk_cb(struct ll_queue* q, void* arg) {
media_delivery_stream_done(md->inst); media_delivery_stream_done(md->inst);
fclose(sc->file); fclose(sc->file);
u_free(sc); u_free(sc);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_DONE sent chunk=%d total=%u", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_DONE sent chunk=%d total=%u",
MD_ID, sc->chunk, bd->total_size); MD_ID, sc->chunk, bd->total_size);
} else { } else {
/* continue streaming — register waiter for backpressure */ /* continue streaming — register waiter for backpressure */
@ -839,7 +839,7 @@ static void md_handle_block_req(struct media_delivery_ctx* md, uint64_t from_nod
struct media_pkt_block_req* req = (struct media_pkt_block_req*)data; struct media_pkt_block_req* req = (struct media_pkt_block_req*)data;
uint64_t group_id = req->group_id ? req->group_id : TOPO_GROUP_UTUN; uint64_t group_id = req->group_id ? req->group_id : TOPO_GROUP_UTUN;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_REQ from 0x%016llx group=%016llx block=%02x%02x... active_streams=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_REQ from 0x%016llx group=%016llx block=%02x%02x... active_streams=%d",
MD_ID, (unsigned long long)from_node, (unsigned long long)group_id, req->block_id[0], req->block_id[1], md->active_streams); MD_ID, (unsigned long long)from_node, (unsigned long long)group_id, req->block_id[0], req->block_id[1], md->active_streams);
int limit_reached = md->active_streams >= MD_MAX_STREAMS; int limit_reached = md->active_streams >= MD_MAX_STREAMS;
@ -864,7 +864,7 @@ static void md_handle_block_req(struct media_delivery_ctx* md, uint64_t from_nod
struct TOPO_GROUP* grp = topo_groups_find(md->inst->topo_groups, group_id); struct TOPO_GROUP* grp = topo_groups_find(md->inst->topo_groups, group_id);
if (!grp) grp = topo_groups_get_default(md->inst->topo_groups); if (!grp) grp = topo_groups_get_default(md->inst->topo_groups);
if (grp && grp->conn_mgr) { if (grp && grp->conn_mgr) {
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: no direct conn to 0x%016llx — connecting via conn_mgr", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: no direct conn to 0x%016llx — connecting via conn_mgr",
MD_ID, (unsigned long long)from_node); MD_ID, (unsigned long long)from_node);
conn_mgr_open_invite(grp->instance, grp->group_id, NULL, from_node, NULL, NULL, NULL); conn_mgr_open_invite(grp->instance, grp->group_id, NULL, from_node, NULL, NULL, NULL);
} }
@ -889,7 +889,7 @@ static void md_handle_block_req(struct media_delivery_ctx* md, uint64_t from_nod
rc->downstream[dsi].group_id = group_id; rc->downstream[dsi].group_id = group_id;
rc->downstream[dsi].sent_offset = 0; rc->downstream[dsi].sent_offset = 0;
memset(&rc->downstream[dsi].waiter, 0, sizeof(rc->downstream[dsi].waiter)); memset(&rc->downstream[dsi].waiter, 0, sizeof(rc->downstream[dsi].waiter));
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: relay downstream[%d] added node=0x%016llx file_offset=%llu", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: relay downstream[%d] added node=0x%016llx file_offset=%llu",
MD_ID, dsi, (unsigned long long)from_node, (unsigned long long)rc->file_offset); MD_ID, dsi, (unsigned long long)from_node, (unsigned long long)rc->file_offset);
md_relay_catchup(md, rc, from_node, group_id, dsi); md_relay_catchup(md, rc, from_node, group_id, dsi);
md->active_streams--; return; md->active_streams--; return;
@ -907,7 +907,7 @@ static void md_handle_block_req(struct media_delivery_ctx* md, uint64_t from_nod
memcpy(rfp + roff, &rc->downstream[i].node_id, 8); roff += 8; memcpy(rfp + roff, &rc->downstream[i].node_id, 8); roff += 8;
} }
md_send(md->inst, group_id, from_node, rfp, (size_t)roff); md_send(md->inst, group_id, from_node, rfp, (size_t)roff);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: relay full for block=%02x%02x..., sent %d downstream nodes to 0x%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: relay full for block=%02x%02x..., sent %d downstream nodes to 0x%016llx",
MD_ID, req->block_id[0], req->block_id[1], rc->downstream_count, (unsigned long long)from_node); MD_ID, req->block_id[0], req->block_id[1], rc->downstream_count, (unsigned long long)from_node);
} else { } else {
DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: BLOCK_REQ block_id=%02x%02x... not found in media_files", DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: BLOCK_REQ block_id=%02x%02x... not found in media_files",
@ -968,7 +968,7 @@ static void md_handle_block_req(struct media_delivery_ctx* md, uint64_t from_nod
memcpy(rfp + roff, &fl->downloader_ids[i], 8); roff += 8; memcpy(rfp + roff, &fl->downloader_ids[i], 8); roff += 8;
} }
md_send(md->inst, group_id, from_node, rfp, (size_t)roff); md_send(md->inst, group_id, from_node, rfp, (size_t)roff);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: source at capacity (%d/%d) for media=%02x%02x..., redirecting to %d nodes", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: source at capacity (%d/%d) for media=%02x%02x..., redirecting to %d nodes",
MD_ID, fl->active_downloads, md->max_downloads_per_file, MD_ID, fl->active_downloads, md->max_downloads_per_file,
req->media_id[0], req->media_id[1], fl->active_downloads); req->media_id[0], req->media_id[1], fl->active_downloads);
fclose(f); fclose(f);
@ -991,7 +991,7 @@ static void md_handle_block_req(struct media_delivery_ctx* md, uint64_t from_nod
sc->block_start = (uint64_t)block_start; sc->block_start = (uint64_t)block_start;
sc->block_data_len = (size_t)block_length; sc->block_data_len = (size_t)block_length;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: streaming file=%s chunk=%d start=%lld len=%lld group=%016llx to 0x%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: streaming file=%s chunk=%d start=%lld len=%lld group=%016llx to 0x%016llx",
MD_ID, path, chunk, (long long)block_start, (long long)block_length, (unsigned long long)group_id, (unsigned long long)from_node); MD_ID, path, chunk, (long long)block_start, (long long)block_length, (unsigned long long)group_id, (unsigned long long)from_node);
md->streams_started++; /* monotonic — for test admission checks */ md->streams_started++; /* monotonic — for test admission checks */
@ -1009,7 +1009,7 @@ static void md_handle_block_relay_full(struct media_delivery_ctx* md, uint64_t f
uint16_t nrn = rf->num_relay_nodes; uint16_t nrn = rf->num_relay_nodes;
if (nrn > MD_MAX_RELAY_DOWNSTREAM) nrn = MD_MAX_RELAY_DOWNSTREAM; if (nrn > MD_MAX_RELAY_DOWNSTREAM) nrn = MD_MAX_RELAY_DOWNSTREAM;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: RELAY_FULL from 0x%016llx block=%02x%02x... nodes=%u", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: RELAY_FULL from 0x%016llx block=%02x%02x... nodes=%u",
MD_ID, (unsigned long long)from_node, rf->block_id[0], rf->block_id[1], nrn); MD_ID, (unsigned long long)from_node, rf->block_id[0], rf->block_id[1], nrn);
/* forward to media_download layer to retry from one of the listed nodes */ /* forward to media_download layer to retry from one of the listed nodes */
@ -1045,7 +1045,7 @@ static void md_super_connect(struct media_delivery_ctx* md, uint64_t peer_node_i
return; return;
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: connecting to supernode 0x%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: connecting to supernode 0x%016llx",
MD_ID, (unsigned long long)peer_node_id); MD_ID, (unsigned long long)peer_node_id);
conn_mgr_open_invite(grp->instance, grp->group_id, NULL, peer_node_id, md_super_conn_cb, md, NULL); conn_mgr_open_invite(grp->instance, grp->group_id, NULL, peer_node_id, md_super_conn_cb, md, NULL);
} }
@ -1189,7 +1189,7 @@ static void md_etcp_recv(struct ETCP_CONN* conn, struct ll_entry* entry) {
struct UTUN_INSTANCE* inst = conn->instance; struct UTUN_INSTANCE* inst = conn->instance;
if (!inst) return; if (!inst) return;
struct media_delivery_ctx* md = &inst->md; struct media_delivery_ctx* md = &inst->md;
if (!md->initialized) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: recv before init", MD_ID); return; } if (!md->initialized) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: recv before init", MD_ID); return; }
const uint8_t* data = entry->dgram; const uint8_t* data = entry->dgram;
size_t len = entry->len; size_t len = entry->len;
@ -1200,7 +1200,7 @@ static void md_etcp_recv(struct ETCP_CONN* conn, struct ll_entry* entry) {
data += 1; len -= 1; data += 1; len -= 1;
uint64_t from_node = conn->peer_node_id; uint64_t from_node = conn->peer_node_id;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: recv %s(%02x) from 0x%016llx len=%zu", DEBUG_DEBUG(DEBUG_CATEGORY_MEDIA, "%s: recv %s(%02x) from 0x%016llx len=%zu",
MD_ID, md_subcmd_name(subcmd), subcmd, (unsigned long long)from_node, len); MD_ID, md_subcmd_name(subcmd), subcmd, (unsigned long long)from_node, len);
switch (subcmd) { switch (subcmd) {
@ -1208,7 +1208,7 @@ static void md_etcp_recv(struct ETCP_CONN* conn, struct ll_entry* entry) {
md_handle_serve_reg(md, from_node, data, len); md_handle_serve_reg(md, from_node, data, len);
break; break;
case MEDIA_SUBCMD_SERVE_LEAVE: case MEDIA_SUBCMD_SERVE_LEAVE:
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: SERVE_LEAVE from 0x%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: SERVE_LEAVE from 0x%016llx",
MD_ID, (unsigned long long)from_node); MD_ID, (unsigned long long)from_node);
if (md->served_nodes) { if (md->served_nodes) {
struct ll_entry* e = queue_find_data_by_index(md->served_nodes, &from_node); struct ll_entry* e = queue_find_data_by_index(md->served_nodes, &from_node);
@ -1223,19 +1223,19 @@ static void md_etcp_recv(struct ETCP_CONN* conn, struct ll_entry* entry) {
break; break;
case MEDIA_SUBCMD_BLOCK_PROCESSING: case MEDIA_SUBCMD_BLOCK_PROCESSING:
if (md->is_supernode) md_handle_block_processing(md, from_node, data, len); if (md->is_supernode) md_handle_block_processing(md, from_node, data, len);
else DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_PROCESSING ignored — not supernode", MD_ID); else DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_PROCESSING ignored — not supernode", MD_ID);
break; break;
case MEDIA_SUBCMD_SUPER_REPL: case MEDIA_SUBCMD_SUPER_REPL:
if (md->is_supernode) md_handle_super_repl(md, from_node, data, len); if (md->is_supernode) md_handle_super_repl(md, from_node, data, len);
else DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: SUPER_REPL ignored — not supernode", MD_ID); else DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: SUPER_REPL ignored — not supernode", MD_ID);
break; break;
case MEDIA_SUBCMD_SUPER_ACK: case MEDIA_SUBCMD_SUPER_ACK:
if (md->is_supernode) md_handle_super_ack(md, from_node, data, len); if (md->is_supernode) md_handle_super_ack(md, from_node, data, len);
else DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: SUPER_ACK ignored — not supernode", MD_ID); else DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: SUPER_ACK ignored — not supernode", MD_ID);
break; break;
case MEDIA_SUBCMD_SUPER_HELLO: case MEDIA_SUBCMD_SUPER_HELLO:
if (md->is_supernode) md_handle_super_hello(md, from_node, data, len); if (md->is_supernode) md_handle_super_hello(md, from_node, data, len);
else DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: SUPER_HELLO ignored — not supernode", MD_ID); else DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: SUPER_HELLO ignored — not supernode", MD_ID);
break; break;
case MEDIA_SUBCMD_QUERY_RESP: case MEDIA_SUBCMD_QUERY_RESP:
media_download_handle_query_resp(inst, data, len); media_download_handle_query_resp(inst, data, len);
@ -1264,7 +1264,7 @@ static void md_etcp_recv(struct ETCP_CONN* conn, struct ll_entry* entry) {
/* TODO: handle cancel from remote */ /* TODO: handle cancel from remote */
break; break;
default: default:
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: unknown subcmd 0x%02x from 0x%016llx", DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: unknown subcmd 0x%02x from 0x%016llx",
MD_ID, subcmd, (unsigned long long)from_node); MD_ID, subcmd, (unsigned long long)from_node);
} }
} }

56
src/media_delivery/media_download.c
Unescape View File

@ -86,7 +86,7 @@ static int md_dl_send_block_req(struct UTUN_INSTANCE* inst, uint64_t dst,
req.chunk = (uint32_t)chunk_idx; req.chunk = (uint32_t)chunk_idx;
req.offset = 0; req.offset = 0;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_REQ to 0x%016llx group=%016llx bi=%d dl->num_blocks=%d block_id=%02x%02x%02x%02x...", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_REQ to 0x%016llx group=%016llx bi=%d dl->num_blocks=%d block_id=%02x%02x%02x%02x...",
MDL_ID, (unsigned long long)dst, (unsigned long long)dl->group_id, peer_local_bi, dl->num_blocks, MDL_ID, (unsigned long long)dst, (unsigned long long)dl->group_id, peer_local_bi, dl->num_blocks,
block_id[0], block_id[1], block_id[2], block_id[3]); block_id[0], block_id[1], block_id[2], block_id[3]);
return md_dl_send(inst, dst, (const uint8_t*)&req, sizeof(req)); return md_dl_send(inst, dst, (const uint8_t*)&req, sizeof(req));
@ -142,7 +142,7 @@ static void md_dl_send_have_block(struct UTUN_INSTANCE* inst, struct media_downl
return; return;
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: HAVE_BLOCK to super 0x%016llx block=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: HAVE_BLOCK to super 0x%016llx block=%d",
MDL_ID, (unsigned long long)super, bi); MDL_ID, (unsigned long long)super, bi);
md_dl_send(inst, super, (const uint8_t*)&hb, sizeof(hb)); md_dl_send(inst, super, (const uint8_t*)&hb, sizeof(hb));
} }
@ -172,7 +172,7 @@ static void md_dl_send_block_processing(struct UTUN_INSTANCE* inst, struct media
return; return;
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_PROCESSING to super 0x%016llx block=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_PROCESSING to super 0x%016llx block=%d",
MDL_ID, (unsigned long long)super, bi); MDL_ID, (unsigned long long)super, bi);
md_dl_send(inst, super, (const uint8_t*)&hb, sizeof(hb)); md_dl_send(inst, super, (const uint8_t*)&hb, sizeof(hb));
} }
@ -182,7 +182,7 @@ static void md_dl_send_block_processing(struct UTUN_INSTANCE* inst, struct media
void md_dl_conn_cb(struct CONN_MGR_HANDLE* h, uint64_t node_id, uint64_t group_id, void md_dl_conn_cb(struct CONN_MGR_HANDLE* h, uint64_t node_id, uint64_t group_id,
enum conn_mgr_event event, void* arg) { enum conn_mgr_event event, void* arg) {
struct media_download* dl = (struct media_download*)arg; struct media_download* dl = (struct media_download*)arg;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: conn_cb event=%d node=0x%016llx dl=%p active=%d num_peers=%d num_blocks=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: conn_cb event=%d node=0x%016llx dl=%p active=%d num_peers=%d num_blocks=%d",
MDL_ID, event, (unsigned long long)node_id, (void*)dl, dl->active, dl->num_peers, dl->num_blocks); MDL_ID, event, (unsigned long long)node_id, (void*)dl, dl->active, dl->num_peers, dl->num_blocks);
if (event != CONN_EVENT_UP) { if (event != CONN_EVENT_UP) {
DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "%s: connect to 0x%016llx failed rc=%d", DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "%s: connect to 0x%016llx failed rc=%d",
@ -194,12 +194,12 @@ void md_dl_conn_cb(struct CONN_MGR_HANDLE* h, uint64_t node_id, uint64_t group_i
if (dl->peers[pi].node_id == node_id) { if (dl->peers[pi].node_id == node_id) {
dl->peers[pi].connected = 1; dl->peers[pi].connected = 1;
dl->peers[pi].cm_handle = h; /* store for close on completion */ dl->peers[pi].cm_handle = h; /* store for close on completion */
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: matched peer[%d] num_blocks=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: matched peer[%d] num_blocks=%d",
MDL_ID, pi, dl->peers[pi].num_blocks); MDL_ID, pi, dl->peers[pi].num_blocks);
for (int bi = 0; bi < dl->peers[pi].num_blocks; bi++) { for (int bi = 0; bi < dl->peers[pi].num_blocks; bi++) {
if (!dl->peers[pi].blocks[bi].started) { if (!dl->peers[pi].blocks[bi].started) {
dl->peers[pi].blocks[bi].started = 1; dl->peers[pi].blocks[bi].started = 1;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: conn_cb BLOCK_REQ: peer-local bi=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: conn_cb BLOCK_REQ: peer-local bi=%d",
MDL_ID, bi); MDL_ID, bi);
md_dl_start_block(dl->inst, node_id, dl, dl->peers[pi].blocks[bi].block_id, bi, bi); md_dl_start_block(dl->inst, node_id, dl, dl->peers[pi].blocks[bi].block_id, bi, bi);
break; break;
@ -264,7 +264,7 @@ static void md_dl_send_query(struct UTUN_INSTANCE* inst, struct media_download*
q->num_blocks = (uint16_t)dl->num_blocks; q->num_blocks = (uint16_t)dl->num_blocks;
memcpy(pkt + MEDIA_QUERY_HDR_SIZE, dl->block_ids, (size_t)dl->num_blocks * 16); memcpy(pkt + MEDIA_QUERY_HDR_SIZE, dl->block_ids, (size_t)dl->num_blocks * 16);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: QUERY to super 0x%016llx blocks=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: QUERY to super 0x%016llx blocks=%d",
MDL_ID, (unsigned long long)super, dl->num_blocks); MDL_ID, (unsigned long long)super, dl->num_blocks);
md_dl_send(inst, super, pkt, pkt_len); md_dl_send(inst, super, pkt, pkt_len);
u_free(pkt); u_free(pkt);
@ -295,7 +295,7 @@ void media_download_handle_query_resp(struct UTUN_INSTANCE* inst,
qe = qe->next; qe = qe->next;
} }
} }
if (!dl) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: QUERY_RESP — no matching download", MDL_ID); return; } if (!dl) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: QUERY_RESP — no matching download", MDL_ID); return; }
dl->num_peers = 0; dl->num_peers = 0;
@ -320,16 +320,16 @@ void media_download_handle_query_resp(struct UTUN_INSTANCE* inst,
} }
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: QUERY_RESP entries=%d peers=%d dl=%p num_blocks=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: QUERY_RESP entries=%d peers=%d dl=%p num_blocks=%d",
MDL_ID, ne, dl->num_peers, (void*)dl, dl->num_blocks); MDL_ID, ne, dl->num_peers, (void*)dl, dl->num_blocks);
for (int pi = 0; pi < dl->num_peers; pi++) { for (int pi = 0; pi < dl->num_peers; pi++) {
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: peer[%d] node=0x%016llx num_blocks=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: peer[%d] node=0x%016llx num_blocks=%d",
MDL_ID, pi, (unsigned long long)dl->peers[pi].node_id, dl->peers[pi].num_blocks); MDL_ID, pi, (unsigned long long)dl->peers[pi].node_id, dl->peers[pi].num_blocks);
} }
/* if no peers found, try querying the author directly */ /* if no peers found, try querying the author directly */
if (dl->num_peers == 0 && dl->author_node_id && dl->author_node_id != inst->node_id) { if (dl->num_peers == 0 && dl->author_node_id && dl->author_node_id != inst->node_id) {
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: no holders from supernode, querying author 0x%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: no holders from supernode, querying author 0x%016llx",
MDL_ID, (unsigned long long)dl->author_node_id); MDL_ID, (unsigned long long)dl->author_node_id);
dl->super_nodes[0] = dl->author_node_id; dl->super_nodes[0] = dl->author_node_id;
dl->super_count = 1; dl->super_count = 1;
@ -349,14 +349,14 @@ void media_download_handle_query_resp(struct UTUN_INSTANCE* inst,
for (int pi = 0; pi < dl->num_peers; pi++) { for (int pi = 0; pi < dl->num_peers; pi++) {
dl->peers[pi].connected = 1; dl->peers[pi].connected = 1;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: peer[%d] route: grp=%p conn_mgr=%p", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: peer[%d] route: grp=%p conn_mgr=%p",
MDL_ID, pi, (void*)grp, grp ? (void*)grp->conn_mgr : NULL); MDL_ID, pi, (void*)grp, grp ? (void*)grp->conn_mgr : NULL);
if (grp && grp->conn_mgr) { if (grp && grp->conn_mgr) {
int cm_rc = conn_mgr_open_invite(inst, grp->group_id, NULL, dl->peers[pi].node_id, md_dl_conn_cb, dl, NULL); int cm_rc = conn_mgr_open_invite(inst, grp->group_id, NULL, dl->peers[pi].node_id, md_dl_conn_cb, dl, NULL);
if (cm_rc != 0) DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: conn_mgr_open_invite failed rc=%d for 0x%016llx", MDL_ID, cm_rc, (unsigned long long)dl->peers[pi].node_id); if (cm_rc != 0) DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "%s: conn_mgr_open_invite failed rc=%d for 0x%016llx", MDL_ID, cm_rc, (unsigned long long)dl->peers[pi].node_id);
} else } else
for (int bi = 0; bi < dl->peers[pi].num_blocks; bi++) { for (int bi = 0; bi < dl->peers[pi].num_blocks; bi++) {
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: direct BLOCK_REQ: peer-local bi=%d peer_num_blocks=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: direct BLOCK_REQ: peer-local bi=%d peer_num_blocks=%d",
MDL_ID, bi, dl->peers[pi].num_blocks); MDL_ID, bi, dl->peers[pi].num_blocks);
md_dl_start_block(inst, dl->peers[pi].node_id, dl, dl->peers[pi].blocks[bi].block_id, bi, bi); md_dl_start_block(inst, dl->peers[pi].node_id, dl, dl->peers[pi].blocks[bi].block_id, bi, bi);
} }
@ -372,14 +372,14 @@ void media_download_handle_chunk(struct UTUN_INSTANCE* inst,
const uint8_t* d = data; const uint8_t* d = data;
struct media_pkt_block_chunk* ch = (struct media_pkt_block_chunk*)data; struct media_pkt_block_chunk* ch = (struct media_pkt_block_chunk*)data;
struct media_download* dl = md_dl_find(inst, ch->media_id); struct media_download* dl = md_dl_find(inst, ch->media_id);
if (!dl) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: CHUNK for unknown media %02x%02x...", MDL_ID, ch->media_id[0], ch->media_id[1]); return; } if (!dl) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: CHUNK for unknown media %02x%02x...", MDL_ID, ch->media_id[0], ch->media_id[1]); return; }
if (!dl->active) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: CHUNK for inactive download", MDL_ID); return; } if (!dl->active) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: CHUNK for inactive download", MDL_ID); return; }
int bi = -1; int bi = -1;
for (int i = 0; i < dl->num_blocks; i++) { for (int i = 0; i < dl->num_blocks; i++) {
if (memcmp(dl->block_ids + i * 16, ch->block_id, 16) == 0) { bi = i; break; } if (memcmp(dl->block_ids + i * 16, ch->block_id, 16) == 0) { bi = i; break; }
} }
if (bi < 0) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: CHUNK for unknown block %02x%02x...", MDL_ID, ch->block_id[0], ch->block_id[1]); return; } if (bi < 0) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: CHUNK for unknown block %02x%02x...", MDL_ID, ch->block_id[0], ch->block_id[1]); return; }
char tmp[2048]; char tmp[2048];
snprintf(tmp, sizeof(tmp), "%s.chunk_%d", dl->dest_path, bi); snprintf(tmp, sizeof(tmp), "%s.chunk_%d", dl->dest_path, bi);
@ -389,7 +389,7 @@ void media_download_handle_chunk(struct UTUN_INSTANCE* inst,
if (len >= MEDIA_BLOCK_CHUNK_HDR_SIZE + wlen) { if (len >= MEDIA_BLOCK_CHUNK_HDR_SIZE + wlen) {
fwrite(d + MEDIA_BLOCK_CHUNK_HDR_SIZE, 1, wlen, f); fwrite(d + MEDIA_BLOCK_CHUNK_HDR_SIZE, 1, wlen, f);
} else { } else {
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: CHUNK truncated: len=%zu need=%zu+%zu", DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: CHUNK truncated: len=%zu need=%zu+%zu",
MDL_ID, len, (size_t)MEDIA_BLOCK_CHUNK_HDR_SIZE, (size_t)wlen); MDL_ID, len, (size_t)MEDIA_BLOCK_CHUNK_HDR_SIZE, (size_t)wlen);
} }
fclose(f); fclose(f);
@ -439,14 +439,14 @@ void media_download_handle_done(struct UTUN_INSTANCE* inst,
const uint8_t* d = data; const uint8_t* d = data;
struct media_pkt_block_done* bd = (struct media_pkt_block_done*)data; struct media_pkt_block_done* bd = (struct media_pkt_block_done*)data;
struct media_download* dl = md_dl_find(inst, bd->media_id); struct media_download* dl = md_dl_find(inst, bd->media_id);
if (!dl) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_DONE for unknown media", MDL_ID); return; } if (!dl) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_DONE for unknown media", MDL_ID); return; }
if (!dl->active) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_DONE for inactive download", MDL_ID); return; } if (!dl->active) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_DONE for inactive download", MDL_ID); return; }
int bi = -1; int bi = -1;
for (int i = 0; i < dl->num_blocks; i++) { for (int i = 0; i < dl->num_blocks; i++) {
if (memcmp(dl->block_ids + i * 16, bd->block_id, 16) == 0) { bi = i; break; } if (memcmp(dl->block_ids + i * 16, bd->block_id, 16) == 0) { bi = i; break; }
} }
if (bi < 0) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_DONE for unknown block", MDL_ID); return; } if (bi < 0) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_DONE for unknown block", MDL_ID); return; }
/* verify block data: Ed25519 signature from author, or size-only fallback */ /* verify block data: Ed25519 signature from author, or size-only fallback */
int sig_ok = 0; int sig_ok = 0;
@ -492,7 +492,7 @@ void media_download_handle_done(struct UTUN_INSTANCE* inst,
if (sig_ok) { if (sig_ok) {
dl->blocks_received++; dl->blocks_received++;
dl->blocks_validated++; dl->blocks_validated++;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_DONE block=%d total=%d/%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_DONE block=%d total=%d/%d",
MDL_ID, bi, dl->blocks_validated, dl->num_blocks); MDL_ID, bi, dl->blocks_validated, dl->num_blocks);
if (dl->progress_cb) dl->progress_cb(dl->progress_arg, dl->blocks_validated, dl->num_blocks); if (dl->progress_cb) dl->progress_cb(dl->progress_arg, dl->blocks_validated, dl->num_blocks);
@ -513,7 +513,7 @@ void media_download_handle_done(struct UTUN_INSTANCE* inst,
rd.chunk = (uint32_t)bi; rd.chunk = (uint32_t)bi;
rd.total_size = (uint32_t)rc->file_offset; rd.total_size = (uint32_t)rc->file_offset;
md_dl_send(inst, rc->downstream[i].node_id, (const uint8_t*)&rd, sizeof(rd)); md_dl_send(inst, rc->downstream[i].node_id, (const uint8_t*)&rd, sizeof(rd));
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: relay BLOCK_DONE forwarded to 0x%016llx block=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: relay BLOCK_DONE forwarded to 0x%016llx block=%d",
MDL_ID, (unsigned long long)rc->downstream[i].node_id, bi); MDL_ID, (unsigned long long)rc->downstream[i].node_id, bi);
} }
md_relay_remove(&inst->md, dl->block_ids + bi * 16); md_relay_remove(&inst->md, dl->block_ids + bi * 16);
@ -527,7 +527,7 @@ void media_download_handle_done(struct UTUN_INSTANCE* inst,
for (int bk = 0; bk < dl->peers[pi].num_blocks; bk++) { for (int bk = 0; bk < dl->peers[pi].num_blocks; bk++) {
if (!dl->peers[pi].blocks[bk].started) { if (!dl->peers[pi].blocks[bk].started) {
dl->peers[pi].blocks[bk].started = 1; dl->peers[pi].blocks[bk].started = 1;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: BLOCK_DONE → next req: peer[%d] bi=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: BLOCK_DONE → next req: peer[%d] bi=%d",
MDL_ID, pi, bk); MDL_ID, pi, bk);
md_dl_start_block(inst, dl->peers[pi].node_id, dl, md_dl_start_block(inst, dl->peers[pi].node_id, dl,
dl->peers[pi].blocks[bk].block_id, bk, bk); dl->peers[pi].blocks[bk].block_id, bk, bk);
@ -712,13 +712,13 @@ void media_download_handle_relay_full(struct UTUN_INSTANCE* inst,
const uint8_t* media_id, const uint8_t* block_id, const uint8_t* media_id, const uint8_t* block_id,
uint32_t chunk, const uint64_t* node_ids, int num_nodes) { uint32_t chunk, const uint64_t* node_ids, int num_nodes) {
struct media_download* dl = md_dl_find(inst, media_id); struct media_download* dl = md_dl_find(inst, media_id);
if (!dl || !dl->active) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: RELAY_FULL — no active download", MDL_ID); return; } if (!dl || !dl->active) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: RELAY_FULL — no active download", MDL_ID); return; }
int bi = -1; int bi = -1;
for (int i = 0; i < dl->num_blocks; i++) { for (int i = 0; i < dl->num_blocks; i++) {
if (memcmp(dl->block_ids + i * 16, block_id, 16) == 0) { bi = i; break; } if (memcmp(dl->block_ids + i * 16, block_id, 16) == 0) { bi = i; break; }
} }
if (bi < 0) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: RELAY_FULL — unknown block", MDL_ID); return; } if (bi < 0) { DEBUG_WARN(DEBUG_CATEGORY_MEDIA, "%s: RELAY_FULL — unknown block", MDL_ID); return; }
/* try each listed node — if already a peer, retry block; otherwise add new */ /* try each listed node — if already a peer, retry block; otherwise add new */
for (int ni = 0; ni < num_nodes && ni < MD_MAX_RELAY_DOWNSTREAM; ni++) { for (int ni = 0; ni < num_nodes && ni < MD_MAX_RELAY_DOWNSTREAM; ni++) {
@ -732,7 +732,7 @@ void media_download_handle_relay_full(struct UTUN_INSTANCE* inst,
if (memcmp(dl->peers[found_pi].blocks[bj].block_id, block_id, 16) == 0) { if (memcmp(dl->peers[found_pi].blocks[bj].block_id, block_id, 16) == 0) {
dl->peers[found_pi].blocks[bj].started = 0; dl->peers[found_pi].blocks[bj].started = 0;
dl->peers[found_pi].blocks[bj].received = 0; dl->peers[found_pi].blocks[bj].received = 0;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: RELAY_FULL → retry existing peer[%d] node=0x%016llx bi=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: RELAY_FULL → retry existing peer[%d] node=0x%016llx bi=%d",
MDL_ID, found_pi, (unsigned long long)node_ids[ni], bj); MDL_ID, found_pi, (unsigned long long)node_ids[ni], bj);
md_dl_start_block(inst, node_ids[ni], dl, block_id, (int)chunk, bj); md_dl_start_block(inst, node_ids[ni], dl, block_id, (int)chunk, bj);
return; return;
@ -746,7 +746,7 @@ void media_download_handle_relay_full(struct UTUN_INSTANCE* inst,
dl->peers[found_pi].blocks[nb].received = 0; dl->peers[found_pi].blocks[nb].received = 0;
dl->peers[found_pi].blocks[nb].validated = 0; dl->peers[found_pi].blocks[nb].validated = 0;
dl->peers[found_pi].num_blocks++; dl->peers[found_pi].num_blocks++;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: RELAY_FULL → add block to existing peer[%d] bi=%d", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: RELAY_FULL → add block to existing peer[%d] bi=%d",
MDL_ID, found_pi, nb); MDL_ID, found_pi, nb);
md_dl_start_block(inst, node_ids[ni], dl, block_id, (int)chunk, nb); md_dl_start_block(inst, node_ids[ni], dl, block_id, (int)chunk, nb);
return; return;
@ -762,7 +762,7 @@ void media_download_handle_relay_full(struct UTUN_INSTANCE* inst,
dl->peers[pi].blocks[0].received = 0; dl->peers[pi].blocks[0].received = 0;
dl->peers[pi].blocks[0].validated = 0; dl->peers[pi].blocks[0].validated = 0;
dl->num_peers++; dl->num_peers++;
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: RELAY_FULL → new peer[%d] node=0x%016llx", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "%s: RELAY_FULL → new peer[%d] node=0x%016llx",
MDL_ID, pi, (unsigned long long)node_ids[ni]); MDL_ID, pi, (unsigned long long)node_ids[ni]);
md_dl_start_block(inst, node_ids[ni], dl, block_id, (int)chunk, 0); md_dl_start_block(inst, node_ids[ni], dl, block_id, (int)chunk, 0);
break; break;

18
src/media_delivery/media_index.c
Unescape View File

@ -30,7 +30,7 @@ static int mi_insert(sqlite3* db,
sqlite3_stmt* stmt = NULL; sqlite3_stmt* stmt = NULL;
if (sqlite3_prepare_v2(db, sql, -1, &stmt, NULL) != SQLITE_OK) { if (sqlite3_prepare_v2(db, sql, -1, &stmt, NULL) != SQLITE_OK) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: insert prep fail: %s", sqlite3_errmsg(db)); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: insert prep fail: %s", sqlite3_errmsg(db));
return -1; return -1;
} }
sqlite3_bind_blob(stmt, 1, media_id, 16, SQLITE_STATIC); sqlite3_bind_blob(stmt, 1, media_id, 16, SQLITE_STATIC);
@ -50,7 +50,7 @@ static int mi_insert(sqlite3* db,
sqlite3_finalize(stmt); sqlite3_finalize(stmt);
if (rc != SQLITE_DONE) { if (rc != SQLITE_DONE) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: insert fail rc=%d: %s", rc, sqlite3_errmsg(db)); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: insert fail rc=%d: %s", rc, sqlite3_errmsg(db));
return -1; return -1;
} }
return 0; return 0;
@ -78,7 +78,7 @@ int media_index_init(sqlite3* db) {
char* err = NULL; char* err = NULL;
int rc = sqlite3_exec(db, sql, NULL, NULL, &err); int rc = sqlite3_exec(db, sql, NULL, NULL, &err);
if (rc != SQLITE_OK) { if (rc != SQLITE_OK) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: CREATE TABLE failed: %s", err ? err : "?"); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: CREATE TABLE failed: %s", err ? err : "?");
sqlite3_free(err); sqlite3_free(err);
return -1; return -1;
} }
@ -99,7 +99,7 @@ int media_index_init(sqlite3* db) {
"CREATE INDEX IF NOT EXISTS idx_media_files_content_hash ON media_files(content_hash);", "CREATE INDEX IF NOT EXISTS idx_media_files_content_hash ON media_files(content_hash);",
NULL, NULL, NULL); NULL, NULL, NULL);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "media_index: table+indices created"); DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "media_index: table+indices created");
return 0; return 0;
} }
@ -157,19 +157,19 @@ int media_index_commit(sqlite3* db, const struct media_index_result* result,
uint8_t node_sign[64]; uint8_t node_sign[64];
if (ma_sign_block(ed25519_privkey, sig_msg, soff, node_sign) != 0) { if (ma_sign_block(ed25519_privkey, sig_msg, soff, node_sign) != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: node_sign failed chunk=%d", n); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: node_sign failed chunk=%d", n);
return -1; return -1;
} }
if (mi_insert(db, result->media_id, result->block_ids + n * 16, if (mi_insert(db, result->media_id, result->block_ids + n * 16,
result->content_hash, chat_id, location, result->content_hash, chat_id, location,
node_id, node_sign, ts, fs, cs, n, off) != 0) { node_id, node_sign, ts, fs, cs, n, off) != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: insert failed chunk=%d", n); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: insert failed chunk=%d", n);
return -1; return -1;
} }
} }
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "media_index: committed %d chunks for chat=%s path=%s", DEBUG_INFO(DEBUG_CATEGORY_MEDIA, "media_index: committed %d chunks for chat=%s path=%s",
nb, chat_id, rel); nb, chat_id, rel);
return 0; return 0;
} }
@ -199,7 +199,7 @@ static void mi_reg_work(void* data) {
struct mi_reg_ctx* ctx = (struct mi_reg_ctx*)data; struct mi_reg_ctx* ctx = (struct mi_reg_ctx*)data;
if (ctx->copy_file && ma_copy_file(ctx->src_path, ctx->dest_path) != 0) { if (ctx->copy_file && ma_copy_file(ctx->src_path, ctx->dest_path) != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: copy failed %s -> %s", ctx->src_path, ctx->dest_path); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: copy failed %s -> %s", ctx->src_path, ctx->dest_path);
ctx->err = -10; return; ctx->err = -10; return;
} }
@ -272,7 +272,7 @@ void media_index_register_async(
void* cb_arg) { void* cb_arg) {
if (!ma || !ua || !db || !ed25519_privkey || !chat_id || !src_path || !dest_path || !media_base || !cb) { if (!ma || !ua || !db || !ed25519_privkey || !chat_id || !src_path || !dest_path || !media_base || !cb) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "media_index: register_async invalid args"); DEBUG_ERROR(DEBUG_CATEGORY_MEDIA, "media_index: register_async invalid args");
if (cb) cb(cb_arg, -1, NULL); if (cb) cb(cb_arg, -1, NULL);
return; return;
} }

2
src/routing_layer/conn_mgr_core.c
Unescape View File

@ -1052,7 +1052,7 @@ inv_cancel_free:
void cm_invite_fail(struct cm_invite_pending* inv) { void cm_invite_fail(struct cm_invite_pending* inv) {
if (!inv) return; if (!inv) return;
if (inv->cancelled) { DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "cm_invite_fail: IGNORED — already cancelled node=0x%016llx", (unsigned long long)inv->node_id); return; } if (inv->cancelled) { DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "cm_invite_fail: IGNORED — already cancelled node=0x%016llx", (unsigned long long)inv->node_id); return; }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "cm_invite_fail: node=0x%016llx state=%d conn=%p", DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "cm_invite_fail: node=0x%016llx state=%d conn=%p",
(unsigned long long)inv->node_id, (int)inv->state, (unsigned long long)inv->node_id, (int)inv->state,
(void*)inv->invite_conn); (void*)inv->invite_conn);
conn_mgr_cb_t cb = inv->cb; conn_mgr_cb_t cb = inv->cb;

32
src/routing_layer/topo_group.c
Unescape View File

@ -172,8 +172,7 @@ static void topo_group_receive_cbk(struct ETCP_CONN* from_conn, struct ll_entry*
queue_dgram_free(entry); queue_entry_free(entry); return; queue_dgram_free(entry); queue_entry_free(entry); return;
} }
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "BGP recv %s from %s len=%zu group=%016llx", group_subcmd_name(subcmd), from_conn->log_name, entry->len, (unsigned long long)pkt_group_id); DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "BGP recv NODEINFO from=%s nid=%016llx ver=%d grp=%016llx", from_conn->log_name, (unsigned long long)((struct TOPOMSG_NODEINFO_PKT*)data)->node.node_id, ((struct TOPOMSG_NODEINFO_PKT*)data)->node.ver, (unsigned long long)((struct TOPOMSG_NODEINFO_PKT*)data)->node.group_id);
if (subcmd == TOPO_SUBCMD_NODEINFO) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BGP recv NODEINFO from=%s nid=%016llx ver=%d grp=%016llx", from_conn->log_name, (unsigned long long)((struct TOPOMSG_NODEINFO_PKT*)data)->node.node_id, ((struct TOPOMSG_NODEINFO_PKT*)data)->node.ver, (unsigned long long)((struct TOPOMSG_NODEINFO_PKT*)data)->node.group_id); }
if (subcmd == TOPO_SUBCMD_NODEINFO) { nodeinfo_dump_log(data, entry->len); topo_group_process_nodeinfo(group, from_conn, data, entry->len); } if (subcmd == TOPO_SUBCMD_NODEINFO) { nodeinfo_dump_log(data, entry->len); topo_group_process_nodeinfo(group, from_conn, data, entry->len); }
else if (subcmd == TOPO_SUBCMD_WITHDRAW) topo_group_process_withdraw(group, from_conn, data, entry->len); else if (subcmd == TOPO_SUBCMD_WITHDRAW) topo_group_process_withdraw(group, from_conn, data, entry->len);
@ -312,7 +311,7 @@ struct TOPO_GROUPS* topo_groups_init(struct UTUN_INSTANCE* instance) {
sqlite3_exec(instance->topo_sqlite_db, "PRAGMA mmap_size=134217728", NULL, NULL, NULL); sqlite3_exec(instance->topo_sqlite_db, "PRAGMA mmap_size=134217728", NULL, NULL, NULL);
sqlite3_exec(instance->topo_sqlite_db, "PRAGMA temp_store=MEMORY", NULL, NULL, NULL); sqlite3_exec(instance->topo_sqlite_db, "PRAGMA temp_store=MEMORY", NULL, NULL, NULL);
topo_node_sqlite_init(instance->topo_sqlite_db); topo_node_sqlite_init(instance->topo_sqlite_db);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "SQLite opened: %s rc=%d db=%p", db_file, rc, (void*)instance->topo_sqlite_db); DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "SQLite opened: %s rc=%d db=%p", db_file, rc, (void*)instance->topo_sqlite_db);
} else { } else {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "sqlite3_open(%s) failed: %s", DEBUG_ERROR(DEBUG_CATEGORY_BGP, "sqlite3_open(%s) failed: %s",
db_file, instance->topo_sqlite_db ? sqlite3_errmsg(instance->topo_sqlite_db) : "null db"); db_file, instance->topo_sqlite_db ? sqlite3_errmsg(instance->topo_sqlite_db) : "null db");
@ -457,7 +456,7 @@ void topo_group_new_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn) {
} }
topo_group_add_to_senders(group, conn); topo_group_add_to_senders(group, conn);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "topo_group_new_conn: peer=%016llx group=%016llx type=%d ch=%s", (unsigned long long)conn->peer_node_id, (unsigned long long)group->group_id, group->group_type, group->channel_id); DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "topo_group_new_conn: peer=%016llx group=%016llx type=%d ch=%s", (unsigned long long)conn->peer_node_id, (unsigned long long)group->group_id, group->group_type, group->channel_id);
topo_group_send_table_request(group, conn); topo_group_send_table_request(group, conn);
topo_group_connect_on_up(group, conn); topo_group_connect_on_up(group, conn);
@ -602,7 +601,7 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
struct TOPOMSG_NODE* ni = &pkt->node; struct TOPOMSG_NODE* ni = &pkt->node;
if (ni->group_id != group->group_id) { if (ni->group_id != group->group_id) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "NODEINFO group_id mismatch from %s: expected=%016llx got=%016llx nid=%016llx", DEBUG_ERROR(DEBUG_CATEGORY_BGP, "NODEINFO group_id mismatch from %s: expected=%016llx got=%016llx nid=%016llx",
from->log_name, (unsigned long long)group->group_id, (unsigned long long)ni->group_id, (unsigned long long)ni->node_id); from->log_name, (unsigned long long)group->group_id, (unsigned long long)ni->group_id, (unsigned long long)ni->node_id);
return -1; return -1;
} }
@ -625,11 +624,9 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
struct TOPO_GROUP_NODE* nodeinfo1 = topo_node_find_by_id(group, node_id); struct TOPO_GROUP_NODE* nodeinfo1 = topo_node_find_by_id(group, node_id);
uint8_t new_ver = ni->ver; uint8_t new_ver = ni->ver;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "process_nodeinfo: nid=%016llx ver=%d hops=%d nodeinfo1=%p from=%s",
(unsigned long long)node_id, new_ver, ni->hop_count, (void*)nodeinfo1, from->log_name);
if (nodeinfo1 && (int8_t)(nodeinfo1->last_ver - new_ver) >= 0) { if (nodeinfo1 && (int8_t)(nodeinfo1->last_ver - new_ver) >= 0) {
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "NODEINFO skip (stale ver): node=%016llx cur_ver=%d new_ver=%d from=%s", (unsigned long long)node_id, nodeinfo1->last_ver, new_ver, from->log_name); DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "NODEINFO skip (stale ver): node=%016llx cur_ver=%d new_ver=%d from=%s", (unsigned long long)node_id, nodeinfo1->last_ver, new_ver, from->log_name);
int new_hops = ni->hop_count + 1; int new_hops = ni->hop_count + 1;
if (new_hops <= MAX_HOPS) { if (new_hops <= MAX_HOPS) {
uint64_t hop_list[MAX_HOPS]; uint64_t hop_list[MAX_HOPS];
@ -661,7 +658,7 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
uint64_t* new_hop_list = NULL; uint8_t new_hop_count = 0; uint64_t* new_hop_list = NULL; uint8_t new_hop_count = 0;
uint16_t incoming_cumulative_rtt = 0; uint16_t incoming_cumulative_rtt = 0;
if (topo_node_deserialize(group, ser_data, ser_len, &new_ni, &new_subnets, &new_hop_list, &new_hop_count, &incoming_cumulative_rtt) != 0) { if (topo_node_deserialize(group, ser_data, ser_len, &new_ni, &new_subnets, &new_hop_list, &new_hop_count, &incoming_cumulative_rtt) != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "NODEINFO deserialize failed from %s nid=%016llx", from->log_name, (unsigned long long)node_id); DEBUG_ERROR(DEBUG_CATEGORY_BGP, "NODEINFO deserialize failed from %s nid=%016llx", from->log_name, (unsigned long long)node_id);
if (nodeinfo1) { queue_remove_data(group->nodes, &nodeinfo1->ll); queue_free(paths); queue_entry_free(&nodeinfo1->ll); } if (nodeinfo1) { queue_remove_data(group->nodes, &nodeinfo1->ll); queue_free(paths); queue_entry_free(&nodeinfo1->ll); }
return -1; return -1;
} }
@ -669,8 +666,6 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
int v6c = topo_list_count((struct _topo_head*)new_ni->v6_addrs); int v6c = topo_list_count((struct _topo_head*)new_ni->v6_addrs);
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "NODEINFO deser: nid=%016llx v4a=%d v6a=%d from=%s", DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "NODEINFO deser: nid=%016llx v4a=%d v6a=%d from=%s",
(unsigned long long)node_id, v4c, v6c, from->log_name); } (unsigned long long)node_id, v4c, v6c, from->log_name); }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "NODEINFO deserialized: nid=%016llx new_ver=%d flags=0x%02x ed=%016llx",
(unsigned long long)node_id, new_ni->ver, new_ni->flags, *(uint64_t*)new_ni->ed25519_public_key);
/* verify Ed25519 self-signature over canonical message */ /* verify Ed25519 self-signature over canonical message */
{ {
@ -696,8 +691,6 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
if (nodeinfo1) { if (nodeinfo1) {
{ struct TOPO_NODE* stored = topo_node_registry_store(group->instance->topo_groups, new_ni); { struct TOPO_NODE* stored = topo_node_registry_store(group->instance->topo_groups, new_ni);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "NODEINFO update: stored=%p new_ni=%p same=%d nid=%016llx",
(void*)stored, (void*)new_ni, stored == new_ni, (unsigned long long)(stored ? stored->node_id : 0));
if (stored != new_ni) new_ni = stored; } if (stored != new_ni) new_ni = stored; }
new_ni->group_id = group->group_id; new_ni->group_id = group->group_id;
new_ni->flags = pkt->node.flags; new_ni->flags = pkt->node.flags;
@ -709,8 +702,6 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
nodeinfo1 = (struct TOPO_GROUP_NODE*)qe; nodeinfo1 = (struct TOPO_GROUP_NODE*)qe;
memset((uint8_t*)nodeinfo1 + sizeof(struct ll_entry), 0, sizeof(*nodeinfo1) - sizeof(struct ll_entry)); memset((uint8_t*)nodeinfo1 + sizeof(struct ll_entry), 0, sizeof(*nodeinfo1) - sizeof(struct ll_entry));
{ struct TOPO_NODE* stored = topo_node_registry_store(group->instance->topo_groups, new_ni); { struct TOPO_NODE* stored = topo_node_registry_store(group->instance->topo_groups, new_ni);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "NODEINFO new: stored=%p new_ni=%p same=%d nid=%016llx",
(void*)stored, (void*)new_ni, stored == new_ni, (unsigned long long)(stored ? stored->node_id : 0));
if (stored != new_ni) new_ni = stored; } if (stored != new_ni) new_ni = stored; }
new_ni->group_id = group->group_id; new_ni->group_id = group->group_id;
new_ni->flags = pkt->node.flags; new_ni->flags = pkt->node.flags;
@ -746,14 +737,13 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from
topo_node_sqlite_node_put(sdb, group->instance->topo_groups, nodeinfo1, ntp_time_get_seconds(group->instance)); topo_node_sqlite_node_put(sdb, group->instance->topo_groups, nodeinfo1, ntp_time_get_seconds(group->instance));
if (group->group_type == TOPO_GROUP_TYPE_CHAT && group->channel_id[0]) { if (group->group_type == TOPO_GROUP_TYPE_CHAT && group->channel_id[0]) {
topo_node_sqlite_member_put(sdb, group->channel_id, node_id, NULL, 0, NULL, 0, NULL, NULL, NULL, NULL, NULL, NULL, 0); topo_node_sqlite_member_put(sdb, group->channel_id, node_id, NULL, 0, NULL, 0, NULL, NULL, NULL, NULL, NULL, NULL, 0);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "SQLite member_put: ch=%s node=%016llx", group->channel_id, (unsigned long long)node_id);
} }
topo_node_sqlite_nodeinfo_updated(sdb, node_id); topo_node_sqlite_nodeinfo_updated(sdb, node_id);
} }
} }
if (group->instance->control_srv) control_server_notify_node_change(group->instance->control_srv, nodeinfo1); if (group->instance->control_srv) control_server_notify_node_change(group->instance->control_srv, nodeinfo1);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "node_updated_cb: node=%016llx has_cb=%d ch=%s type=%d", (unsigned long long)node_id, group->instance->topo_groups->node_updated_cb ? 1 : 0, group->channel_id, group->group_type); DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "node_updated_cb: node=%016llx has_cb=%d ch=%s type=%d", (unsigned long long)node_id, group->instance->topo_groups->node_updated_cb ? 1 : 0, group->channel_id, group->group_type);
if (group->instance->topo_groups->node_updated_cb) if (group->instance->topo_groups->node_updated_cb)
group->instance->topo_groups->node_updated_cb(group->instance, node_id, ni->public_key, ni->ed25519_public_key); group->instance->topo_groups->node_updated_cb(group->instance, node_id, ni->public_key, ni->ed25519_public_key);
@ -833,16 +823,16 @@ void topo_group_send_nodeinfo(struct TOPO_GROUP* group, struct TOPO_GROUP_NODE*
p[0] = ETCP_ID_TOPO_ENTRY; p[1] = TOPO_SUBCMD_NODEINFO; p[0] = ETCP_ID_TOPO_ENTRY; p[1] = TOPO_SUBCMD_NODEINFO;
struct TOPO_NODE* sni = topo_node_registry_find(group->instance->topo_groups, node->node_id); struct TOPO_NODE* sni = topo_node_registry_find(group->instance->topo_groups, node->node_id);
if (!sni) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: node %016llx NOT in registry — skip forward to %s", (unsigned long long)node->node_id, conn->log_name); u_free(p); return; } if (!sni) { DEBUG_WARN(DEBUG_CATEGORY_BGP, "send_nodeinfo: node %016llx NOT in registry — skip forward to %s", (unsigned long long)node->node_id, conn->log_name); u_free(p); return; }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: node %016llx ver=%d grp=%016llx to conn=%s", (unsigned long long)node->node_id, sni->ver, (unsigned long long)sni->group_id, conn->log_name); DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "send_nodeinfo: node %016llx ver=%d grp=%016llx to conn=%s", (unsigned long long)node->node_id, sni->ver, (unsigned long long)sni->group_id, conn->log_name);
int ser_len = topo_node_serialize(sni, node, p + 2, max_sz - 2, cumulative_rtt); int ser_len = topo_node_serialize(sni, node, p + 2, max_sz - 2, cumulative_rtt);
if (ser_len < 0) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: serialize failed for node %016llx", (unsigned long long)node->node_id); u_free(p); return; } if (ser_len < 0) { DEBUG_ERROR(DEBUG_CATEGORY_BGP, "send_nodeinfo: serialize failed for node %016llx", (unsigned long long)node->node_id); u_free(p); return; }
struct ll_entry* e = queue_entry_new(0); struct ll_entry* e = queue_entry_new(0);
if (!e) { u_free(p); return; } if (!e) { u_free(p); return; }
e->dgram = p; e->len = (size_t)ser_len + 2; e->dgram = p; e->len = (size_t)ser_len + 2;
if (etcp_send(conn, e) != 0) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: etcp_send FAILED for node %016llx to %s", (unsigned long long)node->node_id, conn->log_name); u_free(p); queue_entry_free(e); } if (etcp_send(conn, e) != 0) { DEBUG_ERROR(DEBUG_CATEGORY_BGP, "send_nodeinfo: etcp_send FAILED for node %016llx to %s", (unsigned long long)node->node_id, conn->log_name); u_free(p); queue_entry_free(e); }
} }
static void topo_group_add_to_senders(struct TOPO_GROUP* group, struct ETCP_CONN* conn) { static void topo_group_add_to_senders(struct TOPO_GROUP* group, struct ETCP_CONN* conn) {

27
src/transport_layer/etcp.c
Unescape View File

@ -320,20 +320,8 @@ static void etcp_on_up(struct ETCP_CONN* etcp) {
etcp->log_name, etcp->links_up, total_links, etcp->mtu, etcp->reinit_count, etcp->log_name, etcp->links_up, total_links, etcp->mtu, etcp->reinit_count,
pp > 0 ? " — up: " : "", links_str); pp > 0 ? " — up: " : "", links_str);
(void)elapsed_ms; (void)elapsed_ms;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_ON_UP_BEFORE: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x",
etcp->log_name,
etcp->crypto_ctx.session_key[0], etcp->crypto_ctx.session_key[1],
etcp->crypto_ctx.session_key[2], etcp->crypto_ctx.session_key[3],
etcp->crypto_ctx.peer_public_key[0], etcp->crypto_ctx.peer_public_key[1],
etcp->crypto_ctx.peer_public_key[2], etcp->crypto_ctx.peer_public_key[3]);
etcp_cbk_fire(etcp, ETCP_CBK_EVENT_UP); etcp_cbk_fire(etcp, ETCP_CBK_EVENT_UP);
etcp_fire_conn_status(etcp, ETCP_CONN_STATUS_UP); etcp_fire_conn_status(etcp, ETCP_CONN_STATUS_UP);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_ON_UP_AFTER: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x",
etcp->log_name,
etcp->crypto_ctx.session_key[0], etcp->crypto_ctx.session_key[1],
etcp->crypto_ctx.session_key[2], etcp->crypto_ctx.session_key[3],
etcp->crypto_ctx.peer_public_key[0], etcp->crypto_ctx.peer_public_key[1],
etcp->crypto_ctx.peer_public_key[2], etcp->crypto_ctx.peer_public_key[3]);
} }
static void etcp_on_down(struct ETCP_CONN* etcp, struct ETCP_LINK* down_link) { static void etcp_on_down(struct ETCP_CONN* etcp, struct ETCP_LINK* down_link) {
@ -397,7 +385,7 @@ void etcp_connection_close(struct ETCP_CONN* etcp) {
if (etcp->state == 2) { DEBUG_WARN(DEBUG_CATEGORY_ETCP, "[%s] already deleted", etcp->log_name); return; } if (etcp->state == 2) { DEBUG_WARN(DEBUG_CATEGORY_ETCP, "[%s] already deleted", etcp->log_name); return; }
if (etcp->callbacks_running) { if (etcp->callbacks_running) {
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "[%s] FATAL: etcp_connection_close called from inside callback chain — SEGFAULTING to show backtrace", DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "[%s] FATAL: etcp_connection_close called from inside callback chain — SEGFAULTING to show backtrace",
etcp->log_name); etcp->log_name);
*(volatile int*)0 = 0; *(volatile int*)0 = 0;
} }
@ -645,17 +633,6 @@ void etcp_conn_ready(struct ETCP_CONN* conn) {
conn->reset_done = 1; conn->reset_done = 1;
if (conn->tx_state == 0) { conn->tx_state = ETCP_TX_STATE_DATA_WAIT; } if (conn->tx_state == 0) { conn->tx_state = ETCP_TX_STATE_DATA_WAIT; }
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection ready", conn->log_name); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection ready", conn->log_name);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_CONN_READY: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x my_pub=%02x%02x%02x%02x links=%p",
conn->log_name,
conn->crypto_ctx.session_key[0], conn->crypto_ctx.session_key[1],
conn->crypto_ctx.session_key[2], conn->crypto_ctx.session_key[3],
conn->crypto_ctx.peer_public_key[0], conn->crypto_ctx.peer_public_key[1],
conn->crypto_ctx.peer_public_key[2], conn->crypto_ctx.peer_public_key[3],
conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[0] : 0,
conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[1] : 0,
conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[2] : 0,
conn->crypto_ctx.pk ? conn->crypto_ctx.pk->public_key[3] : 0,
(void*)conn->links);
etcp_conn_queue_set_ready(conn); etcp_conn_queue_set_ready(conn);
} }
@ -1042,7 +1019,7 @@ static void etcp_link_ready_callback(struct ETCP_CONN* etcp) {
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] etcp_link_ready_callback: links_up 0→1, calling etcp_on_up (initialized=%d tx_state=%d)", etcp->log_name, etcp->initialized, etcp->tx_state); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] etcp_link_ready_callback: links_up 0→1, calling etcp_on_up (initialized=%d tx_state=%d)", etcp->log_name, etcp->initialized, etcp->tx_state);
etcp->links_up=1; etcp->links_up=1;
etcp_on_up(etcp); etcp_on_up(etcp);
} else DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[%s] etcp_link_ready_callback: links_up=%d already up", etcp->log_name, etcp->links_up); }
if (etcp->tx_state!=ETCP_TX_STATE_LINK_WAIT) return; if (etcp->tx_state!=ETCP_TX_STATE_LINK_WAIT) return;

6
src/transport_layer/etcp_api.c
Unescape View File

@ -182,11 +182,11 @@ void etcp_int_recv(struct ll_queue* queue, void* arg) {
struct UTUN_INSTANCE* inst = conn->instance; struct UTUN_INSTANCE* inst = conn->instance;
if (!inst) { queue_dgram_free(e); queue_entry_free(e); queue_resume_callback(queue); return; } if (!inst) { queue_dgram_free(e); queue_entry_free(e); queue_resume_callback(queue); return; }
if (inst->api_bindings.callbacks[id]) { if (inst->api_bindings.callbacks[id]) {
DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "dispatch id=0x%02x conn=%s len=%zu", id, conn->log_name, e->len); DEBUG_TRACE(DEBUG_CATEGORY_TRAFFIC, "dispatch id=0x%02x conn=%s len=%zu", id, conn->log_name, e->len);
inst->api_bindings.callbacks[id](conn, e); inst->api_bindings.callbacks[id](conn, e);
} else if (inst->api_bindings.callbacks[0]) { } else if (inst->api_bindings.callbacks[0]) {
DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "dispatch id=0x%02x (fallback) conn=%s len=%zu", id, conn->log_name, e->len); DEBUG_TRACE(DEBUG_CATEGORY_TRAFFIC, "dispatch id=0x%02x (fallback) conn=%s len=%zu", id, conn->log_name, e->len);
inst->api_bindings.callbacks[0](conn, e); inst->api_bindings.callbacks[0](conn, e);
} else { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "dispatch id=0x%02x NO CB conn=%s len=%zu — DROPPED", id, conn->log_name, e->len); queue_dgram_free(e); queue_entry_free(e); } } else { queue_dgram_free(e); queue_entry_free(e); }
queue_resume_callback(queue); queue_resume_callback(queue);
} }

8
src/transport_layer/etcp_connect.c
Unescape View File

@ -68,7 +68,7 @@ static void connect_cancel(struct ETCP_CONNECT* ctx) {
static void connect_create_links_v4(struct ETCP_CONNECT* ctx, struct TOPO_GROUP_NODE* node) { static void connect_create_links_v4(struct ETCP_CONNECT* ctx, struct TOPO_GROUP_NODE* node) {
if (!node) return; if (!node) return;
struct TOPO_NODE* ni = topo_node_registry_find(ctx->instance->topo_groups, node->node_id); struct TOPO_NODE* ni = topo_node_registry_find(ctx->instance->topo_groups, node->node_id);
if (!ni) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[etcp_connect] links_v4: ni NOT in registry for node=%016llx", (unsigned long long)node->node_id); return; } if (!ni) { DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[etcp_connect] links_v4: ni NOT in registry for node=%016llx", (unsigned long long)node->node_id); return; }
int addr_count = 0, sock_count = 0, link_count = 0; int addr_count = 0, sock_count = 0, link_count = 0;
{ struct ETCP_SOCKET* s = ctx->instance->etcp_sockets; while (s) { sock_count++; s = s->next; } } { struct ETCP_SOCKET* s = ctx->instance->etcp_sockets; while (s) { sock_count++; s = s->next; } }
for (const struct TOPO_ADDR4* a = ni->v4_addrs; a; a = a->next) { for (const struct TOPO_ADDR4* a = ni->v4_addrs; a; a = a->next) {
@ -87,7 +87,7 @@ static void connect_create_links_v4(struct ETCP_CONNECT* ctx, struct TOPO_GROUP_
if (tlink) { tlink->is_tcp = 1; etcp_tcp_link_start_connect(tlink, &sa, a->port); link_count++; } if (tlink) { tlink->is_tcp = 1; etcp_tcp_link_start_connect(tlink, &sa, a->port); link_count++; }
} }
} }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[etcp_connect] links_v4: addrs=%d socks=%d links=%d for node=%016llx", DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[etcp_connect] links_v4: addrs=%d socks=%d links=%d for node=%016llx",
addr_count, sock_count, link_count, (unsigned long long)node->node_id); addr_count, sock_count, link_count, (unsigned long long)node->node_id);
} }
@ -123,7 +123,7 @@ static void connect_create_links_v6(struct ETCP_CONNECT* ctx, struct TOPO_GROUP_
static void connect_bgp_ready_cb(struct ETCP_CONN* conn) { static void connect_bgp_ready_cb(struct ETCP_CONN* conn) {
struct ETCP_CONNECT* ctx = connect_find(conn->instance, conn->peer_node_id); struct ETCP_CONNECT* ctx = connect_find(conn->instance, conn->peer_node_id);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[etcp_connect] bgp_ready_cb: node=%016llx ctx=%p ctx_done=%d ra=%d", DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "[etcp_connect] bgp_ready_cb: node=%016llx ctx=%p ctx_done=%d ra=%d",
(unsigned long long)conn->peer_node_id, (void*)ctx, ctx ? ctx->done : -1, conn->routing_exchange_active); (unsigned long long)conn->peer_node_id, (void*)ctx, ctx ? ctx->done : -1, conn->routing_exchange_active);
if (!ctx || ctx->done) return; if (!ctx || ctx->done) return;
connect_deliver(ctx, ETCP_CONNECT_BGP_READY, 1); connect_deliver(ctx, ETCP_CONNECT_BGP_READY, 1);
@ -212,7 +212,7 @@ int etcp_connect(struct UTUN_INSTANCE* inst, struct TOPO_GROUP_NODE* node,
struct TOPO_NODE* ni = topo_node_registry_find(inst->topo_groups, node->node_id); struct TOPO_NODE* ni = topo_node_registry_find(inst->topo_groups, node->node_id);
if (!ni) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP_CONNECT, "[etcp_connect] node not in registry"); return -1; } if (!ni) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP_CONNECT, "[etcp_connect] node not in registry"); return -1; }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[etcp_connect] registry OK node=%016llx pub=%016llx v4addrs=%p v4socks=%p", DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[etcp_connect] registry OK node=%016llx pub=%016llx v4addrs=%p v4socks=%p",
(unsigned long long)node->node_id, *(uint64_t*)ni->public_key, (void*)ni->v4_addrs, (void*)ni->v4_sock_meta); (unsigned long long)node->node_id, *(uint64_t*)ni->public_key, (void*)ni->v4_addrs, (void*)ni->v4_sock_meta);
uint64_t node_id = ni->node_id; uint64_t node_id = ni->node_id;

10
src/transport_layer/etcp_connections.c
Unescape View File

@ -1210,7 +1210,7 @@ int etcp_encrypt_send(struct ETCP_DGRAM* dgram) {
socklen_t addr_len = (addr->ss_family == AF_INET) ? sizeof(struct sockaddr_in) : sizeof(struct sockaddr_in6); socklen_t addr_len = (addr->ss_family == AF_INET) ? sizeof(struct sockaddr_in) : sizeof(struct sockaddr_in6);
if (addr->ss_family == AF_INET6) { if (addr->ss_family == AF_INET6) {
struct sockaddr_in6* sin6 = (struct sockaddr_in6*)addr; struct sockaddr_in6* sin6 = (struct sockaddr_in6*)addr;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[v6_send] fd=%d dst=%-39s scope=%u", dgram->link->conn->fd, DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "[v6_send] fd=%d dst=%-39s scope=%u", dgram->link->conn->fd,
sockaddr_storage_to_str(addr).str, sin6->sin6_scope_id); sockaddr_storage_to_str(addr).str, sin6->sin6_scope_id);
} }
@ -1813,7 +1813,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
ssize_t recv_len = socket_recvfrom(sock, data, PACKET_DATA_SIZE, (struct sockaddr*)&addr, &addr_len); ssize_t recv_len = socket_recvfrom(sock, data, PACKET_DATA_SIZE, (struct sockaddr*)&addr, &addr_len);
if (recv_len > 0 && addr.ss_family == AF_INET6) { if (recv_len > 0 && addr.ss_family == AF_INET6) {
struct sockaddr_in6* sin6 = (struct sockaddr_in6*)&addr; struct sockaddr_in6* sin6 = (struct sockaddr_in6*)&addr;
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[v6_recv] sock=%s fd=%d src=[%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x]:%d len=%zd scope=%u", DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "[v6_recv] sock=%s fd=%d src=[%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x:%02x%02x]:%d len=%zd scope=%u",
e_sock->name, (int)sock, e_sock->name, (int)sock,
sin6->sin6_addr.s6_addr[0],sin6->sin6_addr.s6_addr[1],sin6->sin6_addr.s6_addr[2],sin6->sin6_addr.s6_addr[3], sin6->sin6_addr.s6_addr[0],sin6->sin6_addr.s6_addr[1],sin6->sin6_addr.s6_addr[2],sin6->sin6_addr.s6_addr[3],
sin6->sin6_addr.s6_addr[4],sin6->sin6_addr.s6_addr[5],sin6->sin6_addr.s6_addr[6],sin6->sin6_addr.s6_addr[7], sin6->sin6_addr.s6_addr[4],sin6->sin6_addr.s6_addr[5],sin6->sin6_addr.s6_addr[6],sin6->sin6_addr.s6_addr[7],
@ -1859,7 +1859,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
link->etcp->crypto_ctx.session_key[0], link->etcp->crypto_ctx.session_key[1], link->etcp->crypto_ctx.session_key[0], link->etcp->crypto_ctx.session_key[1],
link->etcp->crypto_ctx.session_key[2], link->etcp->crypto_ctx.session_key[3]); link->etcp->crypto_ctx.session_key[2], link->etcp->crypto_ctx.session_key[3]);
} else { } else {
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "SKIP normal decrypt: link=%p session_ready=%d — trying init decrypt", DEBUG_DEBUG(DEBUG_CATEGORY_CRYPTO, "SKIP normal decrypt: link=%p session_ready=%d — trying init decrypt",
link, link && link->etcp ? link->etcp->crypto_ctx.session_ready : -1); link, link && link->etcp ? link->etcp->crypto_ctx.session_ready : -1);
} }
@ -2017,7 +2017,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
conn=etcp_connection_create(e_sock->instance,""); conn=etcp_connection_create(e_sock->instance,"");
if (!conn) { errorcode=55; DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "failed to create connection"); goto ec_fr; } if (!conn) { errorcode=55; DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "failed to create connection"); goto ec_fr; }
memcpy(&conn->crypto_ctx, &sc, sizeof(sc)); memcpy(&conn->crypto_ctx, &sc, sizeof(sc));
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_CTX_INIT: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x my_priv=%02x%02x%02x%02x", DEBUG_DEBUG(DEBUG_CATEGORY_CRYPTO, "CRYPTO_CTX_INIT: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x my_priv=%02x%02x%02x%02x",
conn->log_name, conn->log_name,
conn->crypto_ctx.session_key[0], conn->crypto_ctx.session_key[1], conn->crypto_ctx.session_key[0], conn->crypto_ctx.session_key[1],
conn->crypto_ctx.session_key[2], conn->crypto_ctx.session_key[3], conn->crypto_ctx.session_key[2], conn->crypto_ctx.session_key[3],
@ -2054,7 +2054,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
if (conn->fin_wait_clear_cb) { conn->fin_wait_clear_cb(conn, conn->fin_wait_clear_arg); conn->fin_wait_clear_cb = NULL; conn->fin_wait_clear_arg = NULL; } if (conn->fin_wait_clear_cb) { conn->fin_wait_clear_cb(conn, conn->fin_wait_clear_arg); conn->fin_wait_clear_cb = NULL; conn->fin_wait_clear_arg = NULL; }
} }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "INIT conn=%s new_conn=%d peer=0x%016llx state=%d links_up=%d links=%p", conn->log_name, new_conn, (unsigned long long)peer_id, conn->state, conn->links_up, (void*)conn->links); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "INIT conn=%s new_conn=%d peer=0x%016llx state=%d links_up=%d links=%p", conn->log_name, new_conn, (unsigned long long)peer_id, conn->state, conn->links_up, (void*)conn->links);
// Check if link already exists (for CHANNEL_INIT recovery) // Check if link already exists (for CHANNEL_INIT recovery)

2
src/transport_layer/etcp_loadbalancer.c
Unescape View File

@ -194,7 +194,7 @@ void loadbalancer_link_ready(struct ETCP_LINK* link) {
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "link still blocked by shaper"); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "link still blocked by shaper");
return; return;
} }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[%s] loadbalancer_link_ready: link=%p links_up=%d initialized=%d tx_state=%d", link->etcp->log_name, (void*)link, link->etcp->links_up, link->etcp->initialized, link->etcp->tx_state); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] loadbalancer_link_ready: link=%p links_up=%d initialized=%d tx_state=%d", link->etcp->log_name, (void*)link, link->etcp->links_up, link->etcp->initialized, link->etcp->tx_state);
if (link->etcp->link_ready_for_send_fn) { if (link->etcp->link_ready_for_send_fn) {
link->etcp->link_ready_for_send_fn(link->etcp); link->etcp->link_ready_for_send_fn(link->etcp);
} else { } else {

20
src/transport_layer/node_conn_direct.c
Unescape View File

@ -143,14 +143,14 @@ static int ncd_create_links(struct ncd_entry* entry, struct TOPO_NODE* ni,
if (s->local_addr.ss_family == AF_INET && s->type != CFG_SERVER_TYPE_PRIVATE) if (s->local_addr.ss_family == AF_INET && s->type != CFG_SERVER_TYPE_PRIVATE)
socks[sock_count++] = s; socks[sock_count++] = s;
} }
if (sock_count == 0) DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] v4 sock_count=0 node=0x%016llx", (unsigned long long)nid); if (sock_count == 0) DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[ncd] v4 sock_count=0 node=0x%016llx", (unsigned long long)nid);
if (sock_count > 0) { if (sock_count > 0) {
int rr = 0; int rr = 0;
for (const struct TOPO_ADDR4* a = ni->v4_addrs; a; a = a->next) { for (const struct TOPO_ADDR4* a = ni->v4_addrs; a; a = a->next) {
if (a->port == 0 || !(a->protocol & TOPO_PROTO_UDP)) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] v4 skip proto=%02x port=%d node=0x%016llx", a->protocol, (int)a->port, (unsigned long long)nid); continue; } if (a->port == 0 || !(a->protocol & TOPO_PROTO_UDP)) { DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[ncd] v4 skip proto=%02x port=%d node=0x%016llx", a->protocol, (int)a->port, (unsigned long long)nid); continue; }
int zero = 1; for (int j = 0; j < 4; j++) if (a->addr[j] != 0) { zero = 0; break; } int zero = 1; for (int j = 0; j < 4; j++) if (a->addr[j] != 0) { zero = 0; break; }
if (zero) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] v4 skip zero-addr node=0x%016llx", (unsigned long long)nid); continue; } if (zero) { DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[ncd] v4 skip zero-addr node=0x%016llx", (unsigned long long)nid); continue; }
struct sockaddr_in sin; memset(&sin, 0, sizeof(sin)); sin.sin_family = AF_INET; struct sockaddr_in sin; memset(&sin, 0, sizeof(sin)); sin.sin_family = AF_INET;
memcpy(&sin.sin_addr.s_addr, a->addr, 4); sin.sin_port = htons(a->port); memcpy(&sin.sin_addr.s_addr, a->addr, 4); sin.sin_port = htons(a->port);
struct sockaddr_storage sa; memcpy(&sa, &sin, sizeof(sin)); struct sockaddr_storage sa; memcpy(&sa, &sin, sizeof(sin));
@ -193,14 +193,14 @@ static int ncd_create_links(struct ncd_entry* entry, struct TOPO_NODE* ni,
socks[sock_count++] = s; socks[sock_count++] = s;
} }
if (sock_count == 0) DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] v6 sock_count=0 node=0x%016llx", (unsigned long long)nid); if (sock_count == 0) DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[ncd] v6 sock_count=0 node=0x%016llx", (unsigned long long)nid);
if (sock_count > 0) { if (sock_count > 0) {
int rr = 0; int rr = 0;
for (const struct TOPO_ADDR6* a = ni->v6_addrs; a; a = a->next) { for (const struct TOPO_ADDR6* a = ni->v6_addrs; a; a = a->next) {
if (a->port == 0 || !(a->protocol & TOPO_PROTO_UDP)) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] v6 skip proto=%02x port=%d node=0x%016llx", a->protocol, (int)a->port, (unsigned long long)nid); continue; } if (a->port == 0 || !(a->protocol & TOPO_PROTO_UDP)) { DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[ncd] v6 skip proto=%02x port=%d node=0x%016llx", a->protocol, (int)a->port, (unsigned long long)nid); continue; }
int zero = 1; for (int j = 0; j < 16; j++) if (a->addr[j] != 0) { zero = 0; break; } int zero = 1; for (int j = 0; j < 16; j++) if (a->addr[j] != 0) { zero = 0; break; }
if (zero) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] v6 skip zero-addr node=0x%016llx", (unsigned long long)nid); continue; } if (zero) { DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[ncd] v6 skip zero-addr node=0x%016llx", (unsigned long long)nid); continue; }
struct sockaddr_in6 sin6; memset(&sin6, 0, sizeof(sin6)); sin6.sin6_family = AF_INET6; struct sockaddr_in6 sin6; memset(&sin6, 0, sizeof(sin6)); sin6.sin6_family = AF_INET6;
memcpy(&sin6.sin6_addr, a->addr, 16); sin6.sin6_port = htons(a->port); memcpy(&sin6.sin6_addr, a->addr, 16); sin6.sin6_port = htons(a->port);
struct ETCP_SOCKET* use_sock = socks[rr++ % sock_count]; struct ETCP_SOCKET* use_sock = socks[rr++ % sock_count];
@ -559,7 +559,7 @@ int node_conn_direct_open(struct UTUN_INSTANCE* inst, uint64_t node_id,
{ struct TOPO_NODE* ni = ncd_lookup_node(inst, node_id); { struct TOPO_NODE* ni = ncd_lookup_node(inst, node_id);
if (ni) { ncd_create_links(entry, ni, specific_sock); topo_node_registry_unref(inst->topo_groups, ni->node_id); } if (ni) { ncd_create_links(entry, ni, specific_sock); topo_node_registry_unref(inst->topo_groups, ni->node_id); }
} }
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=REUSED_entry_pending", DEBUG_DEBUG(DEBUG_CATEGORY_TIMERS, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=REUSED_entry_pending",
(unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb());
entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect"); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect");
DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open REUSED new-entry (pending) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open REUSED new-entry (pending) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn);
@ -633,7 +633,7 @@ int node_conn_direct_open(struct UTUN_INSTANCE* inst, uint64_t node_id,
if (link_count == 0) if (link_count == 0)
DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] no links created for node=0x%016llx", (unsigned long long)node_id); DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] no links created for node=0x%016llx", (unsigned long long)node_id);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=NEW_node_conn_direct_open", DEBUG_DEBUG(DEBUG_CATEGORY_TIMERS, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=NEW_node_conn_direct_open",
(unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb());
entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect"); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect");
DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open NEW node=0x%016llx conn=%p links=%d handles=%d", DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open NEW node=0x%016llx conn=%p links=%d handles=%d",
@ -710,7 +710,7 @@ int node_conn_direct_open_node(struct UTUN_INSTANCE* inst, uint64_t node_id,
DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node REUSED new-entry (ready) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node REUSED new-entry (ready) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn);
} else { } else {
ncd_create_links(entry, ni, specific_sock); ncd_create_links(entry, ni, specific_sock);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=REUSED_conn_pending", DEBUG_DEBUG(DEBUG_CATEGORY_TIMERS, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=REUSED_conn_pending",
(unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb());
entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect_node"); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect_node");
DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node REUSED new-entry (pending) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node REUSED new-entry (pending) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn);
@ -775,7 +775,7 @@ int node_conn_direct_open_node(struct UTUN_INSTANCE* inst, uint64_t node_id,
if (link_count == 0) if (link_count == 0)
DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] open_node no links created for node=0x%016llx", (unsigned long long)node_id); DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] open_node no links created for node=0x%016llx", (unsigned long long)node_id);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=NEW_node_conn_direct_open_node", DEBUG_DEBUG(DEBUG_CATEGORY_TIMERS, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=NEW_node_conn_direct_open_node",
(unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb());
entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect_node"); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect_node");
DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node NEW node=0x%016llx conn=%p links=%d handles=%d", DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node NEW node=0x%016llx conn=%p links=%d handles=%d",

8
tools/chatgui/src/debug_ui.h
Unescape View File

@ -4,7 +4,7 @@ extern "C" {
#include "../../lib/debug_config.h" #include "../../lib/debug_config.h"
} }
#define GUI_ERROR(fmt, ...) DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, fmt, ##__VA_ARGS__) #define GUI_ERROR(fmt, ...) DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, fmt, ##__VA_ARGS__)
#define GUI_WARN(fmt, ...) DEBUG_WARN(DEBUG_CATEGORY_DEBUG, fmt, ##__VA_ARGS__) #define GUI_WARN(fmt, ...) DEBUG_WARN(DEBUG_CATEGORY_GENERAL, fmt, ##__VA_ARGS__)
#define GUI_INFO(fmt, ...) DEBUG_INFO(DEBUG_CATEGORY_DEBUG, fmt, ##__VA_ARGS__) #define GUI_INFO(fmt, ...) DEBUG_INFO(DEBUG_CATEGORY_GENERAL, fmt, ##__VA_ARGS__)
#define GUI_DEBUG(fmt, ...) DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, fmt, ##__VA_ARGS__) #define GUI_DEBUG(fmt, ...) DEBUG_DEBUG(DEBUG_CATEGORY_GENERAL, fmt, ##__VA_ARGS__)

Write Preview
Loading…
Cancel
Save