Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Socket.Connect(Start|Stop) activity ID missmatch on Windows #41670

Closed
ManickaP opened this issue Sep 1, 2020 · 4 comments · Fixed by #42188
Closed

Socket.Connect(Start|Stop) activity ID missmatch on Windows #41670

ManickaP opened this issue Sep 1, 2020 · 4 comments · Fixed by #42188

Comments

@ManickaP
Copy link
Member

ManickaP commented Sep 1, 2020

New telemetry in System.Net.* namespace produces unexpected ActivityId in Sockets events, seen only on Windows so far.

13:09:56.5107297[RequestStart]00000011-0000-0000-0000-000076f49d59.00000000-0000-0000-0000-000000000000 scheme: https, host: httpbin.org, port: 443, pathAndQuery: /delay/1, versionMajor: 1, versionMinor: 1, versionPolicy: 0
13:09:56.9266637[ResolutionStart]00001011-0000-0000-0000-000076c49d59.00000011-0000-0000-0000-000076f49d59 hostNameOrAddress: 
13:09:56.9345468[ResolutionStop]00001011-0000-0000-0000-000076c49d59.00000000-0000-0000-0000-000000000000 
13:09:56.9666526[ResolutionStart]00002011-0000-0000-0000-000076d49d59.00000011-0000-0000-0000-000076f49d59 hostNameOrAddress: httpbin.org
13:09:57.1922317[ResolutionStop]00002011-0000-0000-0000-000076d49d59.00000000-0000-0000-0000-000000000000 
13:09:57.2279299[ConnectStart]00002111-0000-0000-0000-000076d79d59.00000011-0000-0000-0000-000076f49d59 address: InterNetworkV6:28:{1,187,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,255,35,170,21,246,0,0,0,0}
13:09:57.3805104[ConnectStop]00000000-0000-0000-0000-000000000000.00000000-0000-0000-0000-000000000000 
13:09:57.4509983[HandshakeStart]00003011-0000-0000-0000-000076a49d59.00000011-0000-0000-0000-000076f49d59 isServer: False, targetHost: httpbin.org
13:09:57.9794831[HandshakeStop]00003011-0000-0000-0000-000076a49d59.00000000-0000-0000-0000-000000000000 protocol: 3072
13:09:57.9858053[ConnectionEstablished]00000011-0000-0000-0000-000076f49d59.00000000-0000-0000-0000-000000000000 versionMajor: 1, versionMinor: 1
13:09:57.9981661[RequestHeadersStart]00004011-0000-0000-0000-000076b49d59.00000011-0000-0000-0000-000076f49d59
13:09:58.0127275[RequestHeadersStop]00004011-0000-0000-0000-000076b49d59.00000000-0000-0000-0000-000000000000 
13:09:59.1469800[ResponseHeadersStart]00005011-0000-0000-0000-000076849d59.00000011-0000-0000-0000-000076f49d59 
13:09:59.1619110[ResponseHeadersStop]00005011-0000-0000-0000-000076849d59.00000000-0000-0000-0000-000000000000 
13:09:59.1720101[ResponseContentStart]00006011-0000-0000-0000-000076949d59.00000011-0000-0000-0000-000076f49d59
13:09:59.1818268[ResponseContentStop]00006011-0000-0000-0000-000076949d59.00000000-0000-0000-0000-000000000000 
13:09:59.1871611[RequestStop]00000011-0000-0000-0000-000076f49d59.00000000-0000-0000-0000-000000000000
13:09:59.2011156[ConnectionClosed]00000000-0000-0000-0000-000000000000.00000000-0000-0000-0000-000000000000 versionMajor: 1, versionMinor: 1

Unexpected number:
[ConnectStart]00002111-0000-0000-0000-000076d79d59.00000011-0000-0000-0000-000076f49d59
Missing ActivityId:
[ConnectStop]00000000-0000-0000-0000-000000000000.00000000-0000-0000-0000-000000000000

@ManickaP ManickaP added this to the 5.0.0 milestone Sep 1, 2020
@ManickaP ManickaP self-assigned this Sep 1, 2020
@ghost
Copy link

ghost commented Sep 1, 2020

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

@Dotnet-GitSync-Bot Dotnet-GitSync-Bot added the untriaged New issue has not been triaged by the area owner label Sep 1, 2020
@jeffschwMSFT jeffschwMSFT removed the untriaged New issue has not been triaged by the area owner label Sep 1, 2020
@MihaZupan
Copy link
Member

For reference, with GUIDs translated to activity paths:

RequestStart            /1/1/
ResolutionStart         /1/1/1/         Related: /1/1/
ResolutionStop          /1/1/1/
ResolutionStart         /1/1/2/         Related: /1/1/
ResolutionStop          /1/1/2/
ConnectStart            /1/1/2/1/       Related: /1/1/
ConnectStop             00000000-0000-0000-0000-000000000000
HandshakeStart          /1/1/3/         Related: /1/1/
HandshakeStop           /1/1/3/
ConnectionEstablished   /1/1/
RequestHeadersStart     /1/1/4/         Related: /1/1/
RequestHeadersStop      /1/1/4/
ResponseHeadersStart    /1/1/5/         Related: /1/1/
ResponseHeadersStop     /1/1/5/
ResponseContentStart    /1/1/6/         Related: /1/1/
ResponseContentStop     /1/1/6/
RequestStop             /1/1/
ConnectionClosed        00000000-0000-0000-0000-000000000000

@ManickaP
Copy link
Member Author

ManickaP commented Sep 1, 2020

The weird ActivityId of ConnectStart (/1/1/2/1/) fixed in here: ManickaP@c4c9a2f. It was caused by non-awaited continuation for ResolutionStop.

@karelz
Copy link
Member

karelz commented Jan 26, 2021

Fixed in 6.0/master in PR #42188 and in 5.0 in PR #42726

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants