howto trace Winsock intercept calls

Hi,

I’m trying to trace (in MS Visual Studio 2013), the Winsock intercept calls in Wpthook.cc but can’t seem to see the output.

This is a private instance of WPT and the test itself seems to run fine and I can see the results(with IE, firefox, chrome).

Can someone please post the steps to see the WptTrace output when running in MS Visual Studio 2013?

Thanks.

By far the easiest way is to use debugview: DebugView - Windows Sysinternals | Microsoft Docs

Run it as an administrator and turn on global capture and then all of the logging will be timestamped and displayed (you’ll need a debug WPT build).

If you actually want to step through it in a debugger then you’ll need to uncomment the message box in wpthook.cc and when the “Attach debugger” message gets displayed you’ll need to attach to the process from Visual Studio to actually debug it.

Thank you. I must be missing something trivial.

I cant seem to hit the WptHook::Init() function at all (some sample fprintf in this routine doesnt show up but does from elsewhere).
Uncommenting the messagebox in wpthook.cc, rebuild, start in MS Visual studio doesnt bring up the “attach debugger” message either.

The WPT test is setup to run with Chrome in “Native Connection” mode since I dont have dummynet installed on this Win2k12 server yet.
I’m running MS Visual Studio as Administrator and starting the prog from “Local Windows Debugger”.

On the DebugView, I do see messages coming via OutputDebugString ( Ex. Flushing DNS cache …) but nothing else. I’ve enabled

00000035 27.23285675 [8108] Reading user data…
00000036 27.23323059 [8108] Pipe Logging: 10|300|
00000037 27.24257660 [8108] Pipe Logging: Success!
00000038 27.24312210 [8108] Reading data… Succeeded Reading 75 bytes of data (75 actual).
00000039 27.27181435 [8108] Returning user data[Success|e1dd5524d0c14288b30af76281a1f45d|2.7.45154151|COMA|comet-arcade.com]
00000040 27.44547462 [8108] Pipe Logging: 10|185|
00000041 27.44564056 [8108] Pipe Logging: Success!
00000042 27.47657394 [8108] Pipe Logging: 10|202|Hook Active: closesocket
00000043 27.47994804 [8108] Pipe Logging: Success!
00000044 27.48001862 [8108] Pipe Logging: 10|203|Data Active
00000045 27.48008537 [8108] Pipe Logging: 10|204|Valid Document
00000046 27.48010635 [8108] Pipe Logging: 10|202|Hook Active: connect
00000047 27.48017883 [8108] Pipe Logging: 10|203|Data Active
00000048 27.48022652 [8108] Pipe Logging: 10|207|Trying to Load boot- Mime: application/json Host: 127.0.0.1:8888 Path: /task
00000049 27.58190346 [8108] Pipe Logging: Success!
00000050 27.58213806 [8108] Pipe Logging: Success!
00000051 27.58236313 [8108] Pipe Logging: Success!
00000052 27.68292809 [8108] Pipe Logging: Success!
00000053 27.68321800 [8108] Pipe Logging: Success!
00000054 28.47544479 [10912] Waiting up to 120 seconds for the test to complete
00000055 28.51938248 [8108] Pipe Logging: 10|207|Trying to Load boot- Mime: application/json Host: 127.0.0.1:8888 Path: /task
00000056 28.51953316 [8108] Pipe Logging: Success!
00000057 28.51965904 [8108] Pipe Logging: 10|204|Valid Document
00000058 28.52903748 [8108] Pipe Logging: Success!
00000059 33.79203033 [10912] Checking for software updates…
00000060 33.79264069 [10912] Checking for work…
00000061 33.79665756 [10912] Waiting for work…

Did some more investigation. I see the following in the RegCreateKey() functions in WptDriverCore::Init(). I see (from regedit) the AppInitDLLs, LoadAppInit_DLLs are not getting set to the values 1,0 as it tries to.
Does this mean anything?
I’m running webpagetest-2.15 on Windows2k12 server (as Administrator).

Thanks.
[hr]
Hi Patrick,
In this page using http://calendar.perfplanet.com/2011/webpagetest-internals/, you talk about using (inject.cc) CreateRemoteThread() to load the dll. However, we see that in the latest code, it uses AppInitDlls approach.
Can you please clarify the difference here? I believe that the CreateRemoteThread() is more reliable.
Thanks

CreateRemoteThread is actually less reliable, particularly as the browsers put in more sandbox protections. I made the change to App Init dll’s close to a year ago and it solved a LOT of issues where the agent wouldn’t inject into the browser process correctly.

If the test itself is running fine then the App Init injection is working because the test is completely driven by the injected wpthook.dll.

Are you running wptdriver.exe from the same directory as your debug wpthook.dll?

Since we’re a 32-bit process running on a 64-bit OS you might be looking at the wrong place in the registry. You need to look at HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\Windows NT\CurrentVersion\Windows\AppInit_DLLs

I am running wptdriver.exe from Debug/ folder, same as wptload.dll.

You’re right; the REGKEY in the location you point out looks good.

To verify that I’m hitting the Winsock hooks as expected I added a fprintf(), OutputDebugString() inside the closesocket_Hook(), connect_Hook(), select_Hook(), but dont see the output after the test (the DbgView does show, “Pipe Logging: 10|202|Hook Active: closesocket”, …)

Also, the test itself (with IE, Chrome, Firefox) completes just fine.

What are the actual winsock hook routines that are invoked?

hmmm… The MessageBox() in wpthook.cc WptHook::Init(), (or DebugBreak(), fprintf, WriteFile()…) are not getting hit.

But the test itself completes fine. Could it be something in the Win2k12 server env?

Shouldn’t be. My best guess is that a different wpthook.dll is being used. Do you have the server pushing updates (check work/update/wptupdate.zip)? If so it could be overwriting your local build.

That is correct! Is there a way (ex. an entry in the wptdriver.ini) to get the server to NOT push these updates?

Best way is to just rename wptupdate.ini on the server so it doesn’t try to push the update. You can also create a directory under update with the name of the location and the server will look in there for updates instead if you only want to exclude a single location (like your dev location).