Forward log level to custom vprintf #3070

eloparco · 2024-01-22T11:52:11Z

Follow-up on #2907.
The log level is needed in the embedded to better integrate with the embedder's logger.

wenyongh · 2024-01-23T00:06:58Z

core/shared/utils/bh_log.c

@@ -51,7 +51,7 @@ bh_log(LogLevel log_level, const char *file, int line, const char *fmt, ...)
        os_printf("%s, line %d, ", file, line);

    va_start(ap, fmt);
-    os_vprintf(fmt, ap);
+    os_vprintf(log_level, fmt, ap);


@eloparco this change introduces lots of code changes, and it makes the code structure a little strange, the platform layer seems to rely on the shared/util layer, and the prototype of os_vprintf is inconsistent with vprintf.
Per my understanding, you want to take control the log dump in your code, how about introducing another macro BH_VLOG like BH_VPRINTF, and call it when it is defined:

va_start(ap, fmt); #if defined(BH_VLOG) BH_VLOG(log_level, fmt, ap); #else os_vprintf(fmt, ap); #endif

Or just defined BH_LOG to replace bh_log function:

#ifndef BH_LOG void bh_log(LogLevel log_level, const char *file, int line, const char *fmt, ...) { ... } #endif and in bh_log.h #ifndef BH_LOG void bh_log(LogLevel log_level, const char *file, int line, const char *fmt, ...); #else void BH_LOG(LogLevel log_level, const char *file, int line, const char *fmt, ...); #define bh_log BH_LOG #endif

Tried that just to make sure, but it doesn't allow to forward the wasm output, coming from os_printf,

wasm-micro-runtime/core/iwasm/libraries/libc-wasi/libc_wasi_wrapper.c

Line 669 in 627debc

