Skip to content

experiment: Add trace logging for pion (dtls,ice,pc) #147

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.

Sign up for GitHub

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

Jump to bottom
Closed
wants to merge 2 commits into from
Closed

experiment: Add trace logging for pion (dtls,ice,pc) #147

wants to merge 2 commits into from

Conversation

bryphe-coder
Copy link
Contributor

@bryphe-coder bryphe-coder commented Feb 2, 2022 •
edited
Loading

See if the additional logging from pion can give us any clues on the failures....

Test Runs

  • Run 1: ✅
  • Run 2: Hit failure
dtls TRACE: 23:39:00.909762 handshaker.go:166: [handshake:client] Flight 1: Waiting
pc WARNING: 2022/02/02 23:39:00 Failed to start manager: ICE connection not started
pc WARNING: 2022/02/02 23:39:00 Failed to start SCTP: DTLS not established
pc WARNING: 2022/02/02 23:39:00 undeclaredMediaProcessor failed to open SrtpSession: the DTLS transport has not started yet
pc INFO: 2022/02/02 23:39:00 ICE connection state changed: connected
    t.go:56: 2022-02-02 23:39:00.910 [DEBUG]	(client)	<conn.go:148>	ice connection state updated	{"state": "connected"}
pc WARNING: 2022/02/02 23:39:00 undeclaredMediaProcessor failed to open SrtcpSession: the DTLS transport has not started yet
pc INFO: 2022/02/02 23:39:00 ICE connection state changed: checking
    t.go:56: 2022-02-02 23:39:00.910 [DEBUG]	(client)	<conn.go:148>	ice connection state updated	{"state": "checking"}
    t.go:56: 2022-02-02 23:39:30.908 [DEBUG]	(server)	<conn.go:222>	dtls transport state updated	{"state": "failed"}
pc INFO: 2022/02/02 23:39:30 peer connection state changed: failed
pc WARNING: 2022/02/02 23:39:30 Failed to start manager: handshake error: context deadline exceeded
    t.go:56: 2022-02-02 23:39:30.909 [DEBUG]	(server)	<conn.go:186>	rtc connection updated	{"state": "failed"}

This is what we'd expect to see, instead:

    t.go:56: 2022-02-03 01:49:32.651 [DEBUG]    (server)        <conn.go:222>   dtls transport state updated    {"state": "connecting"}
pc INFO: 2022/02/03 01:49:32 ICE connection state changed: connected
    t.go:56: 2022-02-03 01:49:32.651 [DEBUG]    (server)        <conn.go:148>   ice connection state updated    {"state": "connected"}
    t.go:56: 2022-02-03 01:49:32.651 [DEBUG]    (client)        <conn.go:148>   ice connection state updated    {"state": "connected"}
dtls TRACE: 01:49:32.652197 handshaker.go:166: [handshake:client] Flight 1: Preparing
    t.go:56: 2022-02-03 01:49:32.651 [DEBUG]    (client)        <conn.go:222>   dtls transport state updated    {"state": "connecting"}
    t.go:56: 2022-02-03 01:49:32.651 [DEBUG]    (server)        <conn.go:226>   selected candidate pair changed {"local": {"foundation": "608990844", "priority": 2130706431, "address": "1.2.3.5", "protocol": 1, "port": 5887, "type": 1, "component": 1, "relatedAddress": "", "relatedPort": 0, "tcpType": ""}, "remote": {"foundation": "422338508", "priority": 2130706431, "address": "1.2.3.4", "protocol": 1, "port": 5081, "type": 1, "component": 1, "relatedAddress": "", "relatedPort": 0, "tcpType": ""}}
dtls TRACE: 01:49:32.652387 handshaker.go:166: [handshake:client] Flight 1: Sending
    t.go:56: 2022-02-03 01:49:32.651 [DEBUG]    (client)        <conn.go:226>   selected candidate pair changed {"local": {"foundation": "422338508", "priority": 2130706431, "address": "1.2.3.4", "protocol": 1, "port": 5081, "type": 1, "component": 1, "relatedAddress": "", "relatedPort": 0, "tcpType": ""}, "remote": {"foundation": "3674517152", "priority": 1862270975, "address": "1.2.3.5", "protocol": 1, "port": 5887, "type": 3, "component": 1, "relatedAddress": "", "relatedPort": 0, "tcpType": ""}}
dtls TRACE: 01:49:32.652587 conn.go:382: [handshake:client] -> ClientHello (epoch: 0, seq: 0)
dtls TRACE: 01:49:32.652733 handshaker.go:166: [handshake:server] Flight 0: Preparing
dtls TRACE: 01:49:32.652819 handshaker.go:166: [handshake:server] Flight 0: Sending
dtls TRACE: 01:49:32.652870 handshaker.go:166: [handshake:server] Flight 0: Waiting
dtls TRACE: 01:49:32.653020 handshaker.go:166: [handshake:client] Flight 1: Waiting
dtls INFO: 2022/02/03 01:49:32 [vendor time]
dtls TRACE: 01:49:32.654543 handshaker.go:283: [handshake:server] Flight 0 -> Flight 2
dtls TRACE: 01:49:32.654572 handshaker.go:166: [handshake:server] Flight 2: Preparing
dtls TRACE: 01:49:32.654606 handshaker.go:166: [handshake:server] Flight 2: Sending
dtls TRACE: 01:49:32.654669 conn.go:382: [handshake:server] -> HelloVerifyRequest (epoch: 0, seq: 0)
dtls TRACE: 01:49:32.654882 handshaker.go:166: [handshake:server] Flight 2: Waiting
dtls INFO: 2022/02/03 01:49:32 [vendor time]
dtls TRACE: 01:49:32.655164 handshaker.go:283: [handshake:client] Flight 1 -> Flight 3
dtls TRACE: 01:49:32.655193 handshaker.go:166: [handshake:client] Flight 3: Preparing
dtls TRACE: 01:49:32.655272 handshaker.go:166: [handshake:client] Flight 3: Sending
dtls TRACE: 01:49:32.655346 conn.go:382: [handshake:client] -> ClientHello (epoch: 0, seq: 1)
dtls TRACE: 01:49:32.655644 handshaker.go:166: [handshake:client] Flight 3: Waiting
dtls INFO: 2022/02/03 01:49:32 [vendor time]
dtls TRACE: 01:49:32.655787 handshaker.go:283: [handshake:server] Flight 2 -> Flight 4
dtls TRACE: 01:49:32.655812 handshaker.go:166: [handshake:server] Flight 4: Preparing
dtls TRACE: 01:49:32.655993 handshaker.go:166: [handshake:server] Flight 4: Sending
dtls TRACE: 01:49:32.656043 conn.go:382: [handshake:server] -> ServerHello (epoch: 0, seq: 1)
dtls TRACE: 01:49:32.656123 conn.go:382: [handshake:server] -> TypeCertificate (epoch: 0, seq: 2)
dtls TRACE: 01:49:32.656206 conn.go:382: [handshake:server] -> ServerKeyExchange (epoch: 0, seq: 3)
dtls TRACE: 01:49:32.656271 conn.go:382: [handshake:server] -> CertificateRequest (epoch: 0, seq: 4)
dtls TRACE: 01:49:32.656319 conn.go:382: [handshake:server] -> ServerHelloDone (epoch: 0, seq: 5)
dtls TRACE: 01:49:32.656559 handshaker.go:166: [handshake:server] Flight 4: Waiting
dtls TRACE: 01:49:32.656908 flight3handler.go:86: [handshake] use cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
dtls INFO: 2022/02/03 01:49:32 [vendor time]
dtls TRACE: 01:49:32.659273 handshaker.go:283: [handshake:client] Flight 3 -> Flight 5
dtls TRACE: 01:49:32.659311 handshaker.go:166: [handshake:client] Flight 5: Preparing
dtls TRACE: 01:49:32.660117 handshaker.go:234: [handshake:client] -> changeCipherSpec (epoch: 1)
dtls TRACE: 01:49:32.660159 handshaker.go:166: [handshake:client] Flight 5: Sending
dtls TRACE: 01:49:32.660197 conn.go:382: [handshake:client] -> TypeCertificate (epoch: 0, seq: 2)
dtls TRACE: 01:49:32.660265 conn.go:382: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 3)
dtls TRACE: 01:49:32.660308 conn.go:382: [handshake:client] -> CertificateVerify (epoch: 0, seq: 4)
dtls TRACE: 01:49:32.660351 conn.go:382: [handshake:client] -> Finished (epoch: 1, seq: 5)
dtls TRACE: 01:49:32.660671 handshaker.go:166: [handshake:client] Flight 5: Waiting
dtls DEBUG: 01:49:32.660814 conn.go:731: CipherSuite not initialized, queuing packet
dtls DEBUG: 01:49:32.660899 conn.go:653: received packet of next epoch, queuing packet
dtls TRACE: 01:49:32.662465 conn.go:737: server: <- ChangeCipherSpec (epoch: 1)
dtls INFO: 2022/02/03 01:49:32 [vendor time]
dtls TRACE: 01:49:32.662591 handshaker.go:283: [handshake:server] Flight 4 -> Flight 6
dtls TRACE: 01:49:32.662625 handshaker.go:166: [handshake:server] Flight 6: Preparing
dtls TRACE: 01:49:32.662743 handshaker.go:234: [handshake:server] -> changeCipherSpec (epoch: 1)
dtls TRACE: 01:49:32.662784 handshaker.go:166: [handshake:server] Flight 6: Sending
dtls TRACE: 01:49:32.662818 conn.go:382: [handshake:server] -> Finished (epoch: 1, seq: 6)
dtls TRACE: 01:49:32.663141 handshaker.go:166: [handshake:server] Flight 6: Finished
dtls TRACE: 01:49:32.663197 conn.go:211: Handshake Completed
dtls TRACE: 01:49:32.663203 conn.go:737: client: <- ChangeCipherSpec (epoch: 1)
dtls INFO: 2022/02/03 01:49:32 [vendor time]
dtls TRACE: 01:49:32.663517 handshaker.go:283: [handshake:client] Flight 5 -> Flight 5
dtls TRACE: 01:49:32.663561 handshaker.go:166: [handshake:client] Flight 5: Finished
dtls TRACE: 01:49:32.663615 conn.go:211: Handshake Completed
    t.go:56: 2022-02-03 01:49:32.663 [DEBUG]    (client)        <conn.go:222>   dtls transport state updated    {"state": "connected"}

Maybe related to this:
pion/dtls#279

@bryphe-coder bryphe-coder self-assigned this Feb 2, 2022
@codecov
Copy link

codecov bot commented Feb 2, 2022 •
edited
Loading

Codecov Report

Merging #147 (4bc8994) into main (d76737b) will decrease coverage by 1.34%.
The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff             @@
##             main     #147      +/-   ##
==========================================
- Coverage   70.63%   69.28%   -1.35%     
==========================================
  Files          98       98              
  Lines        4314     4314              
  Branches       68       68              
==========================================
- Hits         3047     2989      -58     
- Misses       1021     1093      +72     
+ Partials      246      232      -14
Flag Coverage Δ
unittest-go-macos-latest 68.76% <ø> (+0.80%) ⬆️
unittest-go-ubuntu-latest 69.30% <ø> (-1.01%) ⬇️
unittest-go-windows-latest ?
unittest-js 64.92% <ø> (ø)
Impacted Files Coverage Δ
database/postgres/postgres.go 0.00% <0.00%> (-70.74%) ⬇️
database/migrate.go 0.00% <0.00%> (-52.39%) ⬇️
coderd/coderdtest/coderdtest.go 77.35% <0.00%> (-22.65%) ⬇️
peer/channel.go 87.19% <0.00%> (+2.43%) ⬆️
peer/conn.go 82.81% <0.00%> (+4.94%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update d76737b...4bc8994. Read the comment docs.

@kylecarbs
Copy link
Member

Fixed in #153

@kylecarbs kylecarbs closed this Feb 3, 2022
@kylecarbs kylecarbs deleted the bryphe/investigate/pion-logging branch February 3, 2022 19:57
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@bryphe-coder @kylecarbs