[Bug 41450] New: Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

Bug ID: 41450
           Summary: Wine Debug Channel +timestamp, timestamp missing from
                    some entries
           Product: Wine
           Version: 1.6.2
          Hardware: x86-64
                OS: Linux
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: -unknown
          Assignee: [e-mail]
          Reporter: [e-mail]
      Distribution: ---

Created attachment 55817
  --> https://bugs.winehq.org/attachment.cgi?id=55817
Log with missing timestamps

example of log with +timestamp,+tid (note timestamp missing for 7 lines
starting with 'Call PE DLL'):

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

[e-mail] changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]

--- Comment #1 from [e-mail] ---
(In reply to brewmanz from comment #0)
> Created attachment 55817 [details]
> Log with missing timestamps
>
> example of log with +timestamp,+tid (note timestamp missing for 7 lines
> starting with 'Call PE DLL'):

Update to a much newer version of Wine such as 1.8.4 (stable) or Wine 1.9.20
(development) as version 1.6.2 is quite old and unsupported.

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

brewmanz  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
  Attachment #55817|0                           |1
        is obsolete|                            |

--- Comment #2 from brewmanz  ---
Created attachment 55825
  --> https://bugs.winehq.org/attachment.cgi?id=55825
examples from 1.9.20

Same problem (missing timestamps) with 1.9.20

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

brewmanz  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
            Version|1.6.2                       |1.9.20

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

brewmanz  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
           Severity|normal                      |enhancement
            Version|1.9.20                      |1.9.22

--- Comment #3 from brewmanz  ---
here is some code that fixes the problem:

diff --git a/dlls/kernel32/process.c b/dlls/kernel32/process.c
index 5b584ac..c1f1301 100644
--- a/dlls/kernel32/process.c
+++ b/dlls/kernel32/process.c
@@ -65,6 +65,13 @@
 WINE_DEFAULT_DEBUG_CHANNEL(process);
 WINE_DECLARE_DEBUG_CHANNEL(file);
 WINE_DECLARE_DEBUG_CHANNEL(relay);
+WINE_DECLARE_DEBUG_CHANNEL(timestamp);
+
+static void print_timestamp(void)
+{
+    ULONG ticks = NtGetTickCount();
+    DPRINTF( "%3u.%03u:", ticks / 1000, ticks % 1000 );
+}

#ifdef __APPLE__
 extern char **__wine_get_main_environment(void);
@@ -1100,9 +1107,11 @@
     }

if (TRACE_ON(relay))
+    {
+        if (TRACE_ON(timestamp)) print_timestamp();
         DPRINTF( "%04x:Starting process %s (entryproc=%p)\n",
GetCurrentThreadId(),
                  debugstr_w(peb->ProcessParameters->ImagePathName.Buffer),
entry );
-
+    }
     SetLastError( 0 );  /* clear error code */
     if (peb->BeingDebugged) DbgBreakPoint();
     return call_process_entry( peb, entry );
diff --git a/dlls/ntdll/loader.c b/dlls/ntdll/loader.c
index f1ef7ab..5b2fddd 100644
--- a/dlls/ntdll/loader.c
+++ b/dlls/ntdll/loader.c
@@ -50,6 +50,13 @@
 WINE_DECLARE_DEBUG_CHANNEL(loaddll);
 WINE_DECLARE_DEBUG_CHANNEL(imports);
 WINE_DECLARE_DEBUG_CHANNEL(pid);
+WINE_DECLARE_DEBUG_CHANNEL(timestamp);
+
+static void print_timestamp(void)
+{
+    ULONG ticks = NtGetTickCount();
+    DPRINTF( "%3u.%03u:", ticks / 1000, ticks % 1000 );
+}

#ifdef _WIN64
 #define DEFAULT_SECURITY_COOKIE_64  (((ULONGLONG)0x00002b99 << 32) |
