[GH-ISSUE #137] Too high memory usage #113

Closed
opened 2026-02-26 12:34:00 +03:00 by kerem · 20 comments
Owner

Originally created by @notsure2 on GitHub (Dec 5, 2020).
Original GitHub issue: https://github.com/cbeuw/Cloak/issues/137

Stress testing ck-server with NumConn=0 and making only around 70 Cloak sessions, it's already consuming 180 MB of RAM and it continues to climb. It doesn't seem to be releasing memory properly even after the connections are stopped. There seems to be a memory leak.

Originally created by @notsure2 on GitHub (Dec 5, 2020). Original GitHub issue: https://github.com/cbeuw/Cloak/issues/137 Stress testing ck-server with NumConn=0 and making only around 70 Cloak sessions, it's already consuming 180 MB of RAM and it continues to climb. It doesn't seem to be releasing memory properly even after the connections are stopped. There seems to be a memory leak.
kerem closed this issue 2026-02-26 12:34:00 +03:00
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

Info from pprof:

File: ck-server
Type: inuse_space
Time: Dec 5, 2020 at 3:53am (EET)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 71.75MB, 100% of 71.75MB total
Showing top 10 nodes out of 16
      flat  flat%   sum%        cum   cum%
      49MB 68.30% 68.30%    54.70MB 76.23%  time.AfterFunc
   12.50MB 17.42% 85.72%    67.20MB 93.66%  github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo
    5.69MB  7.93% 93.66%     5.69MB  7.93%  time.startTimer
    2.02MB  2.81% 96.46%     2.52MB  3.51%  github.com/cbeuw/Cloak/internal/multiplex.MakeSession
    1.02MB  1.42% 97.89%     1.02MB  1.42%  github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex
    0.51MB  0.71% 98.60%     0.51MB  0.71%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom
    0.51MB  0.71% 99.30%     0.51MB  0.71%  github.com/cbeuw/Cloak/internal/common.NewTLSConn
    0.50MB   0.7%   100%     0.50MB   0.7%  github.com/cbeuw/Cloak/internal/multiplex.makeSwitchboard
         0     0%   100%    67.71MB 94.37%  github.com/cbeuw/Cloak/internal/common.Copy
         0     0%   100%    67.20MB 93.66%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo
<!-- gh-comment-id:739105081 --> @notsure2 commented on GitHub (Dec 5, 2020): Info from pprof: ``` File: ck-server Type: inuse_space Time: Dec 5, 2020 at 3:53am (EET) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 71.75MB, 100% of 71.75MB total Showing top 10 nodes out of 16 flat flat% sum% cum cum% 49MB 68.30% 68.30% 54.70MB 76.23% time.AfterFunc 12.50MB 17.42% 85.72% 67.20MB 93.66% github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo 5.69MB 7.93% 93.66% 5.69MB 7.93% time.startTimer 2.02MB 2.81% 96.46% 2.52MB 3.51% github.com/cbeuw/Cloak/internal/multiplex.MakeSession 1.02MB 1.42% 97.89% 1.02MB 1.42% github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex 0.51MB 0.71% 98.60% 0.51MB 0.71% github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom 0.51MB 0.71% 99.30% 0.51MB 0.71% github.com/cbeuw/Cloak/internal/common.NewTLSConn 0.50MB 0.7% 100% 0.50MB 0.7% github.com/cbeuw/Cloak/internal/multiplex.makeSwitchboard 0 0% 100% 67.71MB 94.37% github.com/cbeuw/Cloak/internal/common.Copy 0 0% 100% 67.20MB 93.66% github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo ```
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

profile001

<!-- gh-comment-id:739106075 --> @notsure2 commented on GitHub (Dec 5, 2020): ![profile001](https://user-images.githubusercontent.com/35424927/101230548-a11a5900-36ae-11eb-92c0-d2349a4ddced.png)
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

Example of triggering event: Use NumConn=0, setup as plugin with shadowsocks, setup with qBittorrent, set large number of simultaneous connections in qBittorrent, download a torrent with lot of sources (eg: Linux Distro).

<!-- gh-comment-id:739107147 --> @notsure2 commented on GitHub (Dec 5, 2020): Example of triggering event: Use NumConn=0, setup as plugin with shadowsocks, setup with qBittorrent, set large number of simultaneous connections in qBittorrent, download a torrent with lot of sources (eg: Linux Distro).
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

(pprof) list multiplex
Total: 161.43MB
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go
    1.02MB     1.02MB (flat, cum)  0.63% of Total
         .          .    172:
         .          .    173:// ReadFrom continuously read data from r and send it off, until either r returns error or nothing has been read
         .          .    174:// for readFromTimeout amount of time
         .          .    175:func (s *Stream) ReadFrom(r io.Reader) (n int64, err error) {
         .          .    176:   if s.obfsBuf == nil {
    1.02MB     1.02MB    177:           s.obfsBuf = make([]byte, s.session.StreamSendBufferSize)
         .          .    178:   }
         .          .    179:   for {
         .          .    180:           if s.readFromTimeout != 0 {
         .          .    181:                   if rder, ok := r.(net.Conn); !ok {
         .          .    182:                           log.Warn("ReadFrom timeout is set but reader doesn't implement SetReadDeadline")
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go
         0   158.38MB (flat, cum) 98.11% of Total
         .          .    100:}
         .          .    101:
         .          .    102:// WriteTo continuously write data Stream has received into the writer w.
         .          .    103:func (s *Stream) WriteTo(w io.Writer) (int64, error) {
         .          .    104:   // will keep writing until the underlying buffer is closed
         .   158.38MB    105:   n, err := s.recvBuf.WriteTo(w)
         .          .    106:   log.Tracef("%v read from stream %v with err %v", n, s.id, err)
         .          .    107:   if err == io.EOF {
         .          .    108:           return n, ErrBrokenStream
         .          .    109:   }
         .          .    110:   return n, nil
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go
         0   158.38MB (flat, cum) 98.11% of Total
         .          .     98:func (sb *streamBuffer) Read(buf []byte) (int, error) {
         .          .     99:   return sb.buf.Read(buf)
         .          .    100:}
         .          .    101:
         .          .    102:func (sb *streamBuffer) WriteTo(w io.Writer) (int64, error) {
         .   158.38MB    103:   return sb.buf.WriteTo(w)
         .          .    104:}
         .          .    105:
         .          .    106:func (sb *streamBuffer) Close() error {
         .          .    107:   sb.recvM.Lock()
         .          .    108:   defer sb.recvM.Unlock()
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go
   31.50MB   158.38MB (flat, cum) 98.11% of Total
         .          .     75:                           time.AfterFunc(d, p.rwCond.Broadcast)
         .          .     76:                   }
         .          .     77:           }
         .          .     78:           if p.wtTimeout != 0 {
         .          .     79:                   p.rDeadline = time.Now().Add(p.wtTimeout)
   31.50MB   158.38MB     80:                   time.AfterFunc(p.wtTimeout, p.rwCond.Broadcast)
         .          .     81:           }
         .          .     82:           if p.buf.Len() > 0 {
         .          .     83:                   written, er := p.buf.WriteTo(w)
         .          .     84:                   n += written
         .          .     85:                   if er != nil {
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go
  522.06kB   522.06kB (flat, cum)  0.32% of Total
         .          .    157:}
         .          .    158:
         .          .    159:// deplex function costantly reads from a TCP connection
         .          .    160:func (sb *switchboard) deplex(connId uint32, conn net.Conn) {
         .          .    161:   defer conn.Close()
  522.06kB   522.06kB    162:   buf := make([]byte, sb.session.ConnReceiveBufferSize)
         .          .    163:   for {
         .          .    164:           n, err := conn.Read(buf)
         .          .    165:           sb.valve.rxWait(n)
         .          .    166:           sb.valve.AddRx(int64(n))
         .          .    167:           if err != nil {
(pprof)
<!-- gh-comment-id:739108343 --> @notsure2 commented on GitHub (Dec 5, 2020): ``` (pprof) list multiplex Total: 161.43MB ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go 1.02MB 1.02MB (flat, cum) 0.63% of Total . . 172: . . 173:// ReadFrom continuously read data from r and send it off, until either r returns error or nothing has been read . . 174:// for readFromTimeout amount of time . . 175:func (s *Stream) ReadFrom(r io.Reader) (n int64, err error) { . . 176: if s.obfsBuf == nil { 1.02MB 1.02MB 177: s.obfsBuf = make([]byte, s.session.StreamSendBufferSize) . . 178: } . . 179: for { . . 180: if s.readFromTimeout != 0 { . . 181: if rder, ok := r.(net.Conn); !ok { . . 182: log.Warn("ReadFrom timeout is set but reader doesn't implement SetReadDeadline") ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go 0 158.38MB (flat, cum) 98.11% of Total . . 100:} . . 101: . . 102:// WriteTo continuously write data Stream has received into the writer w. . . 103:func (s *Stream) WriteTo(w io.Writer) (int64, error) { . . 104: // will keep writing until the underlying buffer is closed . 158.38MB 105: n, err := s.recvBuf.WriteTo(w) . . 106: log.Tracef("%v read from stream %v with err %v", n, s.id, err) . . 107: if err == io.EOF { . . 108: return n, ErrBrokenStream . . 109: } . . 110: return n, nil ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go 0 158.38MB (flat, cum) 98.11% of Total . . 98:func (sb *streamBuffer) Read(buf []byte) (int, error) { . . 99: return sb.buf.Read(buf) . . 100:} . . 101: . . 102:func (sb *streamBuffer) WriteTo(w io.Writer) (int64, error) { . 158.38MB 103: return sb.buf.WriteTo(w) . . 104:} . . 105: . . 106:func (sb *streamBuffer) Close() error { . . 107: sb.recvM.Lock() . . 108: defer sb.recvM.Unlock() ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go 31.50MB 158.38MB (flat, cum) 98.11% of Total . . 75: time.AfterFunc(d, p.rwCond.Broadcast) . . 76: } . . 77: } . . 78: if p.wtTimeout != 0 { . . 79: p.rDeadline = time.Now().Add(p.wtTimeout) 31.50MB 158.38MB 80: time.AfterFunc(p.wtTimeout, p.rwCond.Broadcast) . . 81: } . . 82: if p.buf.Len() > 0 { . . 83: written, er := p.buf.WriteTo(w) . . 84: n += written . . 85: if er != nil { ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go 522.06kB 522.06kB (flat, cum) 0.32% of Total . . 157:} . . 158: . . 159:// deplex function costantly reads from a TCP connection . . 160:func (sb *switchboard) deplex(connId uint32, conn net.Conn) { . . 161: defer conn.Close() 522.06kB 522.06kB 162: buf := make([]byte, sb.session.ConnReceiveBufferSize) . . 163: for { . . 164: n, err := conn.Read(buf) . . 165: sb.valve.rxWait(n) . . 166: sb.valve.AddRx(int64(n)) . . 167: if err != nil { (pprof) ```
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

I think I have a guess for the issue. I think that in case a connection is closed, Cloak does not clear the callback registered with timer.AfterFunc, so the Timer instances are getting accumulated in memory (memory leak). Eventually they timeout and get cleared but if a program opens and closes many connections in a short time, it will cause infinite memory growth until cloak is killed by the server.

<!-- gh-comment-id:739110867 --> @notsure2 commented on GitHub (Dec 5, 2020): I think I have a guess for the issue. I think that in case a connection is closed, Cloak does not clear the callback registered with timer.AfterFunc, so the Timer instances are getting accumulated in memory (memory leak). Eventually they timeout and get cleared but if a program opens and closes many connections in a short time, it will cause infinite memory growth until cloak is killed by the server.
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

Possible workaround, reduce StreamTimeout. But the correct solution is track the timers created per connection, don't create more than 1 timeout timer for each connection and when the connection is closed, cancel and destroy the timer.

<!-- gh-comment-id:739113774 --> @notsure2 commented on GitHub (Dec 5, 2020): Possible workaround, reduce StreamTimeout. But the correct solution is track the timers created per connection, don't create more than 1 timeout timer for each connection and when the connection is closed, cancel and destroy the timer.
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

Actually, maybe I'm misunderstanding the code, I'm not completely familiar with golang rwCond, the problem maybe simply only that the timeout was too long.

<!-- gh-comment-id:739116320 --> @notsure2 commented on GitHub (Dec 5, 2020): Actually, maybe I'm misunderstanding the code, I'm not completely familiar with golang rwCond, the problem maybe simply only that the timeout was too long.
Author
Owner

@cbeuw commented on GitHub (Dec 5, 2020):

So apparently timer.AfterFunc() creates a timer that does not get garbage collected until the timer fires: https://medium.com/@oboturov/golang-time-after-is-not-garbage-collected-4cbc94740082

Since it is in a hot loop, a lot of timers were created. They would get garbage collected eventually but this is still a memory leak. The new commit should fix it by only having one timer per connection

<!-- gh-comment-id:739242631 --> @cbeuw commented on GitHub (Dec 5, 2020): So apparently timer.AfterFunc() creates a timer that does not get garbage collected until the timer fires: https://medium.com/@oboturov/golang-time-after-is-not-garbage-collected-4cbc94740082 Since it is in a hot loop, a lot of timers were created. They would get garbage collected eventually but this is still a memory leak. The new commit should fix it by only having one timer per connection
Author
Owner

@cbeuw commented on GitHub (Dec 5, 2020):

Hmmm this might have broken things. Will fix

<!-- gh-comment-id:739244126 --> @cbeuw commented on GitHub (Dec 5, 2020): Hmmm this might have broken things. Will fix
Author
Owner

@cbeuw commented on GitHub (Dec 5, 2020):

nvm it's my setup. Should actually be fine

<!-- gh-comment-id:739249108 --> @cbeuw commented on GitHub (Dec 5, 2020): nvm it's my setup. Should actually be fine
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

@cbeuw this issue is still not fixed although it is reduced in severity. You still need to clean up the timer when the connection is prematurely closed from the sender side before the timeout elapsed, otherwise the timer will wait until the timeout elapsed in order to get garbage collected, even after the connection is closed by a long time.

<!-- gh-comment-id:739289023 --> @notsure2 commented on GitHub (Dec 5, 2020): @cbeuw this issue is still not fixed although it is reduced in severity. You still need to clean up the timer when the connection is prematurely closed from the sender side before the timeout elapsed, otherwise the timer will wait until the timeout elapsed in order to get garbage collected, even after the connection is closed by a long time.
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

Memory usage is still climbing. Now the pprof is showing different results:

File: ck-server
Type: inuse_space
Time: Dec 5, 2020 at 10:53pm (EET)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 33722.22kB, 95.64% of 35258.32kB total
Showing top 10 nodes out of 37
      flat  flat%   sum%        cum   cum%
12292.50kB 34.86% 34.86% 12292.50kB 34.86%  runtime.malg
 6144.56kB 17.43% 52.29%  6144.56kB 17.43%  github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1
 5657.96kB 16.05% 68.34%  5657.96kB 16.05%  bytes.makeSlice
 2610.33kB  7.40% 75.74%  9804.39kB 27.81%  github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex
 2088.26kB  5.92% 81.66%  2600.27kB  7.37%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom
 1322.42kB  3.75% 85.42%  1322.42kB  3.75%  github.com/cbeuw/Cloak/internal/server.(*State).registerRandom
 1038.06kB  2.94% 88.36%  1038.06kB  2.94%  github.com/cbeuw/Cloak/internal/common.NewTLSConn
 1032.02kB  2.93% 91.29%  1032.02kB  2.93%  github.com/cbeuw/Cloak/internal/multiplex.MakeSession
 1024.06kB  2.90% 94.19%  1024.06kB  2.90%  time.NewTimer
  512.05kB  1.45% 95.64%   512.05kB  1.45%  github.com/cbeuw/Cloak/internal/multiplex.(*Session).Accept

profile002

alloc_space mode:

Showing nodes accounting for 264.58MB, 81.01% of 326.60MB total
Dropped 48 nodes (cum <= 1.63MB)
Showing top 10 nodes out of 79
      flat  flat%   sum%        cum   cum%
   67.74MB 20.74% 20.74%    72.29MB 22.14%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom
   66.79MB 20.45% 41.19%    97.82MB 29.95%  github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex
   58.29MB 17.85% 59.04%    58.29MB 17.85%  github.com/cbeuw/Cloak/internal/common.NewTLSConn (inline)
   29.22MB  8.95% 67.98%    29.72MB  9.10%  github.com/cbeuw/Cloak/internal/multiplex.MakeSession
      12MB  3.68% 71.66%       12MB  3.68%  runtime.malg
    6.53MB  2.00% 73.66%     6.53MB  2.00%  bytes.makeSlice
    6.50MB  1.99% 75.65%     6.50MB  1.99%  github.com/cbeuw/Cloak/internal/server.parseExtensions
    6.01MB  1.84% 77.49%   125.82MB 38.52%  github.com/cbeuw/Cloak/internal/server.dispatchConnection
       6MB  1.84% 79.33%        6MB  1.84%  github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1
    5.50MB  1.68% 81.01%    13.50MB  4.13%  github.com/cbeuw/Cloak/internal/multiplex.NewStreamBufferedPipe

profile003

<!-- gh-comment-id:739414952 --> @notsure2 commented on GitHub (Dec 5, 2020): Memory usage is still climbing. Now the pprof is showing different results: ``` File: ck-server Type: inuse_space Time: Dec 5, 2020 at 10:53pm (EET) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 33722.22kB, 95.64% of 35258.32kB total Showing top 10 nodes out of 37 flat flat% sum% cum cum% 12292.50kB 34.86% 34.86% 12292.50kB 34.86% runtime.malg 6144.56kB 17.43% 52.29% 6144.56kB 17.43% github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1 5657.96kB 16.05% 68.34% 5657.96kB 16.05% bytes.makeSlice 2610.33kB 7.40% 75.74% 9804.39kB 27.81% github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex 2088.26kB 5.92% 81.66% 2600.27kB 7.37% github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom 1322.42kB 3.75% 85.42% 1322.42kB 3.75% github.com/cbeuw/Cloak/internal/server.(*State).registerRandom 1038.06kB 2.94% 88.36% 1038.06kB 2.94% github.com/cbeuw/Cloak/internal/common.NewTLSConn 1032.02kB 2.93% 91.29% 1032.02kB 2.93% github.com/cbeuw/Cloak/internal/multiplex.MakeSession 1024.06kB 2.90% 94.19% 1024.06kB 2.90% time.NewTimer 512.05kB 1.45% 95.64% 512.05kB 1.45% github.com/cbeuw/Cloak/internal/multiplex.(*Session).Accept ``` ![profile002](https://user-images.githubusercontent.com/35424927/101263307-df665580-374c-11eb-9ae7-7785909ce75d.png) alloc_space mode: ``` Showing nodes accounting for 264.58MB, 81.01% of 326.60MB total Dropped 48 nodes (cum <= 1.63MB) Showing top 10 nodes out of 79 flat flat% sum% cum cum% 67.74MB 20.74% 20.74% 72.29MB 22.14% github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom 66.79MB 20.45% 41.19% 97.82MB 29.95% github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex 58.29MB 17.85% 59.04% 58.29MB 17.85% github.com/cbeuw/Cloak/internal/common.NewTLSConn (inline) 29.22MB 8.95% 67.98% 29.72MB 9.10% github.com/cbeuw/Cloak/internal/multiplex.MakeSession 12MB 3.68% 71.66% 12MB 3.68% runtime.malg 6.53MB 2.00% 73.66% 6.53MB 2.00% bytes.makeSlice 6.50MB 1.99% 75.65% 6.50MB 1.99% github.com/cbeuw/Cloak/internal/server.parseExtensions 6.01MB 1.84% 77.49% 125.82MB 38.52% github.com/cbeuw/Cloak/internal/server.dispatchConnection 6MB 1.84% 79.33% 6MB 1.84% github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1 5.50MB 1.68% 81.01% 13.50MB 4.13% github.com/cbeuw/Cloak/internal/multiplex.NewStreamBufferedPipe ``` ![profile003](https://user-images.githubusercontent.com/35424927/101263747-02910500-374d-11eb-882a-c444400b2994.png)
Author
Owner

@cbeuw commented on GitHub (Dec 5, 2020):

Thanks for your effort! Could you please check how many goroutines are running and if that figure ever goes down when things become quiet? I tried the two channel approach earlier and the main issue was that there are hundreds of goroutines stuck alive, somehow never selected the closing channel.

Prior to github.com/cbeuw/Cloak@4baca256f7, there wasn't any goroutine issues raising from the use of AfterFunc().

<!-- gh-comment-id:739416502 --> @cbeuw commented on GitHub (Dec 5, 2020): Thanks for your effort! Could you please check how many goroutines are running and if that figure ever goes down when things become quiet? I tried the two channel approach earlier and the main issue was that there are hundreds of goroutines stuck alive, somehow never selected the closing channel. Prior to https://github.com/cbeuw/Cloak/commit/4baca256f7d9a4b3786208e2ddf4f013fd06a5d6, there wasn't any goroutine issues raising from the use of AfterFunc().
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

goroutine profile: total 60913
60333 @ 0x437050 0x446eb3 0x789873 0x466241
#	0x789872	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1+0xa2	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:159

100 @ 0x437050 0x40528d 0x405055 0x787bbd 0x786f50 0x783d3c 0x785267 0x785248 0x78435c 0x788900 0x466241
#	0x787bbc	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).Close+0xac	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:130
#	0x786f4f	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).Close+0x6f		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:110
#	0x783d3b	github.com/cbeuw/Cloak/internal/multiplex.(*Session).closeStream+0x11b		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:171
#	0x785266	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).passiveClose+0x96		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:214
#	0x785247	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).recvFrame+0x77		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:77
#	0x78435b	github.com/cbeuw/Cloak/internal/multiplex.(*Session).recvDataFromRemote+0x18b	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:234
#	0x7888ff	github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex+0x18f		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go:175

99 @ 0x437050 0x4479f0 0x4479db 0x447757 0x47ee0c 0x47ecf7 0x787d68 0x787049 0x791084 0x791045 0x790523 0x466241
#	0x447756	sync.runtime_SemacquireMutex+0x46							/usr/lib/go-1.14/src/runtime/sema.go:71
#	0x47ee0b	sync.(*Mutex).lockSlow+0xfb								/usr/lib/go-1.14/src/sync/mutex.go:138
#	0x47ecf6	sync.(*Mutex).Lock+0x46									/usr/lib/go-1.14/src/sync/mutex.go:81
#	0x787d67	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).SetWriteToTimeout+0x47	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:145
#	0x787048	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).SetWriteToTimeout+0x38	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:114
#	0x791083	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).SetWriteToTimeout+0x673		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:228
#	0x791044	github.com/cbeuw/Cloak/internal/server.serveSession+0x634				/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:279
#	0x790522	github.com/cbeuw/Cloak/internal/server.dispatchConnection+0x1282			/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:248

75 @ 0x437050 0x45389a 0x784f3f 0x466241
#	0x453899	time.Sleep+0xb9								/usr/lib/go-1.14/src/runtime/time.go:188
#	0x784f3e	github.com/cbeuw/Cloak/internal/multiplex.(*Session).timeoutAfter+0x2e	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:338

62 @ 0x437050 0x405ea7 0x405b6b 0x787e8b 0x787776 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241
#	0x787e8a	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter+0xaa	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:155
#	0x787775	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x225		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:85
#	0x786ea2	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42			/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103
#	0x785612	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62			/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105
#	0x7241cf	github.com/cbeuw/Cloak/internal/common.Copy+0x42f					/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46
#	0x795d6c	github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c				/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281

62 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x785f82 0x724100 0x795e4d 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54					/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44					/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c542a	internal/poll.(*pollDesc).waitRead+0x19a				/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c540c	internal/poll.(*FD).Read+0x17c						/usr/lib/go-1.14/src/internal/poll/fd_unix.go:169
#	0x515d6e	net.(*netFD).Read+0x4e							/usr/lib/go-1.14/src/net/fd_unix.go:202
#	0x52876d	net.(*conn).Read+0x8d							/usr/lib/go-1.14/src/net/net.go:184
#	0x785f81	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom+0xe1	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:187
#	0x7240ff	github.com/cbeuw/Cloak/internal/common.Copy+0x35f			/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:50
#	0x795e4c	github.com/cbeuw/Cloak/internal/server.serveSession.func2+0x4c		/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:287

59 @ 0x437050 0x405ea7 0x405b6b 0x783abb 0x790a53 0x790523 0x466241
#	0x783aba	github.com/cbeuw/Cloak/internal/multiplex.(*Session).Accept+0x5a	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:159
#	0x790a52	github.com/cbeuw/Cloak/internal/server.serveSession+0x42		/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:254
#	0x790522	github.com/cbeuw/Cloak/internal/server.dispatchConnection+0x1282	/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:248

58 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x4a68a7 0x724cf4 0x724c91 0x788856 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54					/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44					/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c542a	internal/poll.(*pollDesc).waitRead+0x19a				/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c540c	internal/poll.(*FD).Read+0x17c						/usr/lib/go-1.14/src/internal/poll/fd_unix.go:169
#	0x515d6e	net.(*netFD).Read+0x4e							/usr/lib/go-1.14/src/net/fd_unix.go:202
#	0x52876d	net.(*conn).Read+0x8d							/usr/lib/go-1.14/src/net/net.go:184
#	0x4a68a6	io.ReadAtLeast+0x86							/usr/lib/go-1.14/src/io/io.go:310
#	0x724cf3	io.ReadFull+0x93							/usr/lib/go-1.14/src/io/io.go:329
#	0x724c90	github.com/cbeuw/Cloak/internal/common.(*TLSConn).Read+0x30		/d/Users/User/Work/GitHub/Cloak/internal/common/tls.go:82
#	0x788855	github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex+0xe5	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go:164

58 @ 0x437050 0x4488e8 0x4488be 0x47cfcd 0x78766b 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241
#	0x4488bd	sync.runtime_notifyListWait+0xcd						/usr/lib/go-1.14/src/runtime/sema.go:513
#	0x47cfcc	sync.(*Cond).Wait+0x9c								/usr/lib/go-1.14/src/sync/cond.go:56
#	0x78766a	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x11a	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:96
#	0x786ea2	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103
#	0x785612	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105
#	0x7241cf	github.com/cbeuw/Cloak/internal/common.Copy+0x42f				/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46
#	0x795d6c	github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c			/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281

1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x6dc338 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54		/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44		/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c542a	internal/poll.(*pollDesc).waitRead+0x19a	/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c540c	internal/poll.(*FD).Read+0x17c			/usr/lib/go-1.14/src/internal/poll/fd_unix.go:169
#	0x515d6e	net.(*netFD).Read+0x4e				/usr/lib/go-1.14/src/net/fd_unix.go:202
#	0x52876d	net.(*conn).Read+0x8d				/usr/lib/go-1.14/src/net/net.go:184
#	0x6dc337	net/http.(*connReader).backgroundRead+0x57	/usr/lib/go-1.14/src/net/http/server.go:678

1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c6dd4 0x4c6db6 0x516622 0x5327b2 0x531544 0x6e6a8d 0x6e67d7 0x7ea486 0x7ea432 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54		/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44		/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c6dd3	internal/poll.(*pollDesc).waitRead+0x1d3	/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c6db5	internal/poll.(*FD).Accept+0x1b5		/usr/lib/go-1.14/src/internal/poll/fd_unix.go:384
#	0x516621	net.(*netFD).accept+0x41			/usr/lib/go-1.14/src/net/fd_unix.go:238
#	0x5327b1	net.(*TCPListener).accept+0x31			/usr/lib/go-1.14/src/net/tcpsock_posix.go:139
#	0x531543	net.(*TCPListener).Accept+0x63			/usr/lib/go-1.14/src/net/tcpsock.go:261
#	0x6e6a8c	net/http.(*Server).Serve+0x25c			/usr/lib/go-1.14/src/net/http/server.go:2901
#	0x6e67d6	net/http.(*Server).ListenAndServe+0xb6		/usr/lib/go-1.14/src/net/http/server.go:2830
#	0x7ea485	net/http.ListenAndServe+0x75			/usr/lib/go-1.14/src/net/http/server.go:3086
#	0x7ea431	main.main.func1+0x21				/d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:112

1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c6dd4 0x4c6db6 0x516622 0x5327b2 0x531544 0x78e37f 0x7ea693 0x7e95e9 0x436c72 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54			/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44			/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c6dd3	internal/poll.(*pollDesc).waitRead+0x1d3		/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c6db5	internal/poll.(*FD).Accept+0x1b5			/usr/lib/go-1.14/src/internal/poll/fd_unix.go:384
#	0x516621	net.(*netFD).accept+0x41				/usr/lib/go-1.14/src/net/fd_unix.go:238
#	0x5327b1	net.(*TCPListener).accept+0x31				/usr/lib/go-1.14/src/net/tcpsock_posix.go:139
#	0x531543	net.(*TCPListener).Accept+0x63				/usr/lib/go-1.14/src/net/tcpsock.go:261
#	0x78e37e	github.com/cbeuw/Cloak/internal/server.Serve+0x6e	/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:29
#	0x7ea692	main.main.func2+0x192					/d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:170
#	0x7e95e8	main.main+0x428						/d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:178
#	0x436c71	runtime.main+0x211					/usr/lib/go-1.14/src/runtime/proc.go:203

1 @ 0x437050 0x4479f0 0x4479db 0x447757 0x47ee0c 0x47ecf7 0x7875af 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241
#	0x447756	sync.runtime_SemacquireMutex+0x46						/usr/lib/go-1.14/src/runtime/sema.go:71
#	0x47ee0b	sync.(*Mutex).lockSlow+0xfb							/usr/lib/go-1.14/src/sync/mutex.go:138
#	0x47ecf6	sync.(*Mutex).Lock+0x46								/usr/lib/go-1.14/src/sync/mutex.go:81
#	0x7875ae	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x5e	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:64
#	0x786ea2	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103
#	0x785612	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105
#	0x7241cf	github.com/cbeuw/Cloak/internal/common.Copy+0x42f				/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46
#	0x795d6c	github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c			/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281

1 @ 0x437050 0x45389a 0x7927d1 0x466241
#	0x453899	time.Sleep+0xb9								/usr/lib/go-1.14/src/runtime/time.go:188
#	0x7927d0	github.com/cbeuw/Cloak/internal/server.(*State).UsedRandomCleaner+0x170	/d/Users/User/Work/GitHub/Cloak/internal/server/state.go:213

1 @ 0x437050 0x45389a 0x79449f 0x466241
#	0x453899	time.Sleep+0xb9									/usr/lib/go-1.14/src/runtime/time.go:188
#	0x79449e	github.com/cbeuw/Cloak/internal/server.(*userPanel).regularQueueUpload+0x2e	/d/Users/User/Work/GitHub/Cloak/internal/server/userpanel.go:210

1 @ 0x7dd625 0x7dd440 0x7da1da 0x7e764a 0x7e80a5 0x6e3354 0x6e5195 0x6e66e3 0x6e215c 0x466241
#	0x7dd624	runtime/pprof.writeRuntimeProfile+0x94	/usr/lib/go-1.14/src/runtime/pprof/pprof.go:694
#	0x7dd43f	runtime/pprof.writeGoroutine+0x9f	/usr/lib/go-1.14/src/runtime/pprof/pprof.go:656
#	0x7da1d9	runtime/pprof.(*Profile).WriteTo+0x3d9	/usr/lib/go-1.14/src/runtime/pprof/pprof.go:329
#	0x7e7649	net/http/pprof.handler.ServeHTTP+0x339	/usr/lib/go-1.14/src/net/http/pprof/pprof.go:248
#	0x7e80a4	net/http/pprof.Index+0x734		/usr/lib/go-1.14/src/net/http/pprof/pprof.go:271
#	0x6e3353	net/http.HandlerFunc.ServeHTTP+0x43	/usr/lib/go-1.14/src/net/http/server.go:2012
#	0x6e5194	net/http.(*ServeMux).ServeHTTP+0x1a4	/usr/lib/go-1.14/src/net/http/server.go:2387
#	0x6e66e2	net/http.serverHandler.ServeHTTP+0xa2	/usr/lib/go-1.14/src/net/http/server.go:2807
#	0x6e215b	net/http.(*conn).serve+0x86b		/usr/lib/go-1.14/src/net/http/server.go:1895

You're right I'm getting the same issue.

<!-- gh-comment-id:739416837 --> @notsure2 commented on GitHub (Dec 5, 2020): ``` goroutine profile: total 60913 60333 @ 0x437050 0x446eb3 0x789873 0x466241 # 0x789872 github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1+0xa2 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:159 100 @ 0x437050 0x40528d 0x405055 0x787bbd 0x786f50 0x783d3c 0x785267 0x785248 0x78435c 0x788900 0x466241 # 0x787bbc github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).Close+0xac /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:130 # 0x786f4f github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).Close+0x6f /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:110 # 0x783d3b github.com/cbeuw/Cloak/internal/multiplex.(*Session).closeStream+0x11b /d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:171 # 0x785266 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).passiveClose+0x96 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:214 # 0x785247 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).recvFrame+0x77 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:77 # 0x78435b github.com/cbeuw/Cloak/internal/multiplex.(*Session).recvDataFromRemote+0x18b /d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:234 # 0x7888ff github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex+0x18f /d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go:175 99 @ 0x437050 0x4479f0 0x4479db 0x447757 0x47ee0c 0x47ecf7 0x787d68 0x787049 0x791084 0x791045 0x790523 0x466241 # 0x447756 sync.runtime_SemacquireMutex+0x46 /usr/lib/go-1.14/src/runtime/sema.go:71 # 0x47ee0b sync.(*Mutex).lockSlow+0xfb /usr/lib/go-1.14/src/sync/mutex.go:138 # 0x47ecf6 sync.(*Mutex).Lock+0x46 /usr/lib/go-1.14/src/sync/mutex.go:81 # 0x787d67 github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).SetWriteToTimeout+0x47 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:145 # 0x787048 github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).SetWriteToTimeout+0x38 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:114 # 0x791083 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).SetWriteToTimeout+0x673 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:228 # 0x791044 github.com/cbeuw/Cloak/internal/server.serveSession+0x634 /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:279 # 0x790522 github.com/cbeuw/Cloak/internal/server.dispatchConnection+0x1282 /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:248 75 @ 0x437050 0x45389a 0x784f3f 0x466241 # 0x453899 time.Sleep+0xb9 /usr/lib/go-1.14/src/runtime/time.go:188 # 0x784f3e github.com/cbeuw/Cloak/internal/multiplex.(*Session).timeoutAfter+0x2e /d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:338 62 @ 0x437050 0x405ea7 0x405b6b 0x787e8b 0x787776 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241 # 0x787e8a github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter+0xaa /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:155 # 0x787775 github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x225 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:85 # 0x786ea2 github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103 # 0x785612 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105 # 0x7241cf github.com/cbeuw/Cloak/internal/common.Copy+0x42f /d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46 # 0x795d6c github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281 62 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x785f82 0x724100 0x795e4d 0x466241 # 0x42f544 internal/poll.runtime_pollWait+0x54 /usr/lib/go-1.14/src/runtime/netpoll.go:203 # 0x4c4594 internal/poll.(*pollDesc).wait+0x44 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87 # 0x4c542a internal/poll.(*pollDesc).waitRead+0x19a /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92 # 0x4c540c internal/poll.(*FD).Read+0x17c /usr/lib/go-1.14/src/internal/poll/fd_unix.go:169 # 0x515d6e net.(*netFD).Read+0x4e /usr/lib/go-1.14/src/net/fd_unix.go:202 # 0x52876d net.(*conn).Read+0x8d /usr/lib/go-1.14/src/net/net.go:184 # 0x785f81 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom+0xe1 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:187 # 0x7240ff github.com/cbeuw/Cloak/internal/common.Copy+0x35f /d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:50 # 0x795e4c github.com/cbeuw/Cloak/internal/server.serveSession.func2+0x4c /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:287 59 @ 0x437050 0x405ea7 0x405b6b 0x783abb 0x790a53 0x790523 0x466241 # 0x783aba github.com/cbeuw/Cloak/internal/multiplex.(*Session).Accept+0x5a /d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:159 # 0x790a52 github.com/cbeuw/Cloak/internal/server.serveSession+0x42 /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:254 # 0x790522 github.com/cbeuw/Cloak/internal/server.dispatchConnection+0x1282 /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:248 58 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x4a68a7 0x724cf4 0x724c91 0x788856 0x466241 # 0x42f544 internal/poll.runtime_pollWait+0x54 /usr/lib/go-1.14/src/runtime/netpoll.go:203 # 0x4c4594 internal/poll.(*pollDesc).wait+0x44 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87 # 0x4c542a internal/poll.(*pollDesc).waitRead+0x19a /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92 # 0x4c540c internal/poll.(*FD).Read+0x17c /usr/lib/go-1.14/src/internal/poll/fd_unix.go:169 # 0x515d6e net.(*netFD).Read+0x4e /usr/lib/go-1.14/src/net/fd_unix.go:202 # 0x52876d net.(*conn).Read+0x8d /usr/lib/go-1.14/src/net/net.go:184 # 0x4a68a6 io.ReadAtLeast+0x86 /usr/lib/go-1.14/src/io/io.go:310 # 0x724cf3 io.ReadFull+0x93 /usr/lib/go-1.14/src/io/io.go:329 # 0x724c90 github.com/cbeuw/Cloak/internal/common.(*TLSConn).Read+0x30 /d/Users/User/Work/GitHub/Cloak/internal/common/tls.go:82 # 0x788855 github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex+0xe5 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go:164 58 @ 0x437050 0x4488e8 0x4488be 0x47cfcd 0x78766b 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241 # 0x4488bd sync.runtime_notifyListWait+0xcd /usr/lib/go-1.14/src/runtime/sema.go:513 # 0x47cfcc sync.(*Cond).Wait+0x9c /usr/lib/go-1.14/src/sync/cond.go:56 # 0x78766a github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x11a /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:96 # 0x786ea2 github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103 # 0x785612 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105 # 0x7241cf github.com/cbeuw/Cloak/internal/common.Copy+0x42f /d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46 # 0x795d6c github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281 1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x6dc338 0x466241 # 0x42f544 internal/poll.runtime_pollWait+0x54 /usr/lib/go-1.14/src/runtime/netpoll.go:203 # 0x4c4594 internal/poll.(*pollDesc).wait+0x44 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87 # 0x4c542a internal/poll.(*pollDesc).waitRead+0x19a /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92 # 0x4c540c internal/poll.(*FD).Read+0x17c /usr/lib/go-1.14/src/internal/poll/fd_unix.go:169 # 0x515d6e net.(*netFD).Read+0x4e /usr/lib/go-1.14/src/net/fd_unix.go:202 # 0x52876d net.(*conn).Read+0x8d /usr/lib/go-1.14/src/net/net.go:184 # 0x6dc337 net/http.(*connReader).backgroundRead+0x57 /usr/lib/go-1.14/src/net/http/server.go:678 1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c6dd4 0x4c6db6 0x516622 0x5327b2 0x531544 0x6e6a8d 0x6e67d7 0x7ea486 0x7ea432 0x466241 # 0x42f544 internal/poll.runtime_pollWait+0x54 /usr/lib/go-1.14/src/runtime/netpoll.go:203 # 0x4c4594 internal/poll.(*pollDesc).wait+0x44 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87 # 0x4c6dd3 internal/poll.(*pollDesc).waitRead+0x1d3 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92 # 0x4c6db5 internal/poll.(*FD).Accept+0x1b5 /usr/lib/go-1.14/src/internal/poll/fd_unix.go:384 # 0x516621 net.(*netFD).accept+0x41 /usr/lib/go-1.14/src/net/fd_unix.go:238 # 0x5327b1 net.(*TCPListener).accept+0x31 /usr/lib/go-1.14/src/net/tcpsock_posix.go:139 # 0x531543 net.(*TCPListener).Accept+0x63 /usr/lib/go-1.14/src/net/tcpsock.go:261 # 0x6e6a8c net/http.(*Server).Serve+0x25c /usr/lib/go-1.14/src/net/http/server.go:2901 # 0x6e67d6 net/http.(*Server).ListenAndServe+0xb6 /usr/lib/go-1.14/src/net/http/server.go:2830 # 0x7ea485 net/http.ListenAndServe+0x75 /usr/lib/go-1.14/src/net/http/server.go:3086 # 0x7ea431 main.main.func1+0x21 /d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:112 1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c6dd4 0x4c6db6 0x516622 0x5327b2 0x531544 0x78e37f 0x7ea693 0x7e95e9 0x436c72 0x466241 # 0x42f544 internal/poll.runtime_pollWait+0x54 /usr/lib/go-1.14/src/runtime/netpoll.go:203 # 0x4c4594 internal/poll.(*pollDesc).wait+0x44 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87 # 0x4c6dd3 internal/poll.(*pollDesc).waitRead+0x1d3 /usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92 # 0x4c6db5 internal/poll.(*FD).Accept+0x1b5 /usr/lib/go-1.14/src/internal/poll/fd_unix.go:384 # 0x516621 net.(*netFD).accept+0x41 /usr/lib/go-1.14/src/net/fd_unix.go:238 # 0x5327b1 net.(*TCPListener).accept+0x31 /usr/lib/go-1.14/src/net/tcpsock_posix.go:139 # 0x531543 net.(*TCPListener).Accept+0x63 /usr/lib/go-1.14/src/net/tcpsock.go:261 # 0x78e37e github.com/cbeuw/Cloak/internal/server.Serve+0x6e /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:29 # 0x7ea692 main.main.func2+0x192 /d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:170 # 0x7e95e8 main.main+0x428 /d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:178 # 0x436c71 runtime.main+0x211 /usr/lib/go-1.14/src/runtime/proc.go:203 1 @ 0x437050 0x4479f0 0x4479db 0x447757 0x47ee0c 0x47ecf7 0x7875af 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241 # 0x447756 sync.runtime_SemacquireMutex+0x46 /usr/lib/go-1.14/src/runtime/sema.go:71 # 0x47ee0b sync.(*Mutex).lockSlow+0xfb /usr/lib/go-1.14/src/sync/mutex.go:138 # 0x47ecf6 sync.(*Mutex).Lock+0x46 /usr/lib/go-1.14/src/sync/mutex.go:81 # 0x7875ae github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x5e /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:64 # 0x786ea2 github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103 # 0x785612 github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62 /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105 # 0x7241cf github.com/cbeuw/Cloak/internal/common.Copy+0x42f /d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46 # 0x795d6c github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c /d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281 1 @ 0x437050 0x45389a 0x7927d1 0x466241 # 0x453899 time.Sleep+0xb9 /usr/lib/go-1.14/src/runtime/time.go:188 # 0x7927d0 github.com/cbeuw/Cloak/internal/server.(*State).UsedRandomCleaner+0x170 /d/Users/User/Work/GitHub/Cloak/internal/server/state.go:213 1 @ 0x437050 0x45389a 0x79449f 0x466241 # 0x453899 time.Sleep+0xb9 /usr/lib/go-1.14/src/runtime/time.go:188 # 0x79449e github.com/cbeuw/Cloak/internal/server.(*userPanel).regularQueueUpload+0x2e /d/Users/User/Work/GitHub/Cloak/internal/server/userpanel.go:210 1 @ 0x7dd625 0x7dd440 0x7da1da 0x7e764a 0x7e80a5 0x6e3354 0x6e5195 0x6e66e3 0x6e215c 0x466241 # 0x7dd624 runtime/pprof.writeRuntimeProfile+0x94 /usr/lib/go-1.14/src/runtime/pprof/pprof.go:694 # 0x7dd43f runtime/pprof.writeGoroutine+0x9f /usr/lib/go-1.14/src/runtime/pprof/pprof.go:656 # 0x7da1d9 runtime/pprof.(*Profile).WriteTo+0x3d9 /usr/lib/go-1.14/src/runtime/pprof/pprof.go:329 # 0x7e7649 net/http/pprof.handler.ServeHTTP+0x339 /usr/lib/go-1.14/src/net/http/pprof/pprof.go:248 # 0x7e80a4 net/http/pprof.Index+0x734 /usr/lib/go-1.14/src/net/http/pprof/pprof.go:271 # 0x6e3353 net/http.HandlerFunc.ServeHTTP+0x43 /usr/lib/go-1.14/src/net/http/server.go:2012 # 0x6e5194 net/http.(*ServeMux).ServeHTTP+0x1a4 /usr/lib/go-1.14/src/net/http/server.go:2387 # 0x6e66e2 net/http.serverHandler.ServeHTTP+0xa2 /usr/lib/go-1.14/src/net/http/server.go:2807 # 0x6e215b net/http.(*conn).serve+0x86b /usr/lib/go-1.14/src/net/http/server.go:1895 ``` You're right I'm getting the same issue.
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

maybe there's a case where close is not getting called, or broadcastAfter is getting called after close is called....

<!-- gh-comment-id:739418594 --> @notsure2 commented on GitHub (Dec 5, 2020): maybe there's a case where close is not getting called, or broadcastAfter is getting called after close is called....
Author
Owner

@cbeuw commented on GitHub (Dec 5, 2020):

Because a memory leak is better than an excessive goroutine leak under normal load, I've reverted github.com/cbeuw/Cloak@4baca256f7.

Additionally I couldn't reproduce the memory leak without a stress test. I'll experiment with a stress test and see how serious it is and try to find a better solution

<!-- gh-comment-id:739419713 --> @cbeuw commented on GitHub (Dec 5, 2020): Because a memory leak is better than an excessive goroutine leak under normal load, I've reverted https://github.com/cbeuw/Cloak/commit/4baca256f7d9a4b3786208e2ddf4f013fd06a5d6. Additionally I couldn't reproduce the memory leak without a stress test. I'll experiment with a stress test and see how serious it is and try to find a better solution
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

The thing is, it shouldn't have leaked unless broadcastAfter is being called after Close (or both are called together). I'll add some logging messages to investigate this. I think it's possible to solve without reverting.

<!-- gh-comment-id:739421391 --> @notsure2 commented on GitHub (Dec 5, 2020): The thing is, it shouldn't have leaked unless broadcastAfter is being called after Close (or both are called together). I'll add some logging messages to investigate this. I think it's possible to solve without reverting.
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

@cbeuw to reproduce this, just setup shadowsocks + cloak. then setup torrent client to use shadowsocks, then download a torrent with lot of seeds with torrent client set to use ~100 connections per torrent. Set Cloak NumConn=0

<!-- gh-comment-id:739423172 --> @notsure2 commented on GitHub (Dec 5, 2020): @cbeuw to reproduce this, just setup shadowsocks + cloak. then setup torrent client to use shadowsocks, then download a torrent with lot of seeds with torrent client set to use ~100 connections per torrent. Set Cloak NumConn=0
Author
Owner

@notsure2 commented on GitHub (Dec 5, 2020):

@cbeuw I think there's something weird with this part: github.com/cbeuw/Cloak@c0040f20c3/internal/multiplex/streamBufferedPipe.go (L78-L93)

In case wTimeout is not 0 (ie: StreamTimeout is set in the config), it schedules a next broadcast (here's an allocated timer).

However, in the very next line, if the buffer is NOT empty, it writes its contents and sends a broadcast by itself without waiting, making the previously scheduled timer callback redundant.

Shouldn't this if block be moved inside the next else block ? You only need to schedule a broadcast if you are then going to wait. In fact, this is going to create a new timer every loop whether there is data in the buffer or not.

<!-- gh-comment-id:739429248 --> @notsure2 commented on GitHub (Dec 5, 2020): @cbeuw I think there's something weird with this part: https://github.com/cbeuw/Cloak/blob/c0040f20c3353b2aee95386960558f977f127e7c/internal/multiplex/streamBufferedPipe.go#L78-L93 In case wTimeout is not 0 (ie: StreamTimeout is set in the config), it schedules a next broadcast (here's an allocated timer). However, in the very next line, if the buffer is NOT empty, it writes its contents and sends a broadcast by itself without waiting, making the previously scheduled timer callback redundant. Shouldn't this if block be moved inside the next else block ? You only need to schedule a broadcast if you are then going to wait. In fact, this is going to create a new timer every loop whether there is data in the buffer or not.
Author
Owner

@cbeuw commented on GitHub (Dec 6, 2020):

I think you are right. We should only schedule a broadcast via AfterFunc only if we know we will wait for an indeterminate amount of time. In fact, this should apply to the bit above checking if rDeadline is set as well

<!-- gh-comment-id:739434593 --> @cbeuw commented on GitHub (Dec 6, 2020): I think you are right. We should only schedule a broadcast via AfterFunc only if we know we will wait for an indeterminate amount of time. In fact, this should apply to the bit above checking if `rDeadline` is set as well
Sign in to join this conversation.
No labels
pull-request
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/Cloak#113
No description provided.