ntdll: Support magic \1 prefix in debug format for relay traces.

Signed-off-by: Alexandre Julliard <julliard@winehq.org>
This commit is contained in:
Alexandre Julliard 2017-11-25 11:45:20 +01:00
parent ec14c220d2
commit 822e142403
4 changed files with 45 additions and 100 deletions

View file

@ -173,7 +173,9 @@ static int NTDLL_dbg_vlog( enum __wine_debug_class cls, struct __wine_debug_chan
if (TRACE_ON(pid)) if (TRACE_ON(pid))
ret += wine_dbg_printf( "%04x:", GetCurrentProcessId() ); ret += wine_dbg_printf( "%04x:", GetCurrentProcessId() );
ret += wine_dbg_printf( "%04x:", GetCurrentThreadId() ); ret += wine_dbg_printf( "%04x:", GetCurrentThreadId() );
if (cls < sizeof(classes)/sizeof(classes[0])) if (*format == '\1') /* special magic to avoid standard prefix */
format++;
else if (cls < sizeof(classes)/sizeof(classes[0]))
ret += wine_dbg_printf( "%s:%s:%s ", classes[cls], channel->name, function ); ret += wine_dbg_printf( "%s:%s:%s ", classes[cls], channel->name, function );
} }
if (format) if (format)

View file

@ -49,7 +49,6 @@ WINE_DECLARE_DEBUG_CHANNEL(relay);
WINE_DECLARE_DEBUG_CHANNEL(snoop); WINE_DECLARE_DEBUG_CHANNEL(snoop);
WINE_DECLARE_DEBUG_CHANNEL(loaddll); WINE_DECLARE_DEBUG_CHANNEL(loaddll);
WINE_DECLARE_DEBUG_CHANNEL(imports); WINE_DECLARE_DEBUG_CHANNEL(imports);
WINE_DECLARE_DEBUG_CHANNEL(pid);
#ifdef _WIN64 #ifdef _WIN64
#define DEFAULT_SECURITY_COOKIE_64 (((ULONGLONG)0x00002b99 << 32) | 0x2ddfa232) #define DEFAULT_SECURITY_COOKIE_64 (((ULONGLONG)0x00002b99 << 32) | 0x2ddfa232)
@ -1087,36 +1086,21 @@ static void call_tls_callbacks( HMODULE module, UINT reason )
for (callback = (const PIMAGE_TLS_CALLBACK *)dir->AddressOfCallBacks; *callback; callback++) for (callback = (const PIMAGE_TLS_CALLBACK *)dir->AddressOfCallBacks; *callback; callback++)
{ {
if (TRACE_ON(relay)) TRACE_(relay)("\1Call TLS callback (proc=%p,module=%p,reason=%s,reserved=0)\n",
{ *callback, module, reason_names[reason] );
if (TRACE_ON(pid))
DPRINTF( "%04x:", GetCurrentProcessId() );
DPRINTF("%04x:Call TLS callback (proc=%p,module=%p,reason=%s,reserved=0)\n",
GetCurrentThreadId(), *callback, module, reason_names[reason] );
}
__TRY __TRY
{ {
call_dll_entry_point( (DLLENTRYPROC)*callback, module, reason, NULL ); call_dll_entry_point( (DLLENTRYPROC)*callback, module, reason, NULL );
} }
__EXCEPT_ALL __EXCEPT_ALL
{ {
if (TRACE_ON(relay)) TRACE_(relay)("\1exception in TLS callback (proc=%p,module=%p,reason=%s,reserved=0)\n",
{ callback, module, reason_names[reason] );
if (TRACE_ON(pid))
DPRINTF( "%04x:", GetCurrentProcessId() );
DPRINTF("%04x:exception in TLS callback (proc=%p,module=%p,reason=%s,reserved=0)\n",
GetCurrentThreadId(), callback, module, reason_names[reason] );
}
return; return;
} }
__ENDTRY __ENDTRY
if (TRACE_ON(relay)) TRACE_(relay)("\1Ret TLS callback (proc=%p,module=%p,reason=%s,reserved=0)\n",
{ *callback, module, reason_names[reason] );
if (TRACE_ON(pid))
DPRINTF( "%04x:", GetCurrentProcessId() );
DPRINTF("%04x:Ret TLS callback (proc=%p,module=%p,reason=%s,reserved=0)\n",
GetCurrentThreadId(), *callback, module, reason_names[reason] );
}
} }
} }
@ -1143,11 +1127,8 @@ static NTSTATUS MODULE_InitDLL( WINE_MODREF *wm, UINT reason, LPVOID lpReserved
size_t len = min( wm->ldr.BaseDllName.Length, sizeof(mod_name)-sizeof(WCHAR) ); size_t len = min( wm->ldr.BaseDllName.Length, sizeof(mod_name)-sizeof(WCHAR) );
memcpy( mod_name, wm->ldr.BaseDllName.Buffer, len ); memcpy( mod_name, wm->ldr.BaseDllName.Buffer, len );
mod_name[len / sizeof(WCHAR)] = 0; mod_name[len / sizeof(WCHAR)] = 0;
if (TRACE_ON(pid)) TRACE_(relay)("\1Call PE DLL (proc=%p,module=%p %s,reason=%s,res=%p)\n",
DPRINTF( "%04x:", GetCurrentProcessId() ); entry, module, debugstr_w(mod_name), reason_names[reason], lpReserved );
DPRINTF("%04x:Call PE DLL (proc=%p,module=%p %s,reason=%s,res=%p)\n",
GetCurrentThreadId(), entry, module, debugstr_w(mod_name),
reason_names[reason], lpReserved );
} }
else TRACE("(%p %s,%s,%p) - CALL\n", module, debugstr_w(wm->ldr.BaseDllName.Buffer), else TRACE("(%p %s,%s,%p) - CALL\n", module, debugstr_w(wm->ldr.BaseDllName.Buffer),
reason_names[reason], lpReserved ); reason_names[reason], lpReserved );
@ -1160,13 +1141,8 @@ static NTSTATUS MODULE_InitDLL( WINE_MODREF *wm, UINT reason, LPVOID lpReserved
} }
__EXCEPT_ALL __EXCEPT_ALL
{ {
if (TRACE_ON(relay)) TRACE_(relay)("\1exception in PE entry point (proc=%p,module=%p,reason=%s,res=%p)\n",
{ entry, module, reason_names[reason], lpReserved );
if (TRACE_ON(pid))
DPRINTF( "%04x:", GetCurrentProcessId() );
DPRINTF("%04x:exception in PE entry point (proc=%p,module=%p,reason=%s,res=%p)\n",
GetCurrentThreadId(), entry, module, reason_names[reason], lpReserved );
}
status = GetExceptionCode(); status = GetExceptionCode();
} }
__ENDTRY __ENDTRY
@ -1175,14 +1151,10 @@ static NTSTATUS MODULE_InitDLL( WINE_MODREF *wm, UINT reason, LPVOID lpReserved
to the dll. We cannot assume that this module has not been to the dll. We cannot assume that this module has not been
deleted. */ deleted. */
if (TRACE_ON(relay)) if (TRACE_ON(relay))
{ TRACE_(relay)("\1Ret PE DLL (proc=%p,module=%p %s,reason=%s,res=%p) retval=%x\n",
if (TRACE_ON(pid)) entry, module, debugstr_w(mod_name), reason_names[reason], lpReserved, retv );
DPRINTF( "%04x:", GetCurrentProcessId() ); else
DPRINTF("%04x:Ret PE DLL (proc=%p,module=%p %s,reason=%s,res=%p) retval=%x\n", TRACE("(%p,%s,%p) - RETURN %d\n", module, reason_names[reason], lpReserved, retv );
GetCurrentThreadId(), entry, module, debugstr_w(mod_name),
reason_names[reason], lpReserved, retv );
}
else TRACE("(%p,%s,%p) - RETURN %d\n", module, reason_names[reason], lpReserved, retv );
return status; return status;
} }

View file

@ -40,9 +40,6 @@ WINE_DEFAULT_DEBUG_CHANNEL(relay);
#if defined(__i386__) || defined(__x86_64__) || defined(__arm__) || defined(__aarch64__) #if defined(__i386__) || defined(__x86_64__) || defined(__arm__) || defined(__aarch64__)
WINE_DECLARE_DEBUG_CHANNEL(timestamp);
WINE_DECLARE_DEBUG_CHANNEL(pid);
struct relay_descr /* descriptor for a module */ struct relay_descr /* descriptor for a module */
{ {
void *magic; /* signature */ void *magic; /* signature */
@ -308,23 +305,17 @@ static inline void RELAY_PrintArgs( const INT_PTR *args, int nb_args, unsigned i
if ((typemask & 3) && !IS_INTARG(*args)) if ((typemask & 3) && !IS_INTARG(*args))
{ {
if (typemask & 2) if (typemask & 2)
DPRINTF( "%08lx %s", *args, debugstr_w((LPCWSTR)*args) ); TRACE( "%08lx %s", *args, debugstr_w((LPCWSTR)*args) );
else else
DPRINTF( "%08lx %s", *args, debugstr_a((LPCSTR)*args) ); TRACE( "%08lx %s", *args, debugstr_a((LPCSTR)*args) );
} }
else DPRINTF( "%08lx", *args ); else TRACE( "%08lx", *args );
if (nb_args) DPRINTF( "," ); if (nb_args) TRACE( "," );
args++; args++;
typemask >>= 2; typemask >>= 2;
} }
} }
static void print_timestamp(void)
{
ULONG ticks = NtGetTickCount();
DPRINTF( "%3u.%03u:", ticks / 1000, ticks % 1000 );
}
/*********************************************************************** /***********************************************************************
* relay_trace_entry * relay_trace_entry
* *
@ -340,17 +331,12 @@ DECLSPEC_HIDDEN void * WINAPI relay_trace_entry( struct relay_descr *descr,
if (TRACE_ON(relay)) if (TRACE_ON(relay))
{ {
if (TRACE_ON(timestamp)) print_timestamp();
if (TRACE_ON(pid))
DPRINTF( "%04x:", GetCurrentProcessId() );
if (entry_point->name) if (entry_point->name)
DPRINTF( "%04x:Call %s.%s(", GetCurrentThreadId(), data->dllname, entry_point->name ); TRACE( "\1Call %s.%s(", data->dllname, entry_point->name );
else else
DPRINTF( "%04x:Call %s.%u(", GetCurrentThreadId(), data->dllname, data->base + ordinal ); TRACE( "\1Call %s.%u(", data->dllname, data->base + ordinal );
RELAY_PrintArgs( stack + 1, nb_args, descr->arg_types[ordinal] ); RELAY_PrintArgs( stack + 1, nb_args, descr->arg_types[ordinal] );
DPRINTF( ") ret=%08lx\n", stack[0] ); TRACE( ") ret=%08lx\n", stack[0] );
} }
return entry_point->orig_func; return entry_point->orig_func;
} }
@ -366,23 +352,16 @@ DECLSPEC_HIDDEN void WINAPI relay_trace_exit( struct relay_descr *descr, unsigne
struct relay_private_data *data = descr->private; struct relay_private_data *data = descr->private;
struct relay_entry_point *entry_point = data->entry_points + ordinal; struct relay_entry_point *entry_point = data->entry_points + ordinal;
if (!TRACE_ON(relay)) return;
if (TRACE_ON(timestamp)) print_timestamp();
if (TRACE_ON(pid))
DPRINTF( "%04x:", GetCurrentProcessId() );
if (entry_point->name) if (entry_point->name)
DPRINTF( "%04x:Ret %s.%s()", GetCurrentThreadId(), data->dllname, entry_point->name ); TRACE( "\1Ret %s.%s()", data->dllname, entry_point->name );
else else
DPRINTF( "%04x:Ret %s.%u()", GetCurrentThreadId(), data->dllname, data->base + ordinal ); TRACE( "\1Ret %s.%u()", data->dllname, data->base + ordinal );
if (flags & 1) /* 64-bit return value */ if (flags & 1) /* 64-bit return value */
DPRINTF( " retval=%08x%08x ret=%08lx\n", TRACE( " retval=%08x%08x ret=%08lx\n",
(UINT)(retval >> 32), (UINT)retval, stack[0] ); (UINT)(retval >> 32), (UINT)retval, stack[0] );
else else
DPRINTF( " retval=%08lx ret=%08lx\n", (UINT_PTR)retval, stack[0] ); TRACE( " retval=%08lx ret=%08lx\n", (UINT_PTR)retval, stack[0] );
} }
#ifdef __i386__ #ifdef __i386__
@ -952,7 +931,7 @@ static void SNOOP_PrintArg(DWORD x)
{ {
int i,nostring; int i,nostring;
DPRINTF("%08x",x); TRACE_(snoop)("%08x",x);
if (IS_INTARG(x) || TRACE_ON(seh)) return; /* trivial reject to avoid faults */ if (IS_INTARG(x) || TRACE_ON(seh)) return; /* trivial reject to avoid faults */
__TRY __TRY
{ {
@ -965,7 +944,7 @@ static void SNOOP_PrintArg(DWORD x)
i++; i++;
} }
if (!nostring && i > 5) if (!nostring && i > 5)
DPRINTF(" %s",debugstr_an((LPSTR)x,i)); TRACE_(snoop)(" %s",debugstr_an((LPSTR)x,i));
else /* try unicode */ else /* try unicode */
{ {
LPWSTR s=(LPWSTR)x; LPWSTR s=(LPWSTR)x;
@ -976,7 +955,7 @@ static void SNOOP_PrintArg(DWORD x)
if (s[i]>0x100) {nostring=1;break;} if (s[i]>0x100) {nostring=1;break;}
i++; i++;
} }
if (!nostring && i > 5) DPRINTF(" %s",debugstr_wn((LPWSTR)x,i)); if (!nostring && i > 5) TRACE_(snoop)(" %s",debugstr_wn((LPWSTR)x,i));
} }
} }
__EXCEPT_PAGE_FAULT __EXCEPT_PAGE_FAULT
@ -1049,26 +1028,24 @@ void WINAPI DECLSPEC_HIDDEN __regs_SNOOP_Entry( void **stack )
if (!TRACE_ON(snoop)) return; if (!TRACE_ON(snoop)) return;
if (TRACE_ON(timestamp)) if (fun->name) TRACE_(snoop)("\1CALL %s.%s(", dll->name, fun->name);
print_timestamp(); else TRACE_(snoop)("\1CALL %s.%d(", dll->name, dll->ordbase+ret->ordinal);
if (fun->name) DPRINTF("%04x:CALL %s.%s(",GetCurrentThreadId(),dll->name,fun->name);
else DPRINTF("%04x:CALL %s.%d(",GetCurrentThreadId(),dll->name,dll->ordbase+ret->ordinal);
if (fun->nrofargs>0) { if (fun->nrofargs>0) {
max = fun->nrofargs; if (max>16) max=16; max = fun->nrofargs; if (max>16) max=16;
for (i=0;i<max;i++) for (i=0;i<max;i++)
{ {
SNOOP_PrintArg( (DWORD)stack[i + 2] ); SNOOP_PrintArg( (DWORD)stack[i + 2] );
if (i<fun->nrofargs-1) DPRINTF(","); if (i<fun->nrofargs-1) TRACE_(snoop)(",");
} }
if (max!=fun->nrofargs) if (max!=fun->nrofargs)
DPRINTF(" ..."); TRACE_(snoop)(" ...");
} else if (fun->nrofargs<0) { } else if (fun->nrofargs<0) {
DPRINTF("<unknown, check return>"); TRACE_(snoop)("<unknown, check return>");
ret->args = RtlAllocateHeap(GetProcessHeap(), ret->args = RtlAllocateHeap(GetProcessHeap(),
0,16*sizeof(DWORD)); 0,16*sizeof(DWORD));
memcpy(ret->args, stack + 2, sizeof(DWORD)*16); memcpy(ret->args, stack + 2, sizeof(DWORD)*16);
} }
DPRINTF(") ret=%08x\n",(DWORD)ret->origreturn); TRACE_(snoop)(") ret=%08x\n",(DWORD)ret->origreturn);
} }
void WINAPI DECLSPEC_HIDDEN __regs_SNOOP_Return( void **stack ) void WINAPI DECLSPEC_HIDDEN __regs_SNOOP_Return( void **stack )
@ -1091,16 +1068,13 @@ void WINAPI DECLSPEC_HIDDEN __regs_SNOOP_Return( void **stack )
return; return;
} }
if (TRACE_ON(timestamp))
print_timestamp();
if (ret->args) { if (ret->args) {
int i,max; int i,max;
if (fun->name) if (fun->name)
DPRINTF("%04x:RET %s.%s(", GetCurrentThreadId(), ret->dll->name, fun->name); TRACE_(snoop)("\1RET %s.%s(", ret->dll->name, fun->name);
else else
DPRINTF("%04x:RET %s.%d(", GetCurrentThreadId(), TRACE_(snoop)("\1RET %s.%d(", ret->dll->name, ret->dll->ordbase+ret->ordinal);
ret->dll->name,ret->dll->ordbase+ret->ordinal);
max = fun->nrofargs; max = fun->nrofargs;
if (max>16) max=16; if (max>16) max=16;
@ -1108,21 +1082,19 @@ void WINAPI DECLSPEC_HIDDEN __regs_SNOOP_Return( void **stack )
for (i=0;i<max;i++) for (i=0;i<max;i++)
{ {
SNOOP_PrintArg(ret->args[i]); SNOOP_PrintArg(ret->args[i]);
if (i<max-1) DPRINTF(","); if (i<max-1) TRACE_(snoop)(",");
} }
DPRINTF(") retval=%08x ret=%08x\n", retval, (DWORD)ret->origreturn ); TRACE_(snoop)(") retval=%08x ret=%08x\n", retval, (DWORD)ret->origreturn );
RtlFreeHeap(GetProcessHeap(),0,ret->args); RtlFreeHeap(GetProcessHeap(),0,ret->args);
ret->args = NULL; ret->args = NULL;
} }
else else
{ {
if (fun->name) if (fun->name)
DPRINTF("%04x:RET %s.%s() retval=%08x ret=%08x\n", TRACE_(snoop)("\1RET %s.%s() retval=%08x ret=%08x\n",
GetCurrentThreadId(), ret->dll->name, fun->name, retval, (DWORD)ret->origreturn);
ret->dll->name, fun->name, retval, (DWORD)ret->origreturn);
else else
DPRINTF("%04x:RET %s.%d() retval=%08x ret=%08x\n", TRACE_(snoop)("\1RET %s.%d() retval=%08x ret=%08x\n",
GetCurrentThreadId(),
ret->dll->name,ret->dll->ordbase+ret->ordinal, ret->dll->name,ret->dll->ordbase+ret->ordinal,
retval, (DWORD)ret->origreturn); retval, (DWORD)ret->origreturn);
} }

View file

@ -479,8 +479,7 @@ static void thread_startup( void *param )
attach_dlls( (void *)1 ); attach_dlls( (void *)1 );
if (TRACE_ON(relay)) TRACE_(relay)( "\1Starting thread proc %p (arg=%p)\n", func, arg );
DPRINTF( "%04x:Starting thread proc %p (arg=%p)\n", GetCurrentThreadId(), func, arg );
call_thread_entry_point( (LPTHREAD_START_ROUTINE)func, arg ); call_thread_entry_point( (LPTHREAD_START_ROUTINE)func, arg );
} }