Skip to content

Add non-blocking native logger for NIF and CNode backends - #123

Open
khamilowicz wants to merge 18 commits into
masterfrom
new-logger
Open

Add non-blocking native logger for NIF and CNode backends#123
khamilowicz wants to merge 18 commits into
masterfrom
new-logger

Conversation

@khamilowicz

Copy link
Copy Markdown
Contributor

Summary

  • Adds a thread-safe, non-blocking logger (unifex_log()) that native NIF/CNode code can call to send log messages to the BEAM, forwarded through a new Unifex.Logger GenServer to Elixir's Logger. Works identically for both backends.
  • Unifex.Logger is opt-in (config :unifex, enable_logger: true) so consumers that never log don't pay for an idle process/thread.
  • Fixes the include path so any consumer can #include <unifex/logger.h> with no extra bundlex config, plus several native-side safety fixes (NULL message guard, pthread_create failure handling, retry-on-failure for the NIF fallback env).
  • Adds a guide (pages/logger.md) and test coverage (unit tests, an integration test project, and a wired-in integration test run).

Test plan

  • mix test (repo test suite, including new logger unit/integration tests and the logger_test integration project)
  • mix docs builds cleanly with the new guide
  • Verified end-to-end against a standalone example NIF project: config enables Unifex.Logger, unifex_log() calls are received and forwarded to Logger with correct formatting/metadata
  • CNode backend logging exercised only via a successful build, not a live end-to-end run (would need a real ei-connected CNode test harness)

🤖 Generated with Claude Code

khamilowicz and others added 10 commits July 2, 2026 15:45
- Made logger.h backend-agnostic by removing NIF-specific includes
- Added forward declarations for UnifexEnv and UnifexPid
- Created callback-based send function mechanism
- Added unifex_send and unifex_get_pid_by_name to CNode backend
- Created logger_nif.c with NIF-specific send implementation
- Created logger_cnode.c with CNode-specific send implementation
- Added convenience headers (logger_nif.h, logger_cnode.h)
- Updated bundlex.exs to include backend-specific logger files
- Added logger_backend.h for send function declarations

The logger now works with both NIF and CNode by:
1. Using a common core implementation (logger.c)
2. Providing backend-specific send functions
3. Allowing users to register the appropriate send function for their backend

