[PATCH v4 0/1] MR2274: ntdll: Add source file and line to debug traces.

[Rémi Bernon]

--
  v4: ntdll: Add source and return address information to debug traces.
 
https://gitlab.winehq.org/wine/wine/-/merge_requests/2274

[PATCH v4 1/1] ntdll: Add source and return address information to debug traces.

[Rémi Bernon]

From: Rémi Bernon <rbernon(a)codeweavers.com>

---
 dlls/msxml3/main.c           |  8 ++---
 dlls/ntdll/thread.c          | 31 ++++++++++++++++---
 dlls/ntdll/unix/debug.c      | 31 ++++++++++++++++---
 dlls/windowscodecs/libtiff.c |  4 +--
 dlls/winecrt0/debug.c        | 42 +++++++++++++++++--------
 include/wine/debug.h         | 60 ++++++++++++++++++++++++++----------
 6 files changed, 131 insertions(+), 45 deletions(-)

diff --git a/dlls/msxml3/main.c b/dlls/msxml3/main.c
index 66e23114bfa..c6b6b51f68a 100644
--- a/dlls/msxml3/main.c
+++ b/dlls/msxml3/main.c
@@ -74,7 +74,7 @@ void wineXmlCallbackLog(char const* caller, xmlErrorLevel lvl, char const* msg,
     len = vsnprintf(buff, max_size, msg, ap);
     if (len == -1 || len >= max_size) buff[max_size-1] = 0;
 
-    wine_dbg_log(dbcl, &__wine_dbch_msxml, caller, "%s", buff);
+    wine_dbg_log(dbcl, &__wine_dbch_msxml, __FILE__, __LINE__, caller, __WINE_DBG_RETADDR, "%s", buff);
 }
 
 void wineXmlCallbackError(char const* caller, xmlErrorPtr err)
@@ -88,11 +88,11 @@ void wineXmlCallbackError(char const* caller, xmlErrorPtr err)
     default:              dbcl = __WINE_DBCL_ERR; break;
     }
 
-    wine_dbg_log(dbcl, &__wine_dbch_msxml, caller, "error code %d", err->code);
+    wine_dbg_log(dbcl, &__wine_dbch_msxml, __FILE__, __LINE__, caller, __WINE_DBG_RETADDR, "error code %d", err->code);
     if (err->message)
-        wine_dbg_log(dbcl, &__wine_dbch_msxml, caller, ": %s", err->message);
+        wine_dbg_log(dbcl, &__wine_dbch_msxml, __FILE__, __LINE__, caller, __WINE_DBG_RETADDR, ": %s", err->message);
     else
-        wine_dbg_log(dbcl, &__wine_dbch_msxml, caller, "\n");
+        wine_dbg_log(dbcl, &__wine_dbch_msxml, __FILE__, __LINE__, caller, __WINE_DBG_RETADDR, "\n");
 }
 
 /* Support for loading xml files from a Wine Windows drive */
diff --git a/dlls/ntdll/thread.c b/dlls/ntdll/thread.c
index 01733585a75..48171312d4e 100644
--- a/dlls/ntdll/thread.c
+++ b/dlls/ntdll/thread.c
@@ -34,6 +34,8 @@
 WINE_DEFAULT_DEBUG_CHANNEL(thread);
 WINE_DECLARE_DEBUG_CHANNEL(relay);
 WINE_DECLARE_DEBUG_CHANNEL(pid);
+WINE_DECLARE_DEBUG_CHANNEL(source);
+WINE_DECLARE_DEBUG_CHANNEL(retaddr);
 WINE_DECLARE_DEBUG_CHANNEL(timestamp);
 
 struct _KUSER_SHARED_DATA *user_shared_data = (void *)0x7ffe0000;
@@ -131,11 +133,11 @@ const char * __cdecl __wine_dbg_strdup( const char *str )
  *		__wine_dbg_header  (NTDLL.@)
  */
 int __cdecl __wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
-                               const char *function )
+                               const struct __wine_debug_context *context )
 {
     static const char * const classes[] = { "fixme", "err", "warn", "trace" };
     struct debug_info *info = get_info();
-    char *pos = info->output;
+    char *pos = info->output, *end = pos + sizeof(info->output);
 
     if (!(__wine_dbg_get_channel_flags( channel ) & (1 << cls))) return -1;
 
@@ -149,9 +151,28 @@ int __cdecl __wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_
     }
     if (TRACE_ON(pid)) pos += sprintf( pos, "%04lx:", GetCurrentProcessId() );
     pos += sprintf( pos, "%04lx:", GetCurrentThreadId() );
-    if (function && cls < ARRAY_SIZE( classes ))
-        pos += snprintf( pos, sizeof(info->output) - (pos - info->output), "%s:%s:%s ",
-                         classes[cls], channel->name, function );
+    if (cls < ARRAY_SIZE( classes )) pos += snprintf( pos, end - pos, "%s:", classes[cls] );
+    pos += snprintf( pos, end - pos, "%s:", channel->name );
+
+    if (context && context->compat)
+        pos += snprintf( pos, end - pos, "%s ", (const char *)context );
+    else if (context && context->version == WINE_DEBUG_CONTEXT_VERSION)
+    {
+        if (TRACE_ON(retaddr)) pos += snprintf( pos, end - pos, "%012Ix:", (SIZE_T)context->retaddr );
+        if (TRACE_ON(source))
+        {
+            const char *tmp, *file;
+
+            if ((tmp = strrchr( context->file, '/' ))) file = tmp + 1;
+            else if ((tmp = strrchr( context->file, '\\' ))) file = tmp + 1;
+            else file = context->file;
+
+            pos += snprintf( pos, end - pos, "%s:%d:", file, context->line );
+        }
+
+        pos += snprintf( pos, end - pos, "%s ", context->function );
+    }
+
     info->out_pos = pos - info->output;
     return info->out_pos;
 }
diff --git a/dlls/ntdll/unix/debug.c b/dlls/ntdll/unix/debug.c
index bc0e3c1c694..9a035773356 100644
--- a/dlls/ntdll/unix/debug.c
+++ b/dlls/ntdll/unix/debug.c
@@ -43,6 +43,8 @@
 #include "wine/debug.h"
 
 WINE_DECLARE_DEBUG_CHANNEL(pid);
+WINE_DECLARE_DEBUG_CHANNEL(source);
+WINE_DECLARE_DEBUG_CHANNEL(retaddr);
 WINE_DECLARE_DEBUG_CHANNEL(timestamp);
 WINE_DEFAULT_DEBUG_CHANNEL(ntdll);
 
@@ -302,11 +304,11 @@ int __cdecl __wine_dbg_output( const char *str )
  *		__wine_dbg_header  (NTDLL.@)
  */
 int __cdecl __wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
-                               const char *function )
+                               const struct __wine_debug_context *context )
 {
     static const char * const classes[] = { "fixme", "err", "warn", "trace" };
     struct debug_info *info = get_info();
-    char *pos = info->output;
+    char *pos = info->output, *end = pos + sizeof(info->output);
 
     if (!(__wine_dbg_get_channel_flags( channel ) & (1 << cls))) return -1;
 
@@ -323,9 +325,28 @@ int __cdecl __wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_
         if (TRACE_ON(pid)) pos += sprintf( pos, "%04x:", (UINT)GetCurrentProcessId() );
         pos += sprintf( pos, "%04x:", (UINT)GetCurrentThreadId() );
     }
-    if (function && cls < ARRAY_SIZE( classes ))
-        pos += snprintf( pos, sizeof(info->output) - (pos - info->output), "%s:%s:%s ",
-                         classes[cls], channel->name, function );
+    if (cls < ARRAY_SIZE( classes )) pos += snprintf( pos, end - pos, "%s:", classes[cls] );
+    pos += snprintf( pos, end - pos, "%s:", channel->name );
+
+    if (context && context->compat)
+        pos += snprintf( pos, end - pos, "%s ", (const char *)context );
+    else if (context && context->version == WINE_DEBUG_CONTEXT_VERSION)
+    {
+        if (TRACE_ON(retaddr)) pos += snprintf( pos, end - pos, "%012zx:", (size_t)context->retaddr );
+        if (TRACE_ON(source))
+        {
+            const char *tmp, *file;
+
+            if ((tmp = strrchr( context->file, '/' ))) file = tmp + 1;
+            else if ((tmp = strrchr( context->file, '\\' ))) file = tmp + 1;
+            else file = context->file;
+
+            pos += snprintf( pos, end - pos, "%s:%d:", file, context->line );
+        }
+
+        pos += snprintf( pos, end - pos, "%s ", context->function );
+    }
+
     info->out_pos = pos - info->output;
     return info->out_pos;
 }
diff --git a/dlls/windowscodecs/libtiff.c b/dlls/windowscodecs/libtiff.c
index 16701a258f9..06b6ffaa339 100644
--- a/dlls/windowscodecs/libtiff.c
+++ b/dlls/windowscodecs/libtiff.c
@@ -39,14 +39,14 @@ WINE_DECLARE_DEBUG_CHANNEL(tiff);
 static void tiff_error_handler( const char *module, const char *format, va_list args )
 {
     if (!ERR_ON(tiff)) return;
-    if (wine_dbg_vlog( __WINE_DBCL_ERR, &__wine_dbch_tiff, module, format, args ) != -1)
+    if (wine_dbg_vlog( __WINE_DBCL_ERR, &__wine_dbch_tiff, __FILE__, __LINE__, module, __WINE_DBG_RETADDR, format, args ) != -1)
         __wine_dbg_output( "\n" );
 }
 
 static void tiff_warning_handler( const char *module, const char *format, va_list args )
 {
     if (!WARN_ON(tiff)) return;
-    if (wine_dbg_vlog( __WINE_DBCL_WARN, &__wine_dbch_tiff, module, format, args ) != -1)
+    if (wine_dbg_vlog( __WINE_DBCL_WARN, &__wine_dbch_tiff, __FILE__, __LINE__, module, __WINE_DBG_RETADDR, format, args ) != -1)
         __wine_dbg_output( "\n" );
 }
 
diff --git a/dlls/winecrt0/debug.c b/dlls/winecrt0/debug.c
index 2ac4505fb85..3a8b2372dab 100644
--- a/dlls/winecrt0/debug.c
+++ b/dlls/winecrt0/debug.c
@@ -29,14 +29,15 @@
 #include "wine/heap.h"
 
 WINE_DECLARE_DEBUG_CHANNEL(pid);
+WINE_DECLARE_DEBUG_CHANNEL(source);
+WINE_DECLARE_DEBUG_CHANNEL(retaddr);
 WINE_DECLARE_DEBUG_CHANNEL(timestamp);
 
 static const char * (__cdecl *p__wine_dbg_strdup)( const char *str );
 static int (__cdecl *p__wine_dbg_output)( const char *str );
 static unsigned char (__cdecl *p__wine_dbg_get_channel_flags)( struct __wine_debug_channel *channel );
-static int (__cdecl *p__wine_dbg_header)( enum __wine_debug_class cls,
-                                          struct __wine_debug_channel *channel,
-                                          const char *function );
+static int (__cdecl *p__wine_dbg_header)( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
+                                          const struct __wine_debug_context *context );
 
 static const char * const debug_classes[] = { "fixme", "err", "warn", "trace" };
 
@@ -178,11 +179,10 @@ static int __cdecl fallback__wine_dbg_output( const char *str )
     return fwrite( str, 1, len, stderr );
 }
 
-static int __cdecl fallback__wine_dbg_header( enum __wine_debug_class cls,
-                                              struct __wine_debug_channel *channel,
-                                              const char *function )
+static int __cdecl fallback__wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
+                                              const struct __wine_debug_context *context )
 {
-    char buffer[200], *pos = buffer;
+    char buffer[200], *pos = buffer, *end = pos + sizeof(buffer);
 
     if (!(__wine_dbg_get_channel_flags( channel ) & (1 << cls))) return -1;
 
@@ -196,9 +196,27 @@ static int __cdecl fallback__wine_dbg_header( enum __wine_debug_class cls,
     }
     if (TRACE_ON(pid)) pos += sprintf( pos, "%04x:", (UINT)GetCurrentProcessId() );
     pos += sprintf( pos, "%04x:", (UINT)GetCurrentThreadId() );
-    if (function && cls < ARRAY_SIZE( debug_classes ))
-        snprintf( pos, sizeof(buffer) - (pos - buffer), "%s:%s:%s ",
-                  debug_classes[cls], channel->name, function );
+    if (cls < ARRAY_SIZE( debug_classes )) pos += snprintf( pos, end - pos, "%s:", debug_classes[cls] );
+    pos += snprintf( pos, end - pos, "%s:", channel->name );
+
+    if (context && context->compat)
+        pos += snprintf( pos, end - pos, "%s ", (const char *)context );
+    else if (context && context->version == WINE_DEBUG_CONTEXT_VERSION)
+    {
+        if (TRACE_ON(retaddr)) pos += snprintf( pos, end - pos, "%012Ix:", (SIZE_T)context->retaddr );
+        if (TRACE_ON(source))
+        {
+            const char *tmp, *file;
+
+            if ((tmp = strrchr( context->file, '/' ))) file = tmp + 1;
+            else if ((tmp = strrchr( context->file, '\\' ))) file = tmp + 1;
+            else file = context->file;
+
+            pos += snprintf( pos, end - pos, "%s:%d:", file, context->line );
+        }
+
+        pos += snprintf( pos, end - pos, "%s ", context->function );
+    }
 
     return fwrite( buffer, 1, strlen(buffer), stderr );
 }
@@ -243,10 +261,10 @@ unsigned char __cdecl __wine_dbg_get_channel_flags( struct __wine_debug_channel
 }
 
 int __cdecl __wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
-                               const char *function )
+                               const struct __wine_debug_context *context )
 {
     LOAD_FUNC( __wine_dbg_header );
-    return p__wine_dbg_header( cls, channel, function );
+    return p__wine_dbg_header( cls, channel, context );
 }
 
 #endif  /* __WINE_PE_BUILD */
diff --git a/include/wine/debug.h b/include/wine/debug.h
index 9c92fd3d6d6..63b21e4fd95 100644
--- a/include/wine/debug.h
+++ b/include/wine/debug.h
@@ -87,8 +87,25 @@ struct __wine_debug_channel
        const enum __wine_debug_class __dbcl = __WINE_DBCL##dbcl; \
        __WINE_DBG_LOG
 
+struct __wine_debug_context
+{
+    char compat; /* for backward compatibility */
+    int version; /* for forward compatibility */
+    const char *function;
+    const char *file;
+    int line;
+    const void *retaddr;
+};
+#define WINE_DEBUG_CONTEXT_VERSION 1
+
+#if defined(__GNUC__) || defined(__clang__)
+#define __WINE_DBG_RETADDR __builtin_extract_return_addr(__builtin_return_address(0))
+#else
+#define __WINE_DBG_RETADDR ((void *)0)
+#endif
+
 #define __WINE_DBG_LOG(...) \
-   wine_dbg_log( __dbcl, __dbch, __func__, __VA_ARGS__); } } while(0)
+   wine_dbg_log( __dbcl, __dbch, __FILE__, __LINE__, __func__, __WINE_DBG_RETADDR, __VA_ARGS__); } } while(0)
 
 #if defined(__MINGW32__) || (!defined(__WINE_USE_MSVCRT) && (defined(__GNUC__) || defined(__clang__)))
 #define __WINE_PRINTF_ATTR(fmt,args) __attribute__((format (printf,fmt,args)))
@@ -113,7 +130,7 @@ extern unsigned char __cdecl __wine_dbg_get_channel_flags( struct __wine_debug_c
 extern const char * __cdecl __wine_dbg_strdup( const char *str );
 extern int __cdecl __wine_dbg_output( const char *str );
 extern int __cdecl __wine_dbg_header( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
-                                      const char *function );
+                                      const struct __wine_debug_context *context );
 
 /*
  * Exported definitions and macros
@@ -171,36 +188,45 @@ static inline int __wine_dbg_cdecl wine_dbg_printf( const char *format, ... )
     return ret;
 }
 
-static int __wine_dbg_cdecl wine_dbg_vlog( enum __wine_debug_class cls,
-                                           struct __wine_debug_channel *channel, const char *func,
-                                           const char *format, va_list args ) __WINE_PRINTF_ATTR(4,0);
-static inline int __wine_dbg_cdecl wine_dbg_vlog( enum __wine_debug_class cls,
-                                                  struct __wine_debug_channel *channel,
-                                                  const char *function, const char *format, va_list args )
+static int __wine_dbg_cdecl wine_dbg_vlog( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
+                                           const char *file, int line, const char *function, const void *retaddr,
+                                           const char *format, va_list args ) __WINE_PRINTF_ATTR(7,0);
+static inline int __wine_dbg_cdecl wine_dbg_vlog( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
+                                                  const char *file, int line, const char *function, const void *retaddr,
+                                                  const char *format, va_list args )
 {
+    struct __wine_debug_context info =
+    {
+        .version = WINE_DEBUG_CONTEXT_VERSION,
+        .function = function,
+        .file = file,
+        .line = line,
+        .retaddr = retaddr,
+    };
+    struct __wine_debug_context *context = &info;
     int ret;
 
     if (*format == '\1')  /* special magic to avoid standard prefix */
     {
         format++;
-        function = NULL;
+        context = NULL;
     }
-    if ((ret = __wine_dbg_header( cls, channel, function )) != -1) ret += wine_dbg_vprintf( format, args );
+    if ((ret = __wine_dbg_header( cls, channel, context )) != -1) ret += wine_dbg_vprintf( format, args );
     return ret;
 }
 
-static int __wine_dbg_cdecl wine_dbg_log( enum __wine_debug_class cls,
-                                          struct __wine_debug_channel *channel, const char *func,
-                                          const char *format, ... ) __WINE_PRINTF_ATTR(4,5);
-static inline int __wine_dbg_cdecl wine_dbg_log( enum __wine_debug_class cls,
-                                                 struct __wine_debug_channel *channel,
-                                                 const char *function, const char *format, ... )
+static int __wine_dbg_cdecl wine_dbg_log( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
+                                          const char *file, int line, const char *function, const void *retaddr,
+                                          const char *format, ... ) __WINE_PRINTF_ATTR(7,8);
+static inline int __wine_dbg_cdecl wine_dbg_log( enum __wine_debug_class cls, struct __wine_debug_channel *channel,
+                                                 const char *file, int line, const char *function, const void *retaddr,
+                                                 const char *format, ... )
 {
     va_list args;
     int ret;
 
     va_start( args, format );
-    ret = wine_dbg_vlog( cls, channel, function, format, args );
+    ret = wine_dbg_vlog( cls, channel, file, line, function, retaddr, format, args );
     va_end( args );
     return ret;
 }
-- 
GitLab

https://gitlab.winehq.org/wine/wine/-/merge_requests/2274

[Rémi Bernon]

Rebased, squashed the changes together so that the CI doesn't choke on it, and added some opt-in debug channels so that it actually does something.

-- 
https://gitlab.winehq.org/wine/wine/-/merge_requests/2274#note_46696

[PATCH v4 0/1] MR2274: ntdll: Add source file and line to debug traces. - closed

[Rémi Bernon]

This merge request was closed by Rémi Bernon.
-- 
https://gitlab.winehq.org/wine/wine/-/merge_requests/2274