err = wasmtime_ssp_fd_write(exec_env, curfds, fd, ciovec_begin, iovs_len,

to the embedder (e.g. the output here

wasm-micro-runtime/samples/basic/wasm-apps/testapp.c

Line 26 in 627debc

printf("calling into WASM function: %s\n", __FUNCTION__);

goes through os_printf but not bh_log).
What I mean is, overriding bh_log only allows to take control of the runtime output, not the wasm one.

Can you define both BH_LOG and BH_VPRINTF? It will forward both bh_log and os_printf.

This reverts commit 1a00803.

This reverts commit 3c48f88.

loganek · 2024-01-23T10:34:27Z

Rather than making ad-hoc changes to unblock some usecases, I'd rather take a step back and refine how do we log in WAMR in general. I think we already have solid foundations to improve logging - we have a bunch of macros (LOG_*) and bh_log function that I think we should use in WAMR instead of calling vprintf() directly.
We can then introduce a concept of log listener that registers to the logger and gets called with various parameters (log level, line, file, message etc.) Then it's up to the user to define its own log handler, where the default one can be the vprintf().

So in high level we'd have something like:

typedef void (*bh_log_listener)(int level, int line, const char* file, const char *message, void *ud); // and other fields like timestamp or whatever we think is appropriate

void bh_log_register_listener(bh_log_listener, void *ud);

void bh_log_default_listener(int level, int line, const char *file, const char *message, void *_ud)
{
    printf(....);
}

So the bh_log() would call the registered listener (or listeners, if we allow having multiple ones) and the listener decides what to do.

@wenyongh let me know your thoughts.

wenyongh · 2024-01-23T11:10:29Z

Rather than making ad-hoc changes to unblock some usecases, I'd rather take a step back and refine how do we log in WAMR in general. I think we already have solid foundations to improve logging - we have a bunch of macros (LOG_*) and bh_log function that I think we should use in WAMR instead of calling vprintf() directly. We can then introduce a concept of log listener that registers to the logger and gets called with various parameters (log level, line, file, message etc.) Then it's up to the user to define its own log handler, where the default one can be the vprintf().

So in high level we'd have something like:
typedef void (*bh_log_listener)(int level, int line, const char* file, const char *message, void *ud); // and other fields like timestamp or whatever we think is appropriate

void bh_log_register_listener(bh_log_listener, void *ud);

void bh_log_default_listener(int level, int line, const char *file, const char *message, void *_ud)
{
    printf(....);
}
So the bh_log() would call the registered listener (or listeners, if we allow having multiple ones) and the listener decides what to do.

@wenyongh let me know your thoughts.

@loganek using a listener (or callback) is good to me, but I have two concerns:
one is about the prototype, if using argument const char *message, then in bh_log function, runtime should output the log to a message buffer, and then call bh_log_default_listener with the buffer, I am not sure how much the buffer should be. Is it better to use const char *format, va_list ap like os_vprintf? Like:

void bh_log_default_listener(int level, const char *file, int line, const char *fmt, va_list ap, void *user_data)

another is whether it can meet the requirement from @eloparco, he wants to forward the log of os_printf also, but in os_printf, we had better not call the listener directly and also the argument level/file/line cannot be passed to it. Should we add the listener in libc-builtin and libc-wasi which eventually call os_printf, liike:
https://github.com/wenyongh/wasm-micro-runtime/blob/update_build_wamr_doc/core/iwasm/libraries/libc-wasi/sandboxed-system-primitives/src/posix.c#L1119-L1141

loganek · 2024-01-23T11:37:05Z

one is about the prototype

The prototype was just an example, we can tune it. It was mainly just to present a high-level concept

he wants to forward the log of os_printf also

I'd separate os_printf and bh_log - those are two separate ones IMO. We should probably keep the existing mechanism for os_printf and change only the logging. Also, I think there's a few places where os_printf is used in the runtime where actually we should bh_log - I think we can gradually update the code to fully migrate to bh_log instead.

wenyongh · 2024-01-23T13:25:33Z

one is about the prototype

The prototype was just an example, we can tune it. It was mainly just to present a high-level concept

he wants to forward the log of os_printf also

I'd separate os_printf and bh_log - those are two separate ones IMO. We should probably keep the existing mechanism for os_printf and change only the logging. Also, I think there's a few places where os_printf is used in the runtime where actually we should bh_log - I think we can gradually update the code to fully migrate to bh_log instead.

But os_printf and bh_log are difference, bh_log outputs more info, e.g. timestamp and thread id, and some developers may feel that os_printf is more convenient since sometimes we are not sure what we should call for bh_log - LOG_ERROR, LOG_WARNING, LOG_DEBUG or LOG_VERBOSE.

loganek · 2024-01-23T14:56:46Z

one is about the prototype

The prototype was just an example, we can tune it. It was mainly just to present a high-level concept

he wants to forward the log of os_printf also

I'd separate os_printf and bh_log - those are two separate ones IMO. We should probably keep the existing mechanism for os_printf and change only the logging. Also, I think there's a few places where os_printf is used in the runtime where actually we should bh_log - I think we can gradually update the code to fully migrate to bh_log instead.

But os_printf and bh_log are difference, bh_log outputs more info, e.g. timestamp and thread id, and some developers may feel that os_printf is more convenient since sometimes we are not sure what we should call for bh_log - LOG_ERROR, LOG_WARNING, LOG_DEBUG or LOG_VERBOSE.

I see why using os_printf is more appealing as it doesn't require thinking about the log level. I'd still encourage developers to use bh_log as it allows filtering the output, even if sometimes it's not easy to decide the level.

Having said that, I feel like this is a separate discussion, independent on the goal that @eloparco is trying to achieve here. I'd keep BH_VPRINTF as it is today, and introduce log listener or BH_LOG as suggested by @wenyongh (I don't have strong opinion on that, I think both approaches have pros and cons).

wenyongh · 2024-01-24T01:30:45Z

build-scripts/config_common.cmake

@@ -338,6 +338,9 @@ endif ()
 if (DEFINED WAMR_BH_VPRINTF)
  add_definitions (-DBH_VPRINTF=${WAMR_BH_VPRINTF})
 endif ()
+if (DEFINED WAMR_BH_LOG)
+  add_definitions (-DBH_LOG=1)


Suggest to be similar with WAMR_BH_VPRINTF:

if (DEFINED WAMR_BH_LOG) add_defintions (-DBH_LOG=${WAMR_BH_LOG}) endif ()

So we only introduce macro BH_LOG to the code, and can use it as a flag to control the code, and developer can define the function with the name he wants.
In bh_log.h:

#ifndef BH_LOG void bh_log(LogLevel log_level, const char *file, int line, const char *fmt, ...); #else void BH_LOG(uint32 log_level, const char *file, int line, const char *fmt, ...); #define bh_log BH_LOG #endif

We can also use WASM_LOG, e.g. add_defintions (-DWASM_LOG=${WAMR_BH_LOG}), but it seems that BH_LOG is better.

Thanks, good point, updated

core/shared/utils/bh_log.h

doc/build_wamr.md

wenyongh · 2024-01-24T01:34:44Z

samples/basic/build.sh

@@ -21,7 +21,7 @@ echo "#####################build basic project"
 cd ${CURR_DIR}
 mkdir -p cmake_build
 cd cmake_build
-cmake .. -DCMAKE_BUILD_TYPE=Debug
+cmake .. -DCMAKE_BUILD_TYPE=Debug -DWAMR_BH_VPRINTF=my_vprintf -DWAMR_BH_LOG=1


How about -DWAMR_BH_LOG=my_log

wenyongh

LGTM

…#3070) Follow-up on bytecodealliance#2907. The log level is needed in the host embedder to better integrate with the embedder's logger. Allow the developer to customize his bh_log callback with `cmake -DWAMR_BH_LOG=<log_callback>`, and update sample/basic to show the usage.

feat(log): forward log level to custom vprintf

3c48f88

eloparco force-pushed the eloparco/add-log-level-in-vprintf-override branch 3 times, most recently from 1508155 to 8e80eda Compare January 22, 2024 14:31

test: add example to show usage of vprintf override

1a00803

eloparco force-pushed the eloparco/add-log-level-in-vprintf-override branch from 8e80eda to 1a00803 Compare January 22, 2024 15:07

wenyongh reviewed Jan 23, 2024

View reviewed changes

eloparco added 2 commits January 23, 2024 09:18

Revert "test: add example to show usage of vprintf override"

5129dec

This reverts commit 1a00803.

Revert "feat(log): forward log level to custom vprintf"

93edc1e

This reverts commit 3c48f88.

wenyongh reviewed Jan 24, 2024

View reviewed changes

feat(logs): redirect wamr logs to logger defined in embedder

41e2acc

eloparco force-pushed the eloparco/add-log-level-in-vprintf-override branch from 1bc6618 to 41e2acc Compare January 24, 2024 01:57

wenyongh reviewed Jan 24, 2024

View reviewed changes

wenyongh merged commit 3fcd798 into bytecodealliance:main Jan 24, 2024
405 checks passed

eloparco mentioned this pull request Jan 29, 2024

Use logger for runtime prints #3097

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Forward log level to custom vprintf #3070

Forward log level to custom vprintf #3070

eloparco commented Jan 22, 2024 •

edited

Loading

wenyongh Jan 23, 2024 •

edited

Loading

eloparco Jan 23, 2024

wenyongh Jan 23, 2024

loganek commented Jan 23, 2024

wenyongh commented Jan 23, 2024

loganek commented Jan 23, 2024

wenyongh commented Jan 23, 2024

loganek commented Jan 23, 2024

wenyongh Jan 24, 2024

eloparco Jan 24, 2024

wenyongh Jan 24, 2024

wenyongh left a comment

Forward log level to custom vprintf #3070

Forward log level to custom vprintf #3070

Conversation

eloparco commented Jan 22, 2024 • edited Loading

wenyongh Jan 23, 2024 • edited Loading

Choose a reason for hiding this comment

eloparco Jan 23, 2024

Choose a reason for hiding this comment

wenyongh Jan 23, 2024

Choose a reason for hiding this comment

loganek commented Jan 23, 2024

wenyongh commented Jan 23, 2024

loganek commented Jan 23, 2024

wenyongh commented Jan 23, 2024

loganek commented Jan 23, 2024

wenyongh Jan 24, 2024

Choose a reason for hiding this comment

eloparco Jan 24, 2024

Choose a reason for hiding this comment

wenyongh Jan 24, 2024

Choose a reason for hiding this comment

wenyongh left a comment

Choose a reason for hiding this comment

eloparco commented Jan 22, 2024 •

edited

Loading

wenyongh Jan 23, 2024 •

edited

Loading