Generated by Mistral Vibe.
Co-Authored-By: Mistral Vibe <vibe@mistral.ai>
Unifex.Logger no longer starts by default, since most unifex consumers
never call unifex_log(); it's now enabled via `config :unifex,
enable_logger: true`.

Also fixes several correctness issues in the native logger: a NULL
message would crash via strdup(NULL), a failed pthread_create() left a
thread handle that unifex_logger_cleanup() would later join anyway
(UB), and the NIF backend's fallback env was allocated once from a
dlopen-time constructor with no retry, permanently disabling logging on
transient allocation failure.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
logger.h and logger_backend.h live outside both the nif/ and cnode/
source trees, so consumers had no portable include path to reach them
(only a relative-path workaround assuming a sibling checkout worked).
Add the shared directory to the unifex lib's includes so any project
with `deps: [unifex: :unifex]` can `#include <unifex/logger.h>` with
no extra bundlex configuration.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
test_projects/logger_test's handle_load callback referenced a state
struct and a handle_load_result_ok macro the spec never declared,
breaking the build; both were unnecessary; the logger wires itself up
automatically so no load callback is needed. Also switch its include
to <unifex/logger.h> now that it's a real include path, drop the local
logger.h copy that worked around its absence, and wire the project's
mix test into the main repo's integration test suite.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
khamilowicz and others added 2 commits July 7, 2026 13:29
Adds a guide covering enabling Unifex.Logger, the unifex_log() C API,
where messages end up and how they're formatted, and queue/overflow
behavior - verified against a working example project rather than
written from the API alone.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
khamilowicz and others added 4 commits July 7, 2026 13:34
logger_test/mix.exs was missing the deps_path/lockfile overrides that
every other test_projects/* project uses, so mix test tried to fetch
its own deps instead of reusing the already-fetched top-level ones,
failing CI with "dependency not available".

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
test/fixtures/nif_ref_generated/nif/example.{c,cpp} were regenerated
and committed on a machine with clang-format 22, which formats
chained && differently (adds a space: "a && b") than the clang-format
14 used by CI's Ubuntu container ("a &&b"). That drift broke the "NIF
test project" integration test, which compares freshly generated code
against these fixtures. Reverted the affected lines to match CI's
clang-format output, verified by running the test inside the
membraneframeworklabs/docker_membrane image used by CI.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
do_logger_test_project/3 received interface but never used it (the
logger_test project doesn't yet vary its assertions by NIF vs CNode),
which failed mix test --warnings-as-errors in CI.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Comment thread lib/unifex/logger.ex Outdated

@doc false
@spec normalize_level(atom()) :: atom()
def normalize_level(level) when level in @valid_levels, do: level

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we have to support unnormalized log levels? What would cause having such a level?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

User can pass any string to unifex_log, so it is possible to break it.

@FelonEkonom FelonEkonom Jul 28, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could provide an enum to specify a log level. It would remove the risk of user making a typo and the need for handling invalid log levels.

// one of these to stay serialized via socket_mutex.
int unifex_cnode_locked_send(UnifexEnv *env, erlang_pid *pid, char *buff,
int len) {
pthread_mutex_lock(&env->socket_mutex);

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Correct me if I am wrong, but I thought that all we have to do from the C side is to do a proper send to a proper process (the same way as original Elixir Logger works under the hood, AFAIK).

If so, why do we need any locks or mutexes in the code?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I discussed with @varsill about drawing inspiration from this Rust logger for NIFs. The library uses a queue to send messages to a GenServer in an orderly way.
Since this logger is meant to log messages executed in C, we want to avoid making it a bottleneck. The main issue with the previous implementation was that looking up the GenServer process by name was extremely time-consuming and shouldn’t happen on the main thread. Caching the PID would be unreliable, as the process could terminate at any moment. This implementation processes messages on a separate thread, ensuring it doesn’t slow down the main job.

@FelonEkonom FelonEkonom Jul 28, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you discussed the shape of the implementation with @varsill, I think he should be marked as a reviewer too.
BTW what is the time difference between sending message to a process by atom name vs PID? I hear about it for the first time, is it really a big deal? I am curious 🤔

Comment thread c_src/unifex/cnode/unifex/cnode.c
Comment thread lib/unifex/logger.ex Outdated
Comment thread lib/unifex/app.ex
# The native logger queue/worker thread (see c_src/unifex/unifex/logger.c)
# is compiled into every unifex consumer, but only projects that actually
# call unifex_log() need this GenServer running to receive its messages.
defp logger_enabled?, do: Application.get_env(:unifex, :enable_logger, false)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why did you make starting logger configurable? Why does it default to false?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, if you don't use logger in the native code, why start it? Native logger is not the main feature of unifex, so it doesn't need to be obligatory.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, but this could be an another reason to avoid spawning helper logging processes

Comment thread lib/unifex/logger.ex Outdated
Comment on lines +1 to +11
defmodule Unifex.Logger do
@moduledoc """
Generic logger for handling log messages from C NIFs via Unifex.

This process receives log messages from C code and forwards them to Elixir's Logger.
It can be used by any NIF library that needs to log messages to the BEAM.

Not started by default. Enable it with:

config :unifex, enable_logger: true
"""

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is this module a part of public API?

  This process receives log messages from C code and forwards them to Elixir's Logger.
  It can be used by any NIF library that needs to log messages to the BEAM.
  • it might be true, but why is it mentioned in docs? if somebody wants to log something, he should just call unifex_log function from C, no need to sending anything explicitly to this module

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You mean that docs should be removed, right? no problem

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I mean that public docs should describe public API and how our library behaves from the outside because it is what interests developers using our library. Whereas, by default, it should not be a description of how Unifex works from the inside (it may do it in cases where it make sense, in order to describe tool's outside behaviour)

Comment thread README.md
Comment thread mix.exs
"pages/supported_types.md",
"pages/logger.md"
],
skip_undefined_reference_warnings_on: ["pages/logger.md"],

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we skip undefined reference warnings? Is it because of marking Logger moduledoc as false?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes

// one of these to stay serialized via socket_mutex.
int unifex_cnode_locked_send(UnifexEnv *env, erlang_pid *pid, char *buff,
int len) {
pthread_mutex_lock(&env->socket_mutex);

@FelonEkonom FelonEkonom Jul 28, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you discussed the shape of the implementation with @varsill, I think he should be marked as a reviewer too.
BTW what is the time difference between sending message to a process by atom name vs PID? I hear about it for the first time, is it really a big deal? I am curious 🤔

Comment thread lib/unifex/app.ex
# The native logger queue/worker thread (see c_src/unifex/unifex/logger.c)
# is compiled into every unifex consumer, but only projects that actually
# call unifex_log() need this GenServer running to receive its messages.
defp logger_enabled?, do: Application.get_env(:unifex, :enable_logger, false)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, but this could be an another reason to avoid spawning helper logging processes

Comment thread lib/unifex/logger.ex Outdated

@doc false
@spec normalize_level(atom()) :: atom()
def normalize_level(level) when level in @valid_levels, do: level

@FelonEkonom FelonEkonom Jul 28, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could provide an enum to specify a log level. It would remove the risk of user making a typo and the need for handling invalid log levels.

@FelonEkonom
FelonEkonom requested a review from varsill July 28, 2026 11:29
@khamilowicz
khamilowicz requested a review from FelonEkonom July 30, 2026 12:32
@khamilowicz
khamilowicz force-pushed the new-logger branch 2 times, most recently from 34409c3 to 309c878 Compare July 30, 2026 13:29
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants