diff --git a/src/logging.c b/src/logging.c index 93c1b54..e216f53 100644 --- a/src/logging.c +++ b/src/logging.c @@ -26,7 +26,9 @@ #include #include #include +#include #include +#include static FILE *log_file = NULL; @@ -38,6 +40,18 @@ static FILE *log_file = NULL; static int use_syslog = 0; +/* Get current timestamp with milliseconds (thread-safe) */ +static void get_timestamp_ms(char *buffer, size_t buffer_size) { + struct timeval tv; + struct tm tm_storage; + + gettimeofday(&tv, NULL); + localtime_r(&tv.tv_sec, &tm_storage); + + snprintf(buffer, buffer_size, "%02d:%02d:%02d.%03d", tm_storage.tm_hour, tm_storage.tm_min, + tm_storage.tm_sec, (int)(tv.tv_usec / 1000)); +} + int init_syslog(const char *ident) { if (log_file) { fclose(log_file); @@ -56,7 +70,7 @@ static const char *get_filename(const char *path) { return filename ? filename + 1 : path; } -#define PREAMBLE_WIDTH 35 +#define PREAMBLE_WIDTH 45 static void remove_newlines(char *str) { char *src = str, *dst = str; @@ -107,9 +121,12 @@ void log_message(log_level_t level, const char *file, int line, const char *fmt, const char *filename = get_filename(file); + char timestamp[13]; /* "HH:MM:SS.mmm" */ + get_timestamp_ms(timestamp, sizeof(timestamp)); + char preamble[PREAMBLE_WIDTH + 1]; - int preamble_length = snprintf(preamble, sizeof(preamble), "[%s] %s:%d: ", level_str, filename, - line); + int preamble_length = snprintf(preamble, sizeof(preamble), "[%s] %s %s:%d: ", level_str, + timestamp, filename, line); if (preamble_length > PREAMBLE_WIDTH) { preamble[PREAMBLE_WIDTH] = '\0'; diff --git a/src/oasis-echo.c b/src/oasis-echo.c index 757b6bf..0f16e98 100644 --- a/src/oasis-echo.c +++ b/src/oasis-echo.c @@ -49,6 +49,12 @@ static rate_bucket_t g_sms_bucket; /* Thread-safe call state using __atomic builtins (GCC) */ static call_state_t g_call_state = CALL_STATE_IDLE; +/* Ring timeout: if RINGING_IN persists this long after the last RING URC, + * poll AT+CLCC to confirm. Modem sends RING every ~5s, so 10s gap means + * the carrier forwarded to voicemail without a termination URC. */ +#define RING_TIMEOUT_SEC 10 +static time_t g_last_ring_time = 0; + static call_state_t get_call_state(void) { return __atomic_load_n(&g_call_state, __ATOMIC_ACQUIRE); } @@ -57,6 +63,14 @@ static void set_call_state(call_state_t state) { __atomic_store_n(&g_call_state, state, __ATOMIC_RELEASE); } +static time_t get_last_ring_time(void) { + return __atomic_load_n(&g_last_ring_time, __ATOMIC_ACQUIRE); +} + +static void set_last_ring_time(time_t t) { + __atomic_store_n(&g_last_ring_time, t, __ATOMIC_RELEASE); +} + /* ── Command queue (thread-safe, lock-free SPSC ring) ────────────────── */ #define CMD_QUEUE_SIZE 16 @@ -186,8 +200,12 @@ static void on_urc_event(const urc_event_t *event, void *userdata) { switch (event->type) { case URC_RING: { - /* Suppress duplicate RING events — only publish on first RING */ + set_last_ring_time(time(NULL)); + /* Subsequent RINGs — publish lightweight ring event for MIRAGE/DAWN */ if (get_call_state() == CALL_STATE_RINGING_IN) { + if (mqtt_build_event_json("ring", NULL, json, sizeof(json)) >= 0) { + mqtt_publish_event(json); + } break; } set_call_state(CALL_STATE_RINGING_IN); @@ -224,6 +242,7 @@ static void on_urc_event(const urc_event_t *event, void *userdata) { break; } set_call_state(CALL_STATE_IDLE); + set_last_ring_time(0); const char *reason = (prev == CALL_STATE_DIALING) ? "no_carrier" : "remote_hangup"; struct json_object *extra = json_object_new_object(); json_object_object_add(extra, "reason", json_object_new_string(reason)); @@ -285,7 +304,18 @@ static void on_urc_event(const urc_event_t *event, void *userdata) { case URC_CMTI: { /* Defer SMS read to main thread — calling at_command_send from - * the URC reader would deadlock (reader waits for itself). */ + * the URC reader would deadlock (reader waits for itself). + * Deduplicate: SIM7600 sometimes sends duplicate +CMTI for same index. */ + static int last_cmti_index = -1; + static time_t last_cmti_time = 0; + time_t now_t = time(NULL); + if (event->index == last_cmti_index && (now_t - last_cmti_time) < 3) { + OLOG_INFO("Suppressing duplicate CMTI for index %d", event->index); + break; + } + last_cmti_index = event->index; + last_cmti_time = now_t; + OLOG_INFO("New SMS at index %d, deferring read to main loop", event->index); cmd_entry_t cmd; memset(&cmd, 0, sizeof(cmd)); @@ -467,12 +497,28 @@ static void process_mqtt_command(const cmd_entry_t *cmd) { /* hangup — AT+CHUP works in all call states on SIM7600 (ATH does not) */ if (strcmp(action, "hangup") == 0) { + call_state_t prev = get_call_state(); set_call_state(CALL_STATE_HANGING_UP); at_response_t resp; at_status_t rc = at_command_send(&g_at_ctx, "AT+CHUP", &resp, AT_TIMEOUT_DEFAULT); set_call_state(CALL_STATE_IDLE); - if (rc == AT_OK) { + set_last_ring_time(0); + /* AT+CHUP may return OK or NO CARRIER — both mean the call ended */ + if (rc == AT_OK || rc == AT_NO_CARRIER) { mqtt_publish_response(action, request_id, true, NULL, NULL, NULL); + /* Publish call_ended directly — don't rely on URC which we'll suppress + * since state is already IDLE by the time it arrives. */ + if (prev != CALL_STATE_IDLE) { + char json[1024]; + struct json_object *extra = json_object_new_object(); + json_object_object_add(extra, "reason", json_object_new_string("local_hangup")); + json_object_object_add(extra, "duration", json_object_new_int(0)); + if (mqtt_build_event_json("call_ended", extra, json, sizeof(json)) >= 0) { + mqtt_publish_event(json); + } + json_object_put(extra); + OLOG_INFO("Call ended: local hangup"); + } } else { mqtt_publish_response(action, request_id, false, NULL, at_status_str(rc), "Hangup failed"); } @@ -862,6 +908,37 @@ int main(int argc, char *argv[]) { last_at_success = time(NULL); } + /* Ring timeout watchdog — if ringing for too long without a termination URC, + * poll the modem to confirm call state before transitioning to idle. */ + time_t last_ring = get_last_ring_time(); + if (get_call_state() == CALL_STATE_RINGING_IN && last_ring > 0 && + (now - last_ring) >= RING_TIMEOUT_SEC) { + /* Ask the modem if any calls are active (AT+CLCC lists current calls) */ + at_response_t clcc_resp; + at_status_t clcc_rc = at_command_send(&g_at_ctx, "AT+CLCC", &clcc_resp, 3000); + if (clcc_rc == AT_OK && strstr(clcc_resp.data, "+CLCC:") == NULL) { + /* Modem confirms no active calls — carrier forwarded to voicemail */ + set_call_state(CALL_STATE_IDLE); + set_last_ring_time(0); + char json[1024]; + struct json_object *extra = json_object_new_object(); + json_object_object_add(extra, "reason", json_object_new_string("ring_timeout")); + if (mqtt_build_event_json("call_ended", extra, json, sizeof(json)) >= 0) { + mqtt_publish_event(json); + } + json_object_put(extra); + OLOG_INFO("Ring timeout: modem confirms no active calls after %ds", RING_TIMEOUT_SEC); + } else if (clcc_rc == AT_OK) { + /* Call still active on modem — extend the timeout */ + set_last_ring_time(now); + OLOG_INFO("Ring timeout check: modem reports call still active, extending"); + } else { + /* AT command failed — extend timeout, don't make assumptions */ + set_last_ring_time(now); + OLOG_WARNING("Ring timeout check: AT+CLCC failed (rc=%d), extending", clcc_rc); + } + } + /* Telemetry polling */ if (now - last_telemetry >= config.telemetry_interval_s) { modem_telemetry_t telem;