mirror of
https://github.com/coturn/coturn.git
synced 2026-10-24 00:08:57 +03:00
62662ec53e
## What Makes the default log line parseable by a log shipper with no configuration. Rebased on `master` (`441d3e9c`, which now includes #2030). Before: ``` 0: (18446744073709551615): INFO: Listener address to use: 127.0.0.1 ``` After: ``` 2026-08-02T17:32:31.297-0700 INFO Listener address to use: 127.0.0.1 ``` Two commits: | Commit | Change | |---|---| | `Cache the rendered log timestamp per thread, add millisecond precision` | perf + sub-second resolution | | `Log format: ISO-8601 by default, drop thread id, space delimiter` | the format change itself | ## Why **ISO-8601 by default.** The previous default was a counter of seconds since process start — no wall-clock time at all, so nothing downstream can order or window on it. `--new-log-timestamp` now also honours its boolean argument; it previously ignored the value and could only be turned *on*, so with the default flipped there would have been no way back. `--new-log-timestamp=false` restores the counter. **Thread id removed.** It was emitted as a bare unlabelled `(N)`, indistinguishable from any parenthesised number in a message body. Worse, it was gated on `#ifdef SYS_gettid` — a test for whether the *constant* exists, not whether the syscall does what was intended. macOS defines `SYS_gettid` as a different syscall, so the call failed with `ESRCH` and every line on every macOS build carried `(18446744073709551615)`, i.e. `(unsigned long)(pid_t)-1`: ``` SYS_gettid defined = 286 syscall(SYS_gettid) = -1 errno=3 (No such process) as (unsigned long)(pid_t)r = 18446744073709551615 ``` Dropping it also removes the deprecated `syscall(2)` use on macOS. **Space delimiter.** `:` cannot delimit anything a parser can rely on — message bodies are full of it (`realm <north.gov> user <>: ...`). These two changes are coupled: the ISO timestamp emitted *no* trailing separator (the `(tid): ` supplied it), so removing the thread id alone would have produced `...-0700INFO`. The renderer now emits only the timestamp and the caller adds one space. **Millisecond precision** (first commit). Log shippers need sub-second resolution to order records within a second, which a busy relay produces in bulk. `strftime()` has no sub-second conversion, so `%f` is expanded to milliseconds (`%%f` is left alone) and the default format is `%FT%T.%f%z`. **Timestamp caching** (first commit). Everything down to the second only changes once a second, but was re-rendered per line — and `localtime_r()` takes a lock inside libc, so relay threads serialised on it and per-line cost *grew* with thread count. Now cached in thread-local storage keyed on the second, with only the millisecond digits patched in per line. A generation counter bumped by `set_turn_log_timestamp_format()` invalidates live caches on a format change; a format rendering longer than the cache falls back to the caller's buffer. Timestamp rendering, 12 threads on a 12-core machine: | threads | before (no ms) | after (with ms) | |---|---:|---:| | 1 | 163 ns/line | 24 ns/line | | 4 | 53 ns/line | 6 ns/line | | 12 | **304 ns/line** | **3 ns/line** | ## Acceptance check Output run against the stock logstash pattern `%{TIMESTAMP_ISO8601:ts} %{LOGLEVEL:level} %{GREEDYDATA:msg}` — **43/44 startup lines parse with no further configuration**, fields extracting correctly. The one failure is pre-existing: the banner at `mainrelay.c:3211` embeds `\n\n` *inside* the message, so its text lands on a line with no prefix. The right fix is newline normalisation in the logger, not patching call sites; deferred to the `--log-format` work. ## Compatibility This is a visible break for anyone parsing coturn logs. `--new-log-timestamp=false` restores the old timestamp but not the thread id or the colons — there is no single flag that restores the previous line verbatim. Worth pairing with the remaining logging changes in one release and one changelog entry. ## Testing All re-run after the rebase onto `441d3e9c`. **Linux (Docker)** - `ctest` 17/17 - `run_tests.sh`, `run_tests_conf.sh`, `run_tests_mobile.sh`, `run_tests_multiplex_peer.sh`, `run_tests_rfc5780.sh`, `run_tests_stateless_nonce.sh`, `run_tests_dtls_default.sh` — all `rc=0`, zero `FAIL` lines - Both timestamp modes confirmed on glibc: `2026-08-03T00:46:59.742+0000 INFO ...` and, with `--new-log-timestamp=false`, `0 INFO ...` **macOS** - `ctest` 18/18; `run_tests.sh`, `run_tests_conf.sh`, `run_tests_mobile.sh`, `run_tests_stateless_nonce.sh` — all `rc=0`, zero `FAIL` lines - `clang-format` clean **Fuzzing smoke** - `fuzzing/run-local.sh ASan 0 -runs=1` and `ASan 1 -runs=1` — both clean, no new findings **Format matrix**, by hand on both platforms — default, `--new-log-timestamp=false`, explicit on, and the same three through the **config-file** path (a separate parser, also changed). **Timestamp-cache correctness** — milliseconds vary per line (51 distinct timestamps across 7 seconds under traffic); format edge cases: no `%f`, `%f` alone, `%f` at start, `%f` at end, `100%%f-%T.%f` (escaped `%%f` stays literal while the real one expands), and a >128-byte format hitting the fallback. The MSVC branch of `turn_wall_clock()` (`GetSystemTimeAsFileTime`) is inspection-only — there is no MSVC toolchain here, so CI is the first real check on it. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
Before you begin * copy db schema run ./cp-schema.sh * edit coturn/turnserver.conf according your db selection (mysql or postgresql or redis or mongodb) # start docker-compose -f docker-compose-all.yml up --build --detach # restart Notice: May restart needed for coturn container, if it could not access database yet, due initialization delay. docker restart docker_coturn_1 # stop docker-compose -f docker-compose-all.yml down # Or Stop with volume removal docker-compose down --volumes