Skip to content

add set_log_hook/1 #266

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Oct 19, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
65 changes: 65 additions & 0 deletions c_src/sqlite3_nif.c
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,9 @@ static ErlNifResourceType* connection_type = NULL;
static ErlNifResourceType* statement_type = NULL;
static sqlite3_mem_methods default_alloc_methods = {0};

ErlNifPid* log_hook_pid = NULL;
ErlNifMutex* log_hook_mutex = NULL;

typedef struct connection
{
sqlite3* db;
Expand Down Expand Up @@ -956,6 +959,11 @@ on_load(ErlNifEnv* env, void** priv, ERL_NIF_TERM info)
return -1;
}

log_hook_mutex = enif_mutex_create("exqlite:log_hook");
if (!log_hook_mutex) {
return -1;
}

return 0;
}

Expand All @@ -965,6 +973,7 @@ on_unload(ErlNifEnv* caller_env, void* priv_data)
assert(caller_env);

sqlite3_config(SQLITE_CONFIG_MALLOC, &default_alloc_methods);
enif_mutex_destroy(log_hook_mutex);
}

//
Expand Down Expand Up @@ -1065,6 +1074,61 @@ exqlite_set_update_hook(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[])
return make_atom(env, "ok");
}

//
// Log Notifications
//

void
log_callback(void* arg, int iErrCode, const char* zMsg)
{
if (log_hook_pid == NULL) {
return;
}

ErlNifEnv* msg_env = enif_alloc_env();
ERL_NIF_TERM error = make_binary(msg_env, zMsg, strlen(zMsg));
ERL_NIF_TERM msg = enif_make_tuple3(msg_env, make_atom(msg_env, "log"), enif_make_int(msg_env, iErrCode), error);

if (!enif_send(NULL, log_hook_pid, msg_env, msg)) {
enif_mutex_lock(log_hook_mutex);
sqlite3_config(SQLITE_CONFIG_LOG, NULL, NULL);
enif_free(log_hook_pid);
log_hook_pid = NULL;
enif_mutex_unlock(log_hook_mutex);
}

enif_free_env(msg_env);
}

static ERL_NIF_TERM
exqlite_set_log_hook(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[])
{
assert(env);

if (argc != 1) {
return enif_make_badarg(env);
}

ErlNifPid* pid = (ErlNifPid*)enif_alloc(sizeof(ErlNifPid));
if (!enif_get_local_pid(env, argv[0], pid)) {
enif_free(pid);
return make_error_tuple(env, "invalid_pid");
}

enif_mutex_lock(log_hook_mutex);

if (log_hook_pid) {
enif_free(log_hook_pid);
}

log_hook_pid = pid;
sqlite3_config(SQLITE_CONFIG_LOG, log_callback, NULL);
Copy link
Member

Choose a reason for hiding this comment

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

It's a shame this log hook is global like this. I wish it were on a per sqlite database basis, but alas it is not. But I supposed you would only utilize this in a dev or test environment to track down a bug.

Copy link
Contributor Author

@ruslandoga ruslandoga Oct 19, 2023

Choose a reason for hiding this comment

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

The reason it's not per database is -- I guess -- to also be able to cover errors coming from opening invalid databases and some other operations that happen prior to getting a reference to a database.

The docs actually suggest using it in production: https://www.sqlite.org/errlog.html

Developers are encouraged to implement an error logger callback early in the development cycle in order to spot unexpected behavior quickly, and to leave the error logger callback turned on through deployment.


enif_mutex_unlock(log_hook_mutex);

return make_atom(env, "ok");
}

//
// Most of our nif functions are going to be IO bounded
//
Expand All @@ -1086,6 +1150,7 @@ static ErlNifFunc nif_funcs[] = {
{"release", 2, exqlite_release, ERL_NIF_DIRTY_JOB_IO_BOUND},
{"enable_load_extension", 2, exqlite_enable_load_extension, ERL_NIF_DIRTY_JOB_IO_BOUND},
{"set_update_hook", 2, exqlite_set_update_hook, ERL_NIF_DIRTY_JOB_IO_BOUND},
{"set_log_hook", 1, exqlite_set_log_hook, ERL_NIF_DIRTY_JOB_IO_BOUND},
};

ERL_NIF_INIT(Elixir.Exqlite.Sqlite3NIF, nif_funcs, on_load, NULL, NULL, on_unload)
26 changes: 25 additions & 1 deletion lib/exqlite/sqlite3.ex
Original file line number Diff line number Diff line change
Expand Up @@ -223,7 +223,7 @@ defmodule Exqlite.Sqlite3 do
* Only one pid can listen to the changes on a given database connection at a time.
If this function is called multiple times for the same connection, only the last pid will
receive the notifications
* Updates only happen for the connection that is opened. For example, there
* Updates only happen for the connection that is opened. For example, there
are two connections A and B. When an update happens on connection B, the
hook set for connection A will not receive the update, but the hook for
connection B will receive the update.
Expand All @@ -233,6 +233,30 @@ defmodule Exqlite.Sqlite3 do
Sqlite3NIF.set_update_hook(conn, pid)
end

@doc """
Send log messages to a process.

Each time a message is logged in SQLite a message will be sent to the pid provided as the argument.

The message is of the form: `{:log, rc, message}`, where:

* `rc` is an integer [result code](https://www.sqlite.org/rescode.html) or an [extended result code](https://www.sqlite.org/rescode.html#extrc)
* `message` is a string representing the log message

See [`SQLITE_CONFIG_LOG`](https://www.sqlite.org/c3ref/c_config_covering_index_scan.html) and
["The Error And Warning Log"](https://www.sqlite.org/errlog.html) for more details.

## Restrictions

* Only one pid can listen to the log messages at a time.
If this function is called multiple times, only the last pid will
receive the notifications
"""
@spec set_log_hook(pid()) :: :ok | {:error, reason()}
def set_log_hook(pid) do
Sqlite3NIF.set_log_hook(pid)
end

defp convert(%Date{} = val), do: Date.to_iso8601(val)
defp convert(%Time{} = val), do: Time.to_iso8601(val)
defp convert(%NaiveDateTime{} = val), do: NaiveDateTime.to_iso8601(val)
Expand Down
3 changes: 3 additions & 0 deletions lib/exqlite/sqlite3_nif.ex
Original file line number Diff line number Diff line change
Expand Up @@ -67,5 +67,8 @@ defmodule Exqlite.Sqlite3NIF do
@spec set_update_hook(db(), pid()) :: :ok | {:error, reason()}
def set_update_hook(_conn, _pid), do: :erlang.nif_error(:not_loaded)

@spec set_log_hook(pid()) :: :ok | {:error, reason()}
def set_log_hook(_pid), do: :erlang.nif_error(:not_loaded)

# add statement inspection tooling https://sqlite.org/c3ref/expanded_sql.html
end
56 changes: 56 additions & 0 deletions test/exqlite/sqlite3_test.exs
Original file line number Diff line number Diff line change
Expand Up @@ -491,4 +491,60 @@ defmodule Exqlite.Sqlite3Test do
refute_receive {{:insert, "main", "test", 1}, _}, 1000
end
end

describe "set_log_hook/1" do
setup do
{:ok, conn} = Sqlite3.open(":memory:")
on_exit(fn -> Sqlite3.close(conn) end)
{:ok, conn: conn}
end

test "can receive errors", %{conn: conn} do
assert :ok = Sqlite3.set_log_hook(self())

assert {:error, reason} = Sqlite3.prepare(conn, "some invalid sql")
assert reason == "near \"some\": syntax error"

assert_receive {:log, rc, msg}
assert rc == 1
assert msg == "near \"some\": syntax error in \"some invalid sql\""
refute_receive _anything_else
end

test "only one pid can listen at a time", %{conn: conn} do
assert :ok = Sqlite3.set_log_hook(self())

task =
Task.async(fn ->
:ok = Sqlite3.set_log_hook(self())
assert {:error, reason} = Sqlite3.prepare(conn, "some invalid sql")
assert reason == "near \"some\": syntax error"
assert_receive {:log, rc, msg}
assert rc == 1
assert msg == "near \"some\": syntax error in \"some invalid sql\""
refute_receive _anything_else
end)

Task.await(task)
refute_receive _anything_else
end

test "receives notifications from all connections", %{conn: conn1} do
assert :ok = Sqlite3.set_log_hook(self())
assert {:ok, conn2} = Sqlite3.open(":memory:")
on_exit(fn -> Sqlite3.close(conn2) end)

assert {:error, _reason} = Sqlite3.prepare(conn1, "some invalid sql 1")
assert_receive {:log, rc, msg}
assert rc == 1
assert msg == "near \"some\": syntax error in \"some invalid sql 1\""
refute_receive _anything_else

assert {:error, _reason} = Sqlite3.prepare(conn2, "some invalid sql 2")
assert_receive {:log, rc, msg}
assert rc == 1
assert msg == "near \"some\": syntax error in \"some invalid sql 2\""
refute_receive _anything_else
end
end
end