[tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  new
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   |   Keywords:
Actual Points:   |  Parent ID:
   Points:   |   Reviewer:
  Sponsor:   |
-+
 proxy-go sometimes works itself into a state where it is still running and
 working, but using more than 100% CPU. I have had it happen locally a
 couple of times while testing turbotunnel stuff, and it's currently
 happening with proxy-go-restartless:
 {{{
 $ top
   PID USER  PR  NIVIRTRESSHR S  %CPU %MEM TIME+
 COMMAND
 13844 snowfla+  20   0  551292 320692   8844 R 161.1 15.6 129356:18 proxy-
 go
 }}}
 Or looking at single threads:
 {{{
 $ top -H
   PID USER  PR  NIVIRTRESSHR S %CPU %MEM TIME+ COMMAND
 24628 snowfla+  20   0  551292 320692   8844 R 39.7 15.6  15219:01 proxy-
 go
 13844 snowfla+  20   0  551292 320692   8844 R 35.4 15.6  15431:52 proxy-
 go
  1637 snowfla+  20   0  551292 320692   8844 R 34.8 15.6  16057:40 proxy-
 go
 13848 snowfla+  20   0  551292 320692   8844 S 27.5 15.6  13669:02 proxy-
 go
 13846 snowfla+  20   0  551292 320692   8844 S 22.5 15.6  17021:57 proxy-
 go
 }}}

 I caught it once and attached to the process with GDB, but didn't know
 what to make of it. `thread apply all bt` seemed to show all the threads
 being somewhere in the Go runtime; the thread that wasn't was not one of
 the threads using a lot of CPU. (Matching up the `PID` field from `top -H`
 with the `LWP` identifiers in gdb.)

 I had the idea to make proxy-go emit profiling output, and then exmine the
 call chain that was resulting the in the most CPU using
 [https://blog.golang.org/profiling-go-programs profiling tools]. A patch
 to do that is attachment:proxy-go-profile.patch. But I haven't been able
 to reproduce the high CPU usage yet.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  new
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+
Changes (by dcf):

 * Attachment "proxy-go-profile.patch" added.

 Patch that enables pprof output from proxy-go. Wait up to 10 seconds after
 Ctrl+C.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--
Changes (by dcf):

 * status:  new => needs_review


Comment:

 In the short term, I'd like to disable proxy-go-restartless, so we don't
 have a process that gets permanently wedged. The other proxy-go instances
 presumably also encounter the same problem, but they restart themselves
 every so often.

 Ok?

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--

Comment (by cohosh):

 Replying to [comment:1 dcf]:
 > In the short term, I'd like to disable proxy-go-restartless, so we don't
 have a process that gets permanently wedged. The other proxy-go instances
 presumably also encounter the same problem, but they restart themselves
 every so often.
 >
 > Ok?
 Sounds good to me. Thanks for catching this.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---
Changes (by cohosh):

 * status:  needs_review => needs_information


Comment:

 The patch also looks fine, though note that the function `getToken` is now
 unused.

 We could just deploy a version of the proxy-go with the profiling code
 without merging to master. I'd prefer that unless we feel the need to do
 profiling longer term.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by dcf):

 Replying to [comment:2 cohosh]:
 > Replying to [comment:1 dcf]:
 > > In the short term, I'd like to disable proxy-go-restartless, so we
 don't have a process that gets permanently wedged. The other proxy-go
 instances presumably also encounter the same problem, but they restart
 themselves every so often.
 > >
 > > Ok?
 > Sounds good to me. Thanks for catching this.

 Okay, I ran `sv down /etc/service/snowflake-proxy-restartless` at
 2020-02-10 22:51.

 Replying to [comment:3 cohosh]:
 > The patch also looks fine, though note that the function getToken is now
 unused.
 >
 > We could just deploy a version of the proxy-go with the profiling code
 without merging to master. I'd prefer that unless we feel the need to do
 profiling longer term.

 Sorry, I didn't mean to propose merging or deploying that patch. I think
 it's sufficient to try it locally. I was able to reproduce just by running
 proxy-go and restarting the client every few hours, but I wasn't profiling
 at the time.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 Starting to take a look at this. I haven't made it go into an infinite
 loop, but I have noticed that the proxy uses quite a bit of CPU,
 particularly if you have more than one client downloading files through
 it.

 The first thing that struck me was how much more expensive log messages
 are now that we're using safelog to perform regexes. The proxy-go
 instances are logging the byte count of every outgoing and incoming
 messaage [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/tree/proxy-go/snowflake.go#n94 here] and
 [https://gitweb.torproject.org/pluggable-transports/snowflake.git/tree
 /proxy-go/snowflake.go#n323 here]. Removing those shows that the remaining
 CPU time is spent in the pion library:

 {{{
 File: proxy-go
 Type: cpu
 Time: Feb 19, 2020 at 5:04pm (EST)
 Duration: 3.20mins, Total samples = 34.03s (17.73%)
 Entering interactive mode (type "help" for commands, "o" for options)
 (pprof) top --cum
 Showing nodes accounting for 7.20s, 21.16% of 34.03s total
 Dropped 423 nodes (cum <= 0.17s)
 Showing top 10 nodes out of 229
   flat  flat%   sum%cum   cum%
  0.09s  0.26%  0.26%  9.87s 29.00%  runtime.systemstack
  0.05s  0.15%  0.41%  6.61s 19.42%
 github.com/pion/sctp.(*Association).writeLoop
 6s 17.63% 18.04% 6s 17.63%  runtime.futex
  0.03s 0.088% 18.13%  5.54s 16.28%
 github.com/pion/dtls.(*Conn).Write
  0.01s 0.029% 18.16%  5.30s 15.57%
 github.com/pion/dtls.(*Conn).flushPacketBuffer
  0.03s 0.088% 18.25%  5.24s 15.40%  runtime.mcall
  0.07s  0.21% 18.45%  5.01s 14.72%  runtime.schedule
  0.65s  1.91% 20.36%  4.81s 14.13%  runtime.mallocgc
  0.04s  0.12% 20.48%  4.35s 12.78%  runtime.park_m
  0.23s  0.68% 21.16%  4.25s 12.49%  runtime.findrunnable
 }}}

 Removing the log messages is a good start. Doing so makes it so that a
 single client downloading a large file over snowflake uses a maximum of
 about 43% CPU, whereas with the log messages, a single client would cause
 the proxy-go instance to use up to 60% CPU.

 I'll do a deeper dive into the pion code to see if there's something that
 can be optimized there.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 I'm tracking changes to snowflake here:
 https://github.com/cohosh/snowflake/tree/ticket/33211

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by dcf):

 Replying to [comment:5 cohosh]:
 > The first thing that struck me was how much more expensive log messages
 are now that we're using safelog to perform regexes.

 I noticed this too, that in normal operation the CPU use of proxy-go is
 dominated by safelog.

 My feeling is that the occasional anomalous high CPU usage is something
 else. I'll not that I think I have seen the same symptom in snowflake-
 client as well. I neglected to write it down, but I made it happen in the
 past few weeks running the command-line client. I think that was with a
 non–Turbo Tunnel client. I also had it happen again today, with the quic
 snowflake client from #6. I left the browser idle for about a half an
 hour, and when I came back the fans were spinning and it was using
 160–180% CPU. But just as I started to investigate, it resolved itself
 spontaneously and returned to normal levels. I hadn't one of the programs
 escape from that state before.

 > The proxy-go instances are logging the byte count of every outgoing and
 incoming messaage [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/tree/proxy-go/snowflake.go#n94 here] and
 [https://gitweb.torproject.org/pluggable-transports/snowflake.git/tree
 /proxy-go/snowflake.go#n323 here]. Removing those shows that the remaining
 CPU time is spent in the pion library:

 Agree that logging every message is excessive.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 Replying to [comment:7 dcf]:
 > My feeling is that the occasional anomalous high CPU usage is something
 else. I'll not that I think I have seen the same symptom in snowflake-
 client as well. I neglected to write it down, but I made it happen in the
 past few weeks running the command-line client. I think that was with a
 non–Turbo Tunnel client. I also had it happen again today, with the quic
 snowflake client from #6. I left the browser idle for about a half an
 hour, and when I came back the fans were spinning and it was using
 160–180% CPU. But just as I started to investigate, it resolved itself
 spontaneously and returned to normal levels. I hadn't one of the programs
 escape from that state before.

 Hmm, well if it's something in pion, that would explain why we're seeing
 it on both the client and proxy. There's a lot of code reuse there.
 Digging into pion/sctp in particular, there are quite a few loops in use
 that are candidates for closer examination.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by dcf):

 Replying to [comment:7 dcf]:
 > I also had it happen again today, with the quic snowflake client from
 #6. I left the browser idle for about a half an hour, and when I came
 back the fans were spinning and it was using 160–180% CPU. But just as I
 started to investigate, it resolved itself spontaneously and returned to
 normal levels.

 I got this again just now, and this time I happened to be watching the
 log. It happened right after my wifi dropped out, which caused the broker
 HTTP request to stall for 5 minutes before timing out. (Side note, we
 should probably reduce that timeout.) The high CPU happened immediately
 after the "connection" timed out" log message. It lasted for less than a
 minute, then went back to normal.
 {{{
 2020/02/19 23:25:49 WebRTC: Set local description
 2020/02/19 23:25:49 WebRTC: Got ICE candidate: host [scrubbed]
 2020/02/19 23:25:50 WebRTC: Got ICE candidate: srflx [scrubbed] related
 [scrubbed]
 2020/02/19 23:25:50 WebRTC: Done gathering candidates
 2020/02/19 23:25:50 WebRTC: Got ICE candidate: srflx [scrubbed] related
 [scrubbed]7
 2020/02/19 23:25:50 WebRTC: ICEGatheringStateComplete
 2020/02/19 23:25:50 Negotiating via BrokerChannel...
 Target URL:  snowflake-broker.azureedge.net
 Front URL:   ajax.aspnetcdn.com

 2020/02/19 23:30:57 BrokerChannel Error: read tcp [scrubbed]->[scrubbed]:
 read: connection timed out
 2020/02/19 23:30:57 Failed to retrieve answer. Retrying in 10s
 }}}
 Possibly there is a pent-up timer or other recurrent event that creates a
 lot of work while the client is blocking in the HTTP request.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 Replying to [comment:9 dcf]:
 > Replying to [comment:7 dcf]:
 > > I also had it happen again today, with the quic snowflake client from
 #6. I left the browser idle for about a half an hour, and when I came
 back the fans were spinning and it was using 160–180% CPU. But just as I
 started to investigate, it resolved itself spontaneously and returned to
 normal levels.
 >
 > I got this again just now, and this time I happened to be watching the
 log. It happened right after my wifi dropped out, which caused the broker
 HTTP request to stall for 5 minutes before timing out. (Side note, we
 should probably reduce that timeout.) The high CPU happened immediately
 after the "connection" timed out" log message. It lasted for less than a
 minute, then went back to normal.
 ...
 > Possibly there is a pent-up timer or other recurrent event that creates
 a lot of work while the client is blocking in the HTTP request.

 Was this when the client was first starting up or a reconnection through a
 new snowflake?

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by dcf):

 Replying to [comment:10 cohosh]:
 > Was this when the client was first starting up or a reconnection through
 a new snowflake?

 It was during reconnection. I was browsing and the browser stopped working
 for 5 minutes, then it came back. The browser had been running for a few
 hours before it happened. I'm actually still using the same browser
 instance now.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by dcf):

 I've done some profiling locally and I now think that the high CPU use in
 the quic snowflake-client has nothing to do with the high CPU use in
 proxy-go. I created a separate ticket #33401.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 I did some investigating and looks like pion is using DTLS with the
 ciphersuite `TLS_ECDHE_ECDSA_WITH_AES_128_CCM`. I'm almost certain this is
 not a common ciphersuite to use and that we'll be changing this later
 anyway once we have a better idea of the difference between snowflake
 WebRTC fingerprints and other common WebRTC tools. In fact, looking at a
 previous analysis of Snowflake that used the popular Chrome WebRTC
 library, CCM is never listed in the ClientHello as a possible ciphersuite:
 https://trac.torproject.org/projects/tor/wiki/doc/Snowflake/Fingerprinting

 What's relevant to this discussion is that a large amount of the CPU time
 is spent on the CCM encryption operation and I noticed that while
 pion/dtls uses the builtin golang crypto implementations for the other
 ciphersuites it supports, they
 [https://github.com/pion/dtls/tree/master/pkg/crypto/ccm roll their own
 CCM implementation]. My current plan is to remove CCM from the list of
 accepted ciphersuites and see what impact this has on the performance
 first.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---
Changes (by cohosh):

 * Attachment "0001-Change-list-of-dtls-ciphersuites.patch" added.


--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---
Changes (by cohosh):

 * Attachment "0001-Change-list-of-dtls-ciphersuites.patch" added.


--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---
Changes (by cohosh):

 * Attachment "0001-Change-list-of-dtls-ciphersuites.2.patch" added.


--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  (none)
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 Looks like there's no way to set the DTLS ciphersuites from the API. I've
 attached a patch I used on pion/webrtc to set the ciphersuite to just
 `TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256`.

 The result was a huge improvement in performance. The CPU profile output
 is now:

 {{{
 (pprof) top --cum
 Showing nodes accounting for 1.94s, 27.09% of 7.16s total
 Dropped 182 nodes (cum <= 0.04s)
 Showing top 10 nodes out of 231
   flat  flat%   sum%cum   cum%
  0 0% 0%  2.12s 29.61%  runtime.systemstack
  1.74s 24.30% 24.30%  1.74s 24.30%  runtime.futex
  0 0% 24.30%  1.29s 18.02%  runtime.mcall
  0.04s  0.56% 24.86%  1.23s 17.18%  runtime.schedule
  0 0% 24.86%  1.15s 16.06%  runtime.park_m
  0.02s  0.28% 25.14%  1.01s 14.11%  runtime.futexsleep
  0.05s   0.7% 25.84%  0.98s 13.69%  runtime.findrunnable
  0 0% 25.84%  0.93s 12.99%
 github.com/pion/sctp.(*Association).writeLoop
  0.09s  1.26% 27.09%  0.93s 12.99%  runtime.sysmon
  0 0% 27.09%  0.91s 12.71%  runtime.mstart
 }}}

 One client downloading a large file now takes 10-20% CPU as opposed to the
 ~50% before.

 It would be best for us to be able to set the ciphersuites in the API, so
 I'll file an issue with pion for that. I'll also file an issue to take a
 look at the performance of CCM and suggest using a more popular
 ciphersuite as the default.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  assigned
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--
Changes (by cohosh):

 * owner:  (none) => cohosh
 * status:  needs_information => assigned


Comment:

 I filed these two tickets:
 - https://github.com/pion/webrtc/issues/1043
 - https://github.com/pion/dtls/issues/199

 I'm going to work on a patch for the second one now.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--
Changes (by cohosh):

 * status:  assigned => needs_review


Comment:

 Okay, the [https://github.com/pion/dtls/pull/200/ fix for this] was merged
 at
 [https://github.com/pion/dtls/commit/147774b64b6a8ac9bd0af5a7efff69ee8e0fd4a8
 8e0fd4a8] thanks to Sean.

 Note that this will also improve performance at the client side. Still not
 sure if this is the cause of the issue that dcf was seeing originally, but
 it's reasonable that a proxy-go instance with more than 2 or 3
 simultaneous clients would show 100+% CPU usage earlier. We can deploy the
 changes and see what we get.

 I'm putting this in needs_review to review the patch that removes logging:
 https://github.com/cohosh/snowflake/pull/18

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--
Changes (by dcf):

 * Attachment "proxy-go-profile.patch.2" added.

 Patch to add profiling to proxy-go against commit 380b1331

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--
Changes (by dcf):

 * Attachment "proxy-go.profile.2020-02-22T20:32:32Z" added.

 Profile produced by https://people.torproject.org/~dcf/bug33211/proxy-
 go.380b1331.profiled

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--
Changes (by dcf):

 * Attachment "proxy-go.profile.2020-02-22T20:32:32Z.png" added.

 Graph of proxy-go.profile.2020-02-22T20:32:32Z

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+--
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_review
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+--

Comment (by dcf):

 Good work with the CCM discovery. It's different from what I filed the
 ticket about, but it will help everything regardless.

 I reproduced the symptoms I was thinking of and got a profile. Files are
 at https://people.torproject.org/~dcf/bug33211/. I had to let proxy-go run
 for an hour (details below) until it happened. Then I let it run for 30
 minutes at high CPU so that whatever was going wrong would dominate the
 profile. The [https://people.torproject.org/~dcf/bug33211/proxy-
 go.profile.2020-02-22T20:32:32Z.png graph] tells the story.
 `pion/dtls/internal/crypto/ccm.(*ccm).cbcRound` and
 `crypto/aes.encryptBlockAsm` are major contributors, but I believe they
 are a separate issue that is fixed by your comment:16. The culprit for
 what I was describing of is
 `pion/sctp.(*payloadQueue).markAllToRetrasmit`, called by
 `sctp.(*Association).onRetransmissionTimeout`. It looks to me like a timer
 somewhere is becoming negative and becoming a busy-loop (similar to the
 bug in quic-go from #33401).

 During the time of high CPU usage, proxy-go wasn't producing an abnormal
 amount of log output (probably about 1 line per second on average), nor
 was it sending an abnormal amount of packets.

 {{{
 go tool pprof proxy-go.380b1331.profiled 'proxy-
 go.profile.2020-02-22T20:32:32Z'
 File: proxy-go.380b1331.profiled
 Type: cpu
 Time: Feb 22, 2020 at 1:32pm (MST)
 Duration: 1.59hrs, Total samples = 1.08hrs (67.68%)
 Entering interactive mode (type "help" for commands, "o" for options)
 (pprof) top5
 Showing nodes accounting for 23.95mins, 37.03% of 64.68mins total
 Dropped 999 nodes (cum <= 0.32mins)
 Showing top 5 nodes out of 139
   flat  flat%   sum%cum   cum%
   8.07mins 12.48% 12.48%   8.07mins 12.48%  runtime.futex
   4.65mins  7.20% 19.67%  11.15mins 17.23%
 github.com/pion/sctp.(*payloadQueue).markAllToRetrasmit
   4.35mins  6.72% 26.39%   6.35mins  9.82%  runtime.mapiternext
   3.98mins  6.15% 32.55%   3.98mins  6.15%  crypto/aes.encryptBlockAsm
   2.90mins  4.48% 37.03%   5.03mins  7.78%  runtime.scanobject
 (pprof) evince
 }}}

 == Procedure

 Here is what I did to collect the profile, starting at commit
 380b133155ad725126bc418d0e66b3c550b4c555 patched with attachment:proxy-go-
 profile.patch.2. I started a local broker, proxy, and bridge, then set up
 a loop to have a client connect every 2.5 minutes. I was also
 intermittently downloading through the SOCKS port 1, but I don't know
 if that matters.

 {{{
 broker/broker --disable-tls --addr 127.0.0.1:8000
 proxy-go/proxy-go --broker http://127.0.0.1:8000/ --relay
 ws://127.0.0.1:8080/
 tor -f torrc.server
 while true; do timeout 150 tor -f torrc.client SOCKSPort 1; done
 }}}

 torrc.server:
 {{{
 DataDirectory datadir-server
 SocksPort 0
 ORPort 9001
 ExtORPort auto
 BridgeRelay 1
 AssumeReachable 1
 PublishServerDescriptor 0
 ServerTransportListenAddr snowflake 0.0.0.0:8080
 ServerTransportPlugin snowflake exec server/server --disable-tls --log
 snowflake-server.log
 }}}

 torrc.client:
 {{{
 UseBridges 1
 DataDirectory datadir-client
 ClientTransportPlugin snowflake exec client/client \
 -url http://127.0.0.1:8000/ \
 -ice stun:stun.l.google.com:19302 \
 -log snowflake-client.log \
 -max 2
 Bridge snowflake 0.0.3.0:1
 }}}

 * I started everything at 2020-02-22 20:32:55.
 * proxy-go jumped to 200% CPU at about 2020-02-22 21:36:40, roughly one
 hour later. (It happened suddenly, not a gradual increase. The fans start
 spinning.)
 * After 5 minutes it was up to 250% CPU.
 * After 8 minutes it was up to 280% CPU.
 * I killed the tor client loop after 15 minutes at 2020-02-22 21:51:55.
 The high CPU use of proxy-go continued, being in the range of about
 260–295%.
 * I killed the tor server after 30 minutes at 2020-02-22 22:05:46. proxy-
 go's CPU use immediately became negligible.
 * I killed proxy-go at 2020-02-22 22:08:02 and saved the profile.

 The last log output of proxy-go was:
 {{{
 2020/02/22 22:04:23 Write 536 bytes --> WebRTC
 2020/02/22 22:04:26 Write 536 bytes --> WebRTC
 2020/02/22 22:04:28 Write 536 bytes --> WebRTC
 2020/02/22 22:04:29 Write 536 bytes --> WebRTC
 2020/02/22 22:05:46 io.Copy inside CopyLoop generated an error: websocket:
 close 1006 (abnormal closure): unexpected EOF
 2020/02/22 22:05:46 io.Copy inside CopyLoop generated an error: webso

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+-
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  merge_ready
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+-
Changes (by dcf):

 * status:  needs_review => merge_ready


Comment:

 Replying to [comment:16 cohosh]:
 > I'm putting this in needs_review to review the patch that removes
 logging: https://github.com/cohosh/snowflake/pull/18

 Ok.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+-
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  merge_ready
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+-

Comment (by cohosh):

 Replying to [comment:17 dcf]:
 > I reproduced the symptoms I was thinking of and got a profile. Files are
 at https://people.torproject.org/~dcf/bug33211/. I had to let proxy-go run
 for an hour (details below) until it happened. Then I let it run for 30
 minutes at high CPU so that whatever was going wrong would dominate the
 profile. The [https://people.torproject.org/~dcf/bug33211/proxy-
 go.profile.2020-02-22T20:32:32Z.png graph] tells the story.
 `pion/dtls/internal/crypto/ccm.(*ccm).cbcRound` and
 `crypto/aes.encryptBlockAsm` are major contributors, but I believe they
 are a separate issue that is fixed by your comment:16. The culprit for
 what I was describing of is
 `pion/sctp.(*payloadQueue).markAllToRetrasmit`, called by
 `sctp.(*Association).onRetransmissionTimeout`. It looks to me like a timer
 somewhere is becoming negative and becoming a busy-loop (similar to the
 bug in quic-go from #33401).
 >
 > During the time of high CPU usage, proxy-go wasn't producing an abnormal
 amount of log output (probably about 1 line per second on average), nor
 was it sending an abnormal amount of packets.

 Ah interesting. Nice work with this! I can take a closer look at the SCTP
 code next week.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+-
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  merge_ready
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+-
Changes (by cohosh):

 * Attachment "0001-Add-logging-for-pion-library-calls.patch" added.


--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+-
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  merge_ready
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+-

Comment (by cohosh):

 I haven't been able to reproduce this yet, but I'm going to try running it
 outside of a Docker container to see if that helps. I'm using
 attachment:0001-Add-logging-for-pion-library-calls.patch to log debug
 messages from the pion library.

 One thing I did notice, just from staring at the code, is that there's a
 race condition to access the `inflightQueue` chunkmap (which is
 essentially a map between the TSNs and payloads of unacknowledged
 packets). This map is written to when packets are
 [https://github.com/pion/sctp/blob/master/association.go#L1744 pushed] and
 [https://github.com/pion/sctp/blob/master/association.go#L1177 popped],
 and read from in many places. In particular, the function that's the
 source of the problem is when packets are marked for retransmission which
 [https://github.com/pion/sctp/blob/master/payload_queue.go#L163 iterates
 over the range of the map]. This should always occur in a
 [https://github.com/pion/sctp/blob/master/rtx_timer.go#L144 separate
 goroutine] from the rest of the map accesses.

 I added some print statements to try to confirm this, but like I said I
 haven't been able to reproduce the bug yet.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+-
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  merge_ready
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+-

Comment (by cohosh):

 Here's a patch to try:
 https://github.com/cohosh/sctp/commit/6e08a5eec9e421ae45ac6b322baba3a77b9dde6a

 I'll open a PR for this anyway, but it would be nice to confirm that it
 actually solves our problem.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+-
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  merge_ready
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+-

Comment (by cohosh):

 Submitted a PR: https://github.com/pion/sctp/pull/115

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---
Changes (by cohosh):

 * status:  merge_ready => needs_information


Comment:

 Merged [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/commit/?id=2e9e8071787398d9713395d94d93b5427ac8d452
 7ac8d452] to master

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by dcf):

 Replying to [comment:20 cohosh]:
 > I haven't been able to reproduce this yet, but I'm going to try running
 it outside of a Docker container to see if that helps. I'm using
 attachment:0001-Add-logging-for-pion-library-calls.patch to log debug
 messages from the pion library.

 I got it to happen again, with the logging patch. Something went wrong
 with the profiling and the profile output was 0 bytes. I had built the
 executable with `-race`, but I didn't see any race-related messages in the
 log.
  * [https://people.torproject.org/~dcf/bug33211/proxy-
 go.2e9e8071.profiled+logging+race proxy-go.2e9e8071.profiled+logging+race]
 executable
  * [https://people.torproject.org/~dcf/bug33211/proxy-
 go.2e9e8071.profiled+logging+race.log.xz proxy-
 go.2e9e8071.profiled+logging+race.log.xz] log file, 6 MB, decompresses to
 158 MB because of massive logging

 I started everything according to the procedure in comment:17 at about
 2020-02-26 00:50. It jumped to 250% CPU about one hour later at 2020-02-26
 01:58:07. (Note that the pion log lines use local time (UTC–7) instead of
 UTC, so the timestamp to look for is 18:58:07.) It's obvious in the log
 file where it happens, starting at line 48424:

 {{{
 sctp DEBUG: 18:58:07.240692 association.go:648: [0xc94ea0] sending
 SACK: SACK cumTsnAck=4213437655 arwnd=1048576 dupTsn=[]
 sctp DEBUG: 18:58:07.295662 stream.go:118: [0:0xc94ea0]
 reassemblyQueue readable=true
 sctp DEBUG: 18:58:07.295750 stream.go:120: [0:0xc94ea0]
 readNotifier.signal()
 sctp DEBUG: 18:58:07.295798 stream.go:122: [0:0xc94ea0]
 readNotifier.signal() done
 sctp DEBUG: 18:58:07.414562 stream.go:118: [0:0xc94ea0]
 reassemblyQueue readable=true
 sctp DEBUG: 18:58:07.414629 stream.go:120: [0:0xc94ea0]
 readNotifier.signal()
 sctp DEBUG: 18:58:07.414671 stream.go:122: [0:0xc94ea0]
 readNotifier.signal() done
 sctp DEBUG: 18:58:07.414811 association.go:648: [0xc94ea0] sending
 SACK: SACK cumTsnAck=4213437657 arwnd=1048040 dupTsn=[]
 sctp DEBUG: 18:58:07.561561 stream.go:118: [0:0xc94ea0]
 reassemblyQueue readable=true
 sctp DEBUG: 18:58:07.561630 stream.go:120: [0:0xc94ea0]
 readNotifier.signal()
 sctp DEBUG: 18:58:07.561671 stream.go:122: [0:0xc94ea0]
 readNotifier.signal() done
 sctp DEBUG: 18:58:07.636247 stream.go:118: [0:0xc94ea0]
 reassemblyQueue readable=true
 sctp DEBUG: 18:58:07.636309 stream.go:120: [0:0xc94ea0]
 readNotifier.signal()
 sctp DEBUG: 18:58:07.636358 stream.go:122: [0:0xc94ea0]
 readNotifier.signal() done
 sctp DEBUG: 18:58:07.636511 association.go:648: [0xc94ea0] sending
 SACK: SACK cumTsnAck=4213437659 arwnd=1048576 dupTsn=[]
 sctp DEBUG: 18:58:07.744138 stream.go:118: [0:0xc94ea0]
 reassemblyQueue readable=true
 sctp DEBUG: 18:58:07.744215 stream.go:120: [0:0xc94ea0]
 readNotifier.signal()
 sctp DEBUG: 18:58:07.744249 stream.go:122: [0:0xc94ea0]
 readNotifier.signal() done
 sctp DEBUG: 18:58:07.762724 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=63 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.763026 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=64 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.763203 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=65 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.763346 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=66 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.763518 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=67 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.763722 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=68 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.763895 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=69 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.764038 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=70 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.764202 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=71 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.764426 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=72 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.764601 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=73 cwnd=1228 ssthresh=4912
 sctp DEBUG: 18:58:07.764741 association.go:2066: [0xc941a0] T3-rtx
 timed out: nRtos=74 c

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+---
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  needs_information
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+---

Comment (by cohosh):

 Ah, this explains why I wasn't able to reproduce it. Looks like this bug
 was fixed in the most recent version:
 https://github.com/pion/sctp/issues/114#issuecomment-591280752

 Which version of sctp were you using?

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Re: [tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-+
 Reporter:  dcf  |  Owner:  cohosh
 Type:  defect   | Status:  closed
 Priority:  Medium   |  Milestone:
Component:  Circumvention/Snowflake  |Version:
 Severity:  Normal   | Resolution:  fixed
 Keywords:   |  Actual Points:
Parent ID:   | Points:
 Reviewer:   |Sponsor:
-+
Changes (by dcf):

 * status:  needs_information => closed
 * resolution:   => fixed


Comment:

 Replying to [comment:25 cohosh]:
 > Ah, this explains why I wasn't able to reproduce it. Looks like this bug
 was fixed in the most recent version:
 https://github.com/pion/sctp/issues/114#issuecomment-591280752
 >
 > Which version of sctp were you using?

 It was 32f160c5ee1fe015c168a0fc8272633b73c5e4bf, which in in between 1.7.3
 and 1.7.4.

 I rebuilt proxy-go with commit 2e9e8071787398d9713395d94d93b5427ac8d452
 and pion/sctp 1.7.5 and redeployed at about 2020-02-27 17:50.

--
Ticket URL: 
Tor Bug Tracker & Wiki 
The Tor Project: anonymity online
___
tor-bugs mailing list
tor-bugs@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs