printf_wrapper (libc builtin) makes multiple calls to os_printf with individual characters

[malytomas]

I am using WAMR_BH_VPRINTF to provide custom function in place of os_printf. My function logs the formatted string into a file. Unfortunately, the https://github.com/bytecodealliance/wasm-micro-runtime/blob/8f098a5905d4b9a741933ffdb8a75f493e4e81d8/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c#L407 separates a string into individual characters, calling os_printf multiple times, which breaks the logged messages.

[wenyongh]

Hi, could you try defining macro BUILTIN_LIBC_BUFFERED_PRINTF and enlarging the buffer size with macro BUILTIN_LIBC_BUFFERED_PRINT_SIZE? It only outputs the buffer when \n is met or the buffer is full: https://github.com/bytecodealliance/wasm-micro-runtime/blob/main/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c#L348-L386

[malytomas]

Hi, could you try defining macro BUILTIN_LIBC_BUFFERED_PRINTF and enlarging the buffer size with macro BUILTIN_LIBC_BUFFERED_PRINT_SIZE? It only outputs the buffer when \n is met or the buffer is full: https://github.com/bytecodealliance/wasm-micro-runtime/blob/main/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c#L348-L386

Hi, thanks for bringing these macros to my attention. I have not seen it before.

I have tried it and it loses some text from last few calls to printf in the app. I think preferred approach would be to actually have 1 to 1 mapping between printf in the app and os_printf in the embedder.

Furthermore, by looking in the code, the buffer is not thread safe, and allows mixing text from multiple wamr instances too. Perhaps, could the buffer be moved inside str_context?

[wenyongh]

Yes, moving buffer inside str_context is good, and the text losing may be caused by some remaining characters without '\n' are not dumped. I tried to refactor the code, could you try the patch below:

diff --git a/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c b/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c
index 24edd3c0..f4cf6b8e 100644
--- a/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c
+++ b/core/iwasm/libraries/libc-builtin/libc_builtin_wrapper.c
@@ -321,10 +321,22 @@ fail:
     return false;
 }
 
+#ifndef BUILTIN_LIBC_BUFFERED_PRINTF
+#define BUILTIN_LIBC_BUFFERED_PRINTF 0
+#endif
+
+#ifndef BUILTIN_LIBC_BUFFERED_PRINT_SIZE
+#define BUILTIN_LIBC_BUFFERED_PRINT_SIZE 128
+#endif
+
 struct str_context {
     char *str;
     uint32 max;
     uint32 count;
+#if BUILTIN_LIBC_BUFFERED_PRINTF != 0
+    char print_buf[BUILTIN_LIBC_BUFFERED_PRINT_SIZE];
+    uint32 print_buf_size;
+#endif
 };
 
 static int
@@ -345,41 +357,23 @@ sprintf_out(int c, struct str_context *ctx)
     return c;
 }
 
-#ifndef BUILTIN_LIBC_BUFFERED_PRINTF
-#define BUILTIN_LIBC_BUFFERED_PRINTF 0
-#endif
-
-#ifndef BUILTIN_LIBC_BUFFERED_PRINT_SIZE
-#define BUILTIN_LIBC_BUFFERED_PRINT_SIZE 128
-#endif
-#ifndef BUILTIN_LIBC_BUFFERED_PRINT_PREFIX
-#define BUILTIN_LIBC_BUFFERED_PRINT_PREFIX
-#endif
-
 #if BUILTIN_LIBC_BUFFERED_PRINTF != 0
-
-BUILTIN_LIBC_BUFFERED_PRINT_PREFIX
-static char print_buf[BUILTIN_LIBC_BUFFERED_PRINT_SIZE] = { 0 };
-
-BUILTIN_LIBC_BUFFERED_PRINT_PREFIX
-static int print_buf_size = 0;
-
 static int
 printf_out(int c, struct str_context *ctx)
 {
     if (c == '\n') {
-        print_buf[print_buf_size] = '\0';
-        os_printf("%s\n", print_buf);
-        print_buf_size = 0;
+        ctx->print_buf[ctx->print_buf_size] = '\0';
+        os_printf("%s\n", ctx->print_buf);
+        ctx->print_buf_size = 0;
     }
-    else if (print_buf_size >= sizeof(print_buf) - 2) {
-        print_buf[print_buf_size++] = (char)c;
-        print_buf[print_buf_size] = '\0';
-        os_printf("%s\n", print_buf);
-        print_buf_size = 0;
+    else if (ctx->print_buf_size >= sizeof(ctx->print_buf) - 2) {
+        ctx->print_buf[ctx->print_buf_size++] = (char)c;
+        ctx->print_buf[ctx->print_buf_size] = '\0';
+        os_printf("%s\n", ctx->print_buf);
+        ctx->print_buf_size = 0;
     }
     else {
-        print_buf[print_buf_size++] = (char)c;
+        ctx->print_buf[ctx->print_buf_size++] = (char)c;
     }
     ctx->count++;
     return c;
@@ -398,7 +392,9 @@ static int
 printf_wrapper(wasm_exec_env_t exec_env, const char *format, _va_list va_args)
 {
     wasm_module_inst_t module_inst = get_module_inst(exec_env);
-    struct str_context ctx = { NULL, 0, 0 };
+    struct str_context ctx = { 0 };
+
+    memset(&ctx, 0, sizeof(ctx));
 
     /* format has been checked by runtime */
     if (!validate_native_addr(va_args, (uint64)sizeof(int32)))
@@ -408,6 +404,11 @@ printf_wrapper(wasm_exec_env_t exec_env, const char *format, _va_list va_args)
                      module_inst))
         return 0;
 
+#if BUILTIN_LIBC_BUFFERED_PRINTF != 0
+    if (ctx.print_buf_size > 0)
+        os_printf("%s", ctx.print_buf);
+#endif
+
     return (int)ctx.count;
 }

[malytomas]

This works for me. Awesome. Thanks ;)

[wenyongh]

Welcome. #3460

[malytomas]

Thanks ;)