etw collector internal error when profiling remote app running inside docker container

Hi all,

When attaching w3wp and starting timeline, the following error occurs: 

-- Message #0
-----------------------------------------------------------------

ETW collector internal error
Attach command confirmation expected
[location] = C:\BuildAgent\work\ef275f8f93549f08\Profiler\Kernel\Windows\Native\Solution\core\src\bridges\etw\etw_bridge.cpp(150)
[function] = void __cdecl jbprof::etw_bridge::open(const struct jetbrains::collector::event_collector_filters &)
[HResult] = ADAB0000

-----------------------------------------------------------------

As the title  says, i am trying to connect to a remote app which is running inside a docker container. 

any help would be much appreciated. 

-----------------------------------------------------------------
ETW COLLECTOR LOG:

[2019-09-24 12:05:51.014362]: <info> Build version: 192.0.18135.19660.2019-08-27T10:55:21
[2019-09-24 12:05:51.015363]: <info> Command line arguments: C:\Windows\TEMP\jetbrainsetw_fb1469cb-647a-49be-bdac-8c202c3e65fc\JetBrains.Etw.Collector.exe -m 1 --disable HeapTraceProvider
[2019-09-24 12:05:51.016362]: <info> Config arguments:
[2019-09-24 12:05:51.016362]: <info> Image: 64-bit
[2019-09-24 12:05:51.017362]: <info> Running ETW session: ProviderEnableListener
[2019-09-24 12:05:51.018362]: <info> StartTrace: min_bufs = 8, max_bufs = 30, buf_size = 64
[2019-09-24 12:05:51.025361]: <info> Connecting to host
[2019-09-24 12:05:51.025361]: <info> Host command arrived: 0
[2019-09-24 12:05:51.025361]: <info> Pingback host with version: 254
[2019-09-24 12:05:51.026360]: <info> 1: Client connected. Total connected clients count: 1
[2019-09-24 12:05:51.026360]: <info> 1: Reading protocol version
[2019-09-24 12:05:51.026360]: <info> 1: Protocol version: 254
[2019-09-24 12:05:51.026360]: <info> 1: Confirm proto version: 1
[2019-09-24 12:05:51.798599]: <info> 2: Client connected. Total connected clients count: 2
[2019-09-24 12:05:51.798599]: <info> 2: Reading protocol version
[2019-09-24 12:05:51.798599]: <info> 2: Protocol version: 6
[2019-09-24 12:05:51.798599]: <info> 2: Confirm proto version: 1
[2019-09-24 12:05:51.798599]: <info> 2: Reading process_id -> clr_id -> event filters count
[2019-09-24 12:05:51.798599]: <info> Process id: 16092, clr id: 23
[2019-09-24 12:05:51.798599]: <info> Reading event filters, count: 0
[2019-09-24 12:05:51.799612]: <info> 2: Session token is: 140827d0-20c7-4063-ba40-00be9a0c122a
[2019-09-24 12:05:51.799612]: <info> 2: Initializing ETW collector
[2019-09-24 12:05:51.801608]: <info> Running ETW session: CoreProvider
[2019-09-24 12:05:51.802607]: <info> StartTrace: min_bufs = 16, max_bufs = 32, buf_size = 128
[2019-09-24 12:05:51.802607]: <info> Consumer thread started, name: CoreProvider
[2019-09-24 12:05:51.802607]: <info> Running ETW session: JetBrains_SystemTrace
[2019-09-24 12:05:51.923668]: <info> Session JetBrains_SystemTrace was not started previously
[2019-09-24 12:05:51.963652]: <info> StartTrace: min_bufs = 16, max_bufs = 1024, buf_size = 1024
[2019-09-24 12:05:51.963652]: <error> Provider JetBrains_SystemTrace: Set trace information failed (code = 4201)
[2019-09-24 12:05:51.963652]: <error> Set trace information failed, code = 4201
[2019-09-24 12:05:51.964642]: <error> Set trace information failed
[2019-09-24 12:05:51.964642]: <error> 2: Fail to execute command
[2019-09-24 12:05:51.964642]: <info> 2: Client detaching...
[2019-09-24 12:05:51.964642]: <info> 2: Client data clearing
[2019-09-24 12:05:51.964642]: <error> client not found, id: 1
[2019-09-24 12:05:51.964642]: <info> 2: Client data cleared
[2019-09-24 12:05:51.964642]: <info> 2: Client destroyed. Pipe stream closed. Total connected clients count: 1
[2019-09-24 12:05:52.670654]: <info> 1: Command: command_close (16)
[2019-09-24 12:05:52.670654]: <info> 1: Client data clearing
[2019-09-24 12:05:52.670654]: <info> 1: Client data cleared
[2019-09-24 12:05:52.670654]: <info> 1: Client detaching...
[2019-09-24 12:05:52.670654]: <info> 1: Client data clearing
[2019-09-24 12:05:52.670654]: <info> 1: Client data cleared
[2019-09-24 12:05:52.670654]: <info> 1: Client destroyed. Pipe stream closed. Total connected clients count: 0
[2019-09-24 12:05:52.670654]: <info> Host command arrived: 1
[2019-09-24 12:05:52.670654]: <info> Destroy all connections
[2019-09-24 12:05:52.671601]: <error> 0: Connection is broken, code: 109

ETW COLLECTOR HOST:
[2019-09-24 12:05:50.859360]: <info> Build version: 192.0.12.0.2019-08-27T10:55:21
[2019-09-24 12:05:50.861360]: <info> Executed as C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.Host.exe
[2019-09-24 12:05:50.861360]: <info> Image: 64-bit
[2019-09-24 12:05:50.861360]: <info> Service command line arguments: C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.Host.exe -m 1
[2019-09-24 12:05:50.868360]: <info> Console mode running, code: 0
[2019-09-24 12:05:50.869360]: <info> Craete ETW Host pipe
[2019-09-24 12:05:50.919410]: <info> 1: Client attached, connections count: 1, reading handshake
[2019-09-24 12:05:50.919410]: <info> 1: Protocol version: 253
[2019-09-24 12:05:50.919410]: <info> 1: ok, waiting for next command
[2019-09-24 12:05:50.920369]: <info> Received collector params from client: C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.exe --disable HeapTraceProvid
er
[2019-09-24 12:05:50.920369]: <info> Etw collector pipe created
[2019-09-24 12:05:50.927362]: <info> Running etw collector, image: C:\Windows\TEMP\jetbrainsetw_fb1469cb-647a-49be-bdac-8c202c3e65fc\JetBrains.Etw.Collector.exe, command line: -m 1 --disable HeapTraceProvider
[2019-09-24 12:05:50.988360]: <info> Verified: C:\Windows\TEMP\jetbrainsetw_fb1469cb-647a-49be-bdac-8c202c3e65fc\JetBrains.Etw.Collector.exe
[2019-09-24 12:05:50.993360]: <info> Etw collector started successfully
[2019-09-24 12:05:51.025361]: <info> 3: Collector pingback with protocol version: 254
[2019-09-24 12:05:51.025361]: <info> Processing get_collector request from 1
[2019-09-24 12:05:52.670654]: <error> 1: Connection is broken, code: 109
[2019-09-24 12:05:52.670654]: <info> 1: Client detach, connections count: 0
[2019-09-24 12:05:52.670654]: <info> The ETW Host pipe has been closed
[2019-09-24 12:05:52.670654]: <info> No active client connections left, send terminate command to collector
[2019-09-24 12:05:52.670654]: <info> Etw collector is still active, wait time left: 5sec
[2019-09-24 12:05:53.671611]: <info> Etw collector is still active, wait time left: 4sec
[2019-09-24 12:05:54.671704]: <info> Etw collector is still active, wait time left: 3sec
[2019-09-24 12:05:55.672822]: <info> Etw collector is still active, wait time left: 2sec
[2019-09-24 12:05:56.673779]: <info> Etw collector is still active, wait time left: 1sec
[2019-09-24 12:05:57.674039]: <info> Etw collector is still active, wait time left: 0sec
[2019-09-24 12:05:57.674039]: <info> Terminate etw collector
[2019-09-24 12:05:57.677014]: <info> Etw collector terminated


ETW COLLECTOR LOG:

[2019-09-24 12:05:50.859360]: <info> Build version: 192.0.12.0.2019-08-27T10:55:21
[2019-09-24 12:05:50.861360]: <info> Executed as C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.Host.exe
[2019-09-24 12:05:50.861360]: <info> Image: 64-bit
[2019-09-24 12:05:50.861360]: <info> Service command line arguments: C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.Host.exe -m 1
[2019-09-24 12:05:50.868360]: <info> Console mode running, code: 0
[2019-09-24 12:05:50.869360]: <info> Craete ETW Host pipe
[2019-09-24 12:05:50.919410]: <info> 1: Client attached, connections count: 1, reading handshake
[2019-09-24 12:05:50.919410]: <info> 1: Protocol version: 253
[2019-09-24 12:05:50.919410]: <info> 1: ok, waiting for next command
[2019-09-24 12:05:50.920369]: <info> Received collector params from client: C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.exe --disable HeapTraceProvid
er
[2019-09-24 12:05:50.920369]: <info> Etw collector pipe created
[2019-09-24 12:05:50.927362]: <info> Running etw collector, image: C:\Windows\TEMP\jetbrainsetw_fb1469cb-647a-49be-bdac-8c202c3e65fc\JetBrains.Etw.Collector.exe, command line: -m 1 --disable HeapTraceProvider
[2019-09-24 12:05:50.988360]: <info> Verified: C:\Windows\TEMP\jetbrainsetw_fb1469cb-647a-49be-bdac-8c202c3e65fc\JetBrains.Etw.Collector.exe
[2019-09-24 12:05:50.993360]: <info> Etw collector started successfully
[2019-09-24 12:05:51.025361]: <info> 3: Collector pingback with protocol version: 254
[2019-09-24 12:05:51.025361]: <info> Processing get_collector request from 1
[2019-09-24 12:05:52.670654]: <error> 1: Connection is broken, code: 109
[2019-09-24 12:05:52.670654]: <info> 1: Client detach, connections count: 0
[2019-09-24 12:05:52.670654]: <info> The ETW Host pipe has been closed
[2019-09-24 12:05:52.670654]: <info> No active client connections left, send terminate command to collector
[2019-09-24 12:05:52.670654]: <info> Etw collector is still active, wait time left: 5sec
[2019-09-24 12:05:53.671611]: <info> Etw collector is still active, wait time left: 4sec
[2019-09-24 12:05:54.671704]: <info> Etw collector is still active, wait time left: 3sec
[2019-09-24 12:05:55.672822]: <info> Etw collector is still active, wait time left: 2sec
[2019-09-24 12:05:56.673779]: <info> Etw collector is still active, wait time left: 1sec
[2019-09-24 12:05:57.674039]: <info> Etw collector is still active, wait time left: 0sec
[2019-09-24 12:05:57.674039]: <info> Terminate etw collector
[2019-09-24 12:05:57.677014]: <info> Etw collector terminated
PS C:\Users\ContainerAdministrator\AppData\Local\Temp\JetLogs> cat .\JetBrains.ETW.Controller.2019-09-24T12-05-50.log
[2019-09-24 12:05:50.302361]: <info> Build version: 192.0.18135.19660.2019-08-27T10:55:21
[2019-09-24 12:05:50.302361]: <info> controller commander created
[2019-09-24 12:05:50.302361]: <info> Host not running, attempting to start: "C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.Host.exe"
[2019-09-24 12:05:50.353361]: <info> Verified: C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.Host.exe
[2019-09-24 12:05:50.919410]: <info> Host connected, sending protocol version 253
[2019-09-24 12:05:50.919410]: <info> command arrived: 0
[2019-09-24 12:05:50.919410]: <info> Protocol version 253 accepted, requesting for collector
[2019-09-24 12:05:50.919410]: <info> Collector cmd: C:\Users\ContainerAdministrator\AppData\Local\JetBrains\Profiler\UserCache\Profiler.Windows.SysTools_fe8be372-075d-42ec-a8b3-7f8b8742792d\x64\JetBrains.Etw.Collector.exe --disable HeapTraceProvider
[2019-09-24 12:05:50.919410]: <info> Requesting collector pipe name
[2019-09-24 12:05:51.025361]: <info> Collector pipe name received from host, trying to connect collector
[2019-09-24 12:05:51.026360]: <info> executing command: 0
[2019-09-24 12:05:51.026360]: <info> command complete, waiting for client success callback execution
[2019-09-24 12:05:51.026360]: <info> success callback executed
[2019-09-24 12:05:52.596603]: <info> command arrived: 2
[2019-09-24 12:05:52.670654]: <info> executing command: 2
[2019-09-24 12:05:52.670654]: <info> command complete, waiting for client success callback execution
[2019-09-24 12:05:52.670654]: <info> ETW Collector pipe disconnected
[2019-09-24 12:05:52.670654]: <info> success callback executed
[2019-09-24 12:05:52.670654]: <info> controller commander destruction...
[2019-09-24 12:05:52.670654]: <info> controller commander destructed

0
4 comments

Michael,

 

I've answered to your colleague in the corresponding support ticket.

0

Is it possible to list the solution here as well?

1

I get scared when there's only 3 hits in Google for an error such as this.  This is one of those three (the other 2 are just GitHub Gists) and the answer is locked away in someone's support ticket!  Konstantin Katsnelson - please could you share those details?

0

Sure. It looks like this issue was caused by some changes made by Microsoft in system libraries or in permissions required to access these libraries.

The issue was fixed in the 2019.3 version of dotTrace. If you are using this (or newer) version of dotTrace and still facing this issue - please create a support ticket ("Submit a request" button in the upper right corner).

1

Please sign in to leave a comment.