0x2ddfa232)
@@ -1046,6 +1053,7 @@
     {
         if (TRACE_ON(relay))
         {
+            if (TRACE_ON(timestamp)) print_timestamp();
             if (TRACE_ON(pid))
                 DPRINTF( "%04x:", GetCurrentProcessId() );
             DPRINTF("%04x:Call TLS callback
(proc=%p,module=%p,reason=%s,reserved=0)\n",
@@ -1059,6 +1067,7 @@
         {
             if (TRACE_ON(relay))
             {
+                if (TRACE_ON(timestamp)) print_timestamp();
                 if (TRACE_ON(pid))
                     DPRINTF( "%04x:", GetCurrentProcessId() );
                 DPRINTF("%04x:exception in TLS callback
(proc=%p,module=%p,reason=%s,reserved=0)\n",
@@ -1069,6 +1078,7 @@
         __ENDTRY
         if (TRACE_ON(relay))
         {
+            if (TRACE_ON(timestamp)) print_timestamp();
             if (TRACE_ON(pid))
                 DPRINTF( "%04x:", GetCurrentProcessId() );
             DPRINTF("%04x:Ret  TLS callback
(proc=%p,module=%p,reason=%s,reserved=0)\n",
@@ -1100,6 +1110,7 @@
         size_t len = min( wm->ldr.BaseDllName.Length,
sizeof(mod_name)-sizeof(WCHAR) );
         memcpy( mod_name, wm->ldr.BaseDllName.Buffer, len );
         mod_name[len / sizeof(WCHAR)] = 0;
+        if (TRACE_ON(timestamp)) print_timestamp();
         if (TRACE_ON(pid))
             DPRINTF( "%04x:", GetCurrentProcessId() );
         DPRINTF("%04x:Call PE DLL (proc=%p,module=%p %s,reason=%s,res=%p)\n",
@@ -1117,6 +1128,7 @@
     }
     __EXCEPT_ALL
     {
+        if (TRACE_ON(timestamp)) print_timestamp();
         if (TRACE_ON(relay))
         {
             if (TRACE_ON(pid))
@@ -1133,6 +1145,7 @@
        deleted.  */
     if (TRACE_ON(relay))
     {
+        if (TRACE_ON(timestamp)) print_timestamp();
         if (TRACE_ON(pid))
             DPRINTF( "%04x:", GetCurrentProcessId() );
         DPRINTF("%04x:Ret  PE DLL (proc=%p,module=%p %s,reason=%s,res=%p)
retval=%x\n",
diff --git a/dlls/ntdll/thread.c b/dlls/ntdll/thread.c
index 6127c8f..1b12c9c 100644
--- a/dlls/ntdll/thread.c
+++ b/dlls/ntdll/thread.c
@@ -47,6 +47,13 @@

WINE_DEFAULT_DEBUG_CHANNEL(thread);
 WINE_DECLARE_DEBUG_CHANNEL(relay);
+WINE_DECLARE_DEBUG_CHANNEL(timestamp);
+
+static void print_timestamp(void)
+{
+    ULONG ticks = NtGetTickCount();
+    DPRINTF( "%3u.%03u:", ticks / 1000, ticks % 1000 );
+}

struct _KUSER_SHARED_DATA *user_shared_data = NULL;

@@ -448,8 +455,10 @@
     MODULE_DllThreadAttach( NULL );

if (TRACE_ON(relay))
+    {
+        if (TRACE_ON(timestamp)) print_timestamp();
         DPRINTF( "%04x:Starting thread proc %p (arg=%p)\n",
GetCurrentThreadId(), func, arg );
-
+    }
     call_thread_entry_point( (LPTHREAD_START_ROUTINE)func, arg );
 }

diff --git a/programs/winedevice/device.c b/programs/winedevice/device.c
index 44aa1a0..8fd5883 100644
--- a/programs/winedevice/device.c
+++ b/programs/winedevice/device.c
@@ -40,6 +40,13 @@

WINE_DEFAULT_DEBUG_CHANNEL(winedevice);
 WINE_DECLARE_DEBUG_CHANNEL(relay);
+WINE_DECLARE_DEBUG_CHANNEL(timestamp);
+
+static void print_timestamp(void)
+{
+    ULONG ticks = NtGetTickCount();
+    DPRINTF( "%3u.%03u:", ticks / 1000, ticks % 1000 );
+}

extern NTSTATUS CDECL wine_ntoskrnl_main_loop( HANDLE stop_event );

@@ -264,9 +271,11 @@
     driver_object->DriverInit = (PDRIVER_INITIALIZE)((char *)module +
nt->OptionalHeader.AddressOfEntryPoint);

if (WINE_TRACE_ON(relay))
+    {
+        if (TRACE_ON(timestamp)) print_timestamp();
         WINE_DPRINTF( "%04x:Call driver init %p (obj=%p,str=%s)\n",
GetCurrentThreadId(),
                       driver_object->DriverInit, driver_object,
wine_dbgstr_w(keyname->Buffer) );
-
+    }
     status = driver_object->DriverInit( driver_object, keyname );

if (WINE_TRACE_ON(relay))

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

[e-mail] changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]

--- Comment #4 from [e-mail] ---
Can you make those changes in a form of git patch and sent it for a review
wine-devel? Patches arent picked from bug tracker.

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

--- Comment #5 from brewmanz  ---

I thought that that was what I'd done; they came from my git repository
(git-eye - show changes as diff. When you say a git patch, is that a pull
request?

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

--- Comment #6 from [e-mail] ---
(In reply to brewmanz from comment #5)
> I thought that that was what I'd done; they came from my git repository
> (git-eye - show changes as diff. When you say a git patch, is that a pull
> request?

I just put these links here. They explain thigs better than I could. I don't
know if you removed author information from that patch, it needs to be included
when submiting patches.

https://wiki.winehq.org/Git_Wine_Tutorial

https://wiki.winehq.org/Submitting_Patches

When you have done your patch submission correctly it shows here
https://source.winehq.org/patches/

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

--- Comment #7 from [e-mail] ---
Your patch needs author information and email.

Basically you just do

git reset --hard origin
git pull
make your code changes
git commit -m  "patch name"
git format-patch -1

and you have a autogenerated patch that you need to send over. With sign off
message.

I quess you have generated the patch just correctly I just didnt notice the
line starting with diff.

You could add patch keyword into this bug report.

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

--- Comment #8 from brewmanz  ---
I've got bogged down with the testing requirements. It seems that the 'best and
easiest way' to test (WineTest) does not actually give a report of what's
failing if you get 90 failures. 
I mentioned this in the forum
(https://forum.winehq.org/viewtopic.php?f=2&t=27919) but got nowhere; the
answer given did not address the issue I was raising.

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

https://bugs.winehq.org/show_bug.cgi?id=41450

--- Comment #9 from [e-mail] ---
(In reply to brewmanz from comment #8)
> I've got bogged down with the testing requirements. It seems that the 'best
> and easiest way' to test (WineTest) does not actually give a report of
> what's failing if you get 90 failures. 
> I mentioned this in the forum
> (https://forum.winehq.org/viewtopic.php?f=2&t=27919) but got nowhere; the
> answer given did not address the issue I was raising.

You dont need to test a patch with testbots that only adds traces to the code.
Just resend the patch with real full name and look that it merges cleanly with
no offset changes.

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=41450

Zebediah Figura  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]

--- Comment #10 from Zebediah Figura  ---
Still present, but is this really worth fixing?

[Bug 41450] Wine Debug Channel +timestamp, timestamp missing from some entries

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=41450

Zebediah Figura  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|UNCONFIRMED                 |RESOLVED
      Fixed by SHA1|                            |7ca2a1ade5acbe36854049cc713
                   |                            |abf5821d8bffc
         Resolution|---                         |FIXED

--- Comment #11 from Zebediah Figura  ---
Actualy, I didn't completely read this bug. All of the mentioned instances are
fixed as of 7ca2a1ade5. The only remaining messages without a timestamp are
very early on startup, before the timing information is available
(effectively). I think this can be closed as FIXED.

[Bug 41450] timestamp is missing from some debug messages

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=41450

Zebediah Figura  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|Wine Debug Channel          |timestamp is missing from
                   |+timestamp, timestamp       |some debug messages
                   |missing from some entries   |

[Bug 41450] timestamp is missing from some debug messages

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=41450

Alexandre Julliard  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #12 from Alexandre Julliard  ---
Closing bugs fixed in 6.0-rc4.