smux icon indicating copy to clipboard operation
smux copied to clipboard
Published 3 days ago • verified publisher icon xtaci

add token into stream v2

Open cs8425 opened this issue 6 years ago • 43 comments

接續 #19 重新提交PR TestSlowReadBlocking()這個test可以復現 #18

用net.Pipe()測試過程中有踩到類似 #37 的問題 發送cmdACK跟cmdFUL會卡住(已透過另外開個控制包專用channel解決) 有空再試試可否透過test復現

另外改變了keepalive的實作方式 最明顯的改變是KeepAliveInterval可以大於KeepAliveTimeout 送一個包會等KeepAliveTimeout的長度再去確認無回應才斷線 如果回應在timeout之前收到 則會重設timeout跟下次發包的時機 換句話說 ping的時間點不再是固定的KeepAliveInterval 而是KeepAliveInterval + RTT

recvLoop()的部份 收到不明的cmd ID不再強制斷線 可以直接於SMUX這層加入雜訊且不干擾stream token的估測 或者提高之後引入新ID的相容性

cs8425 avatar Mar 09 '19 11:03 cs8425

Codecov Report

Merging #47 into master will increase coverage by 2.33%. The diff coverage is 91.62%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master      #47      +/-   ##
==========================================
+ Coverage    87.5%   89.83%   +2.33%     
==========================================
  Files           4        4              
  Lines         392      531     +139     
==========================================
+ Hits          343      477     +134     
- Misses         44       49       +5     
  Partials        5        5
Impacted Files Coverage Δ
frame.go 76.92% <ø> (ø) :arrow_up:
mux.go 100% <100%> (ø) :arrow_up:
session.go 88.04% <88.13%> (-1.12%) :arrow_down:
stream.go 91.38% <96.05%> (+7.82%) :arrow_up:

Continue to review full report at Codecov.

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

codecov-io avatar Mar 09 '19 11:03 codecov-io

给力给力！

jannson avatar Mar 09 '19 13:03 jannson

https://github.com/cs8425/smux/blob/move-token-to-stream2/stream.go#L252 pushBytes 干的活有点多，建议先 s.streamLock.Unlock() 再 pushBytes https://github.com/cs8425/smux/blob/move-token-to-stream2/session.go#L282

jannson avatar Mar 09 '19 13:03 jannson

....test裡面的setupServer()怎老是failed= = pushBytes()那邊改了 不確定會不會跟streamClosed()沖到 不過OpenStream()應該會有提升

cs8425 avatar Mar 09 '19 16:03 cs8425 

	_, err := s.sess.writeFrameInternal(newFrame(cmdFIN, s.id), time.After(s.sess.config.KeepAliveTimeout))
	s.sess.streamClosed(s.id)

这两行为何要调换过来，不懂。但是调换过来，则就能测试通过了。能说明下原因么？

我现在测试都通过了，--race 也能通过。但是这两行一换过来就不通过。不好理解。

jannson avatar Mar 09 '19 16:03 jannson 

	_, err := s.sess.writeFrameInternal(newFrame(cmdFIN, s.id), time.After(s.sess.config.KeepAliveTimeout))
	s.sess.streamClosed(s.id)

这两行为何要调换过来，不懂。但是调换过来，则就能测试通过了。能说明下原因么？

我现在测试都通过了，--race 也能通过。但是这两行一换过来就不通过。不好理解。

只是剛好執行時間點的問題(writeFrame的部份) 並不是真正的問題原因.. 你試試看加上這個: https://github.com/cs8425/smux/blob/move-token-to-stream2/stream.go#L98-L100 還有把s.empflag改回用Mutex 用script放下去連續跑test到現在還沒失敗過

對了 有需要實作HalfClose的功能嗎? 提供這兩個: func (c *TCPConn) CloseRead() error func (c *TCPConn) CloseWrite() error

cs8425 avatar Mar 09 '19 18:03 cs8425

用 C 写代码用到过 HalfClose，但用 golang 没有这两个接口的需求，并且 net.Conn 里面也没有这两个接口，所以觉得不必要实现，让代码复杂了。 还有疑问点 1：https://github.com/cs8425/smux/blob/move-token-to-stream2/stream.go#L91 这个条件会有机会触发么？如果 n = 0，肯定 rem = 0 2. https://github.com/cs8425/smux/blob/move-token-to-stream2/stream.go#L183 如果这里超时了，那么 stream 对应的对方，在没有SetDeadline 的情况下，是无法感知 stream 应该被关闭的，可能就留下很多僵尸 stream 3. https://github.com/cs8425/smux/blob/move-token-to-stream2/stream.go#L99 在带宽不够大的情况下（应用读数据比整个带宽还大），一般都能 Read 到 n = 0 的，这样 sendResumeForce 频率会高吧？

jannson avatar Mar 10 '19 02:03 jannson

  1. 那個是之前為了處理len(b)的作法...忘了刪掉 很久之前看過一篇文章 說可以先Read()一個長度0的slice 會block住直到對面有資料傳來才會return 此時再分配slice即可省記憶體 但是我昨天找了找沒看到來源....用test實測也不符合

  2. 其實超時造成的deadlock有分幾種 一種是s.writes<-排不到卡住(太多併發), 但是sendLoop()並沒有卡 一種是s.conn.Write()寫到一半直接卡住無法return (sendLoop()卡死) 造成writeFrame*()的s.writes<-卡住 如果又剛好是recvLoop()調用writeFrame*()的話會完全卡死 (兩邊都是recvLoop()調用writeFrame*(), 且剛好卡在s.conn.Write()) 如果是keepalive()調用則卡死keepalive(), 造成timeout失效(這個應該解決了) 第2種才是測試時小機率完全卡死的原因 這麼說來在s.conn.Write()加上deadline才是正解?

  3. 因為之前是用atomic還是有小機率在這地方deadlock 改回Mutex之後還沒試過用s.sendResume()可否解決

對了 剛剛看到有說明說併發Write()操作不會導致一次Write寫入的資料被打亂順序 照目前的實作好像無法保證? 資料長度夠長要切割, 會同時進入這段

	frames := s.split(b, cmdPSH, s.id)
	sent := 0
	for k := range frames {
		req := writeRequest{
			frame:  frames[k],
			result: make(chan writeResult, 1),
		}

		select {
		case s.sess.writes <- req:
		case <-s.die:
			return sent, ErrBrokenPipe
		case <-deadline:
			return sent, errTimeout
		}
		....
	}

還有如果Write()之後馬上Close()有沒有機會cmdFIN比cmdPSH還早送達? 造成資料遺失 s.sess.writes是unbuffered channel, 沒有說一定會FIFO 只有說buffered channel會是FIFO

cs8425 avatar Mar 10 '19 06:03 cs8425

确实有加 lock 的必要，免得多个 goroutine 同时 Write 的时候，顺序会乱。

jannson avatar Mar 10 '19 09:03 jannson

...我懷疑net.Pipe()是不是有bug= = 這次test沒過的是純pipe+併發寫入 可是我這邊電腦掛著跑也沒還沒遇到 然後保證每個stream cmdSYN >> cmdPSH >> cmdFIN的封包順序 還在思考要怎改

cs8425 avatar Mar 10 '19 11:03 cs8425

if n == 0 { s.sendResume() } not compitible to old version , should be if n == 0 && s.sess.config.EnableStreamBuffer { s.sendResume() }

jannson avatar Mar 11 '19 05:03 jannson

The keepalive function is not compitible with old version too

jannson avatar Mar 11 '19 06:03 jannson

if n == 0 { s.sendResume() } not compitible to old version , should be if n == 0 && s.sess.config.EnableStreamBuffer { s.sendResume() }

收到

The keepalive function is not compitible with old version too

什麼情況下會造成問題? 新版連舊版, 只要在舊版KeepAliveTimeout之內有封包就不會舊版斷開 ("新版KeepAliveInterval" 小於 "舊版KeepAliveTimeout"即可) "新版KeepAliveInterval+新版KeepAliveTimeout" 小於 "舊版KeepAliveInterval"才會被新版斷開

舊版連舊版, 只在每個KeepAliveTimeout檢查有沒有收到封包, 本身就是無法保證的狀態 如果ping送出的同時剛好檢查Timeout, 對於幾乎靜止session的來說, 很大機率直接斷線

cs8425 avatar Mar 11 '19 11:03 cs8425

我分析了下，应该是这里： https://github.com/cs8425/smux/blob/move-token-to-stream2/session.go#L350 在旧版本，gotACK 是永远没得到响应的，所以　t 的超时时间是　 s.config.KeepAliveTimeout + s.config.KeepAliveInterval

这样的话，对方在 s.config.KeepAliveTimeout 周期内没得到 ping，就超时关闭连接了。

jannson avatar Mar 11 '19 11:03 jannson

超時會進入這段: https://github.com/cs8425/smux/blob/move-token-to-stream2/session.go#L341-L346 如果沒有任何封包才會斷開 不一定非要有ACK不可

cs8425 avatar Mar 11 '19 11:03 cs8425

A 是旧版本， B 是新版本，但是 B 的 EnableStreamBuffer === False 则 B 在 s.config.KeepAliveTimeout 内没有发出 Ping A 断开连接。 我表达的是这个意思。

因为 t.Reset(s.config.KeepAliveTimeout + s.config.KeepAliveInterval) 明显在 KeepAliveTimeout 时间内不会发出 Ping 的。 B 发出 cmdNOP 但 A 是旧版本，不响应 gotACK，所以 t 一直没机会 reset 到 KeepAliveInterval

jannson avatar Mar 11 '19 11:03 jannson

ok修正了 順便修正了bench的時候 用舊版keepalive()時KeepAliveInterval跟KeepAliveTimeout分別設為50ms 200ms有機會卡死的問題 已順便把間隔加大 至少比較不會因為舊版keepalive()的缺陷造成測試失敗

我覺得其實應該直接升級版本號 強制不相容過去版本 畢竟加了很多不好相容的功能 硬要相容過去版本很容易出問題 尤其是混用+選項分別開關的時候 那組合....

cs8425 avatar Mar 11 '19 17:03 cs8425

没办法啊，比如说服务器端与客户端这样的业务，同时存在新旧的客户端。 服务器端更新的时候，它就得一个库支持新旧客户端，免得就无法达到兼容的目的了，只能强制所有用户更新。 客户端与客户端的连接，可以用版本号控制，不同版本禁止相互连接。但服务器应该是要同时支持新旧的，通过参数控制。

jannson avatar Mar 12 '19 01:03 jannson

继续之前的讨论，你说要 “保證每個stream cmdSYN >> cmdPSH >> cmdFIN的封包順序”， cmdSYN 优先第一，这个现在代码就能保证了吧？因为只有 cmdSYN 之后，才能 OpenStream 或者 AcceptStream，后面只要保证先 Write 的 cmdPSH 比后 Write 的 cmdFIN 快就行了吧？ 如果是这样，则简单实现很多，只要 cmdFIN 与 cmdPSH 共用一个 channel writes，同时在 Write cmdFIN 的时候，也要 writeLock 一下， 这样有调度系统去保证他们获得锁的先后顺序就行了。

思路不变，但补充：

  1. AcceptStream 肯定是在 cmdSYN 成功之后的，不变
  2. OpenStream 是可能有先 cmdPSH 再 cmdSYN 的，思路与 cmdFIN 一样，在发送 cmdSYN cmdPSH cmdFIN 都要加 writeLock，由系统调度的先后来决定他们的顺序，先函数调用肯定先得到锁。

jannson avatar Mar 12 '19 01:03 jannson

目前改進的有:

  1. stream token, 完全不相容舊版
  2. keepalive, 有三種模式:
    1. 任一邊為舊版, 全降級為舊版(有缺陷)
    2. 新版但是要把KeepAliveInterval + KeepAliveTimeout設定成比舊版KeepAliveTimeout還小才能相容
    3. 雙邊都新版
  3. 併發Write的問題, 可相容
  4. (暫)保證cmdSYN >> cmdPSH >> cmdFIN的封包順序, 可相容

就算伺服端更新了新版 為了舊客戶端相容 等於沒有更新版本 那還不如強制所有舊版客戶端更新 反過來的意義比較大 客戶端可以用新版的程式連上還未更新的伺服端繼續使用服務

我認為2.2是比較好的選擇 (至少確定新版這邊不會主動斷開, 舊版那側無解) 但是需要使用者重新確認自己的設定 而不是像現在這樣為了相容舊版 必須回到有缺陷的實作

至於1完全不相容是因為舊版使用比較激進的錯誤處理方式(強制斷線) 如果把那段移除是可以相容的(會發cmdEMP cmdFUL cmdACK但是無作用) 但是改這個一樣要更新 那一樣不如一次到位....

cs8425 avatar Mar 12 '19 07:03 cs8425

除非是新特性实在跟旧客户端冲突，免得兼容的意义还是挺大的。毕竟强制所有用户更新客户端，从产品或业务的角度讲，伤害很大。我想的是如何更好的较缓和的升级服务器端。 当然也可以用你说的方案，先让大部分用户更新客户端，但不启用客户端的新特性，同时服务器端是旧的。等用户更新得差不多了，再在服务器端启用新特性，同时强制小部分用户升级。

兼容这个问题可以先放着，等解决了所有问题咱们再回头来看，看能达到什么兼容程度。

“保證cmdSYN >> cmdPSH >> cmdFIN的封包順序” 这个问题现在解决了吗？ 我说的方案是否可行？如果系统的锁的调度也无法保证顺序，那么也可以实现一个保证顺序的 cmdSYN cmdPSH cmdFIN 优先级的锁来解决。

jannson avatar Mar 12 '19 07:03 jannson

“保證cmdSYN >> cmdPSH >> cmdFIN的封包順序”這個應該是解決了 後來仔細想想 OpenStream()肯定要等到writeFrame(newFrame(cmdSYN, sid))成功後才返回*Stream 之後才會有Write()操作 所以這邊沒問題

Write()跟Close()併發呼叫的時候 是先close還是先write本身就無法保證 但是我們至少能保證一次Write()的資料不會被Close()送的cmdFIN截掉 理論上來說應該是符合正常使用情境

cs8425 avatar Mar 12 '19 12:03 cs8425

恩，看起来很简结，给力给力。

jannson avatar Mar 12 '19 13:03 jannson

感觉用 go test -race 还是会死锁，不知道问题在哪里。代码看起来都很 OK 的。

jannson avatar Mar 13 '19 04:03 jannson

-race我測是有過的啊 (TestParallel() TestParallel2()那邊RAM吃到7~8G) 你能確定是卡在哪個項目嗎? 卡住的時候不要急著關 連上 http://localhost:6060/debug/pprof/goroutine?debug=2 可以把goroutine dump出來分析問題

另外go v1.9.x的net.Pipe()應該有問題 TestWriteStreamRacePipe()一定不會過 猜測是v1.9.x過了support期限所以net.Pipe()的patch沒有backport 既然v1.9.x已停止維護 應該要把它移除了

cs8425 avatar Mar 13 '19 06:03 cs8425

感谢提供思路，我测试是超过 10 分钟没输出结果，就自动 killed 的了。 一会我再跑一次看看。

jannson avatar Mar 13 '19 06:03 jannson 

版本是： go1.11 linux/amd64
系统是： centos (家里的 ubuntu　也没测试过)

--- FAIL: TestSlowReadBlocking (3.57s)
session_test.go:1017: fast write stream start...
session_test.go:1081: normal stream start...
session_test.go:1126: [normal]r 5 0 rtt 5.817711ms stream.bucket 0 stream.guessNeeded 0
session_test.go:1126: [normal]r 5 1 rtt 2.559955ms stream.bucket 0 stream.guessNeeded 18
session_test.go:1126: [normal]r 5 2 rtt 678.696µs stream.bucket 0 stream.guessNeeded 12
session_test.go:1126: [normal]r 5 3 rtt 3.64238ms stream.bucket 0 stream.guessNeeded 0
....................................................................... ....................................................................... ....................................................................... ....................................................................... session_test.go:1126: [normal]r 5 46 rtt 2.722445ms stream.bucket 0 stream.guessNeeded 14
session_test.go:1126: [normal]r 5 47 rtt 2.687178ms stream.bucket 0 stream.guessNeeded 14
session_test.go:1126: [normal]r 5 48 rtt 1.015599ms stream.bucket 0 stream.guessNeeded 28
session_test.go:1126: [normal]r 5 49 rtt 645.687µs stream.bucket 0 stream.guessNeeded 28
session_test.go:1126: [normal]r 5 50 rtt 1.085514ms stream.bucket 0 stream.guessNeeded 14
session_test.go:1126: [normal]r 5 51 rtt 830.415µs stream.bucket 0 stream.guessNeeded 21
session_test.go:1126: [normal]r 5 52 rtt 1.100771ms stream.bucket 0 stream.guessNeeded 0
session_test.go:1126: [normal]r 5 53 rtt 677.102µs stream.bucket 0 stream.guessNeeded 14
session_test.go:1126: [normal]r 5 54 rtt 156.806743ms stream.bucket 0 stream.guessNeeded 2653
session_test.go:1116: 5 55 i/o timeout session.bucket 0 stream.bucket 0 stream.empflag 1 stream.fulflag 0 session_test.go:1560: goroutine 6389 [running]:
runtime/pprof.writeGoroutineStacks(0xa7a460, 0xc0001264d0, 0xd0, 0xd0)
/home/janson/projects/cloud/go1.11/src/runtime/pprof/pprof.go:678 +0xb5
runtime/pprof.writeGoroutine(0xa7a460, 0xc0001264d0, 0x2, 0x435458, 0xd0)
/home/janson/projects/cloud/go1.11/src/runtime/pprof/pprof.go:667 +0x52
runtime/pprof.(*Profile).WriteTo(0xd92200, 0xa7a460, 0xc0001264d0, 0x2, 0xc000124e18, 0xc000379c38) /home/janson/projects/cloud/go1.11/src/runtime/pprof/pprof.go:328 +0x546 github.com/jannson/smux.dumpGoroutine(0xc000124e00) /home/janson/workspace-go/src/github.com/jannson/smux/session_test.go:1559 +0xd8 github.com/jannson/smux.testSlowReadBlocking.func3(0xc00445e4d0, 0xc000137880, 0xc000124e00, 0xc000137878, 0xc004c3a460) /home/janson/workspace-go/src/github.com/jannson/smux/session_test.go:1120 +0xa4f created by github.com/jannson/smux.testSlowReadBlocking /home/janson/workspace-go/src/github.com/jannson/smux/session_test.go:1073 +0x2ce

    goroutine 1 [chan receive]:
    testing.(*T).Run(0xc000124100, 0x9f8781, 0x14, 0xa0d150, 0xc0000ebc01)
            /home/janson/projects/cloud/go1.11/src/testing/testing.go:879 +0x689
    testing.runTests.func1(0xc000124100)
            /home/janson/projects/cloud/go1.11/src/testing/testing.go:1119 +0xa9
    testing.tRunner(0xc000124100, 0xc0000ebd88)
            /home/janson/projects/cloud/go1.11/src/testing/testing.go:827 +0x163
    testing.runTests(0xc00009e3e0, 0xd990e0, 0x2f, 0x2f, 0xc0000ebe78)
            /home/janson/projects/cloud/go1.11/src/testing/testing.go:1117 +0x4ef
    testing.(*M).Run(0xc00013e100, 0x0)
            /home/janson/projects/cloud/go1.11/src/testing/testing.go:1034 +0x2ef
    main.main()
            _testmain.go:150 +0x222

    goroutine 20 [IO wait, 3 minutes]:
    internal/poll.runtime_pollWait(0x7f273c683f00, 0x72, 0xc000146b18)
            /home/janson/projects/cloud/go1.11/src/runtime/netpoll.go:173 +0x66
    internal/poll.(*pollDesc).wait(0xc000152298, 0x72, 0x0, 0x0, 0xa7b660)
            /home/janson/projects/cloud/go1.11/src/internal/poll/fd_poll_runtime.go:85 +0xe4
    internal/poll.(*pollDesc).waitRead(0xc000152298, 0xffffffffffffff00, 0x0, 0x0)
            /home/janson/projects/cloud/go1.11/src/internal/poll/fd_poll_runtime.go:90 +0x4b
    internal/poll.(*FD).Accept(0xc000152280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
            /home/janson/projects/cloud/go1.11/src/internal/poll/fd_unix.go:384 +0x27f
    net.(*netFD).accept(0xc000152280, 0x50, 0x50, 0x46551f)

总结下，卡住的地方有： session.go#225 session.go#408 session.go#362 session.go#390 session.go#135 stream.go#259

jannson avatar Mar 13 '19 09:03 jannson

--- FAIL: TestSlowReadBlocking (3.57s) session_test.go:1017: fast write stream start... session_test.go:1081: normal stream start... session_test.go:1126: [normal]r 5 0 rtt 5.817711ms stream.bucket 0 stream.guessNeeded 0 session_test.go:1126: [normal]r 5 1 rtt 2.559955ms stream.bucket 0 stream.guessNeeded 18 ....................................................................... ....................................................................... ....................................................................... ....................................................................... session_test.go:1126: [normal]r 5 53 rtt 677.102µs stream.bucket 0 stream.guessNeeded 14 session_test.go:1126: [normal]r 5 54 rtt 156.806743ms stream.bucket 0 stream.guessNeeded 2653 session_test.go:1116: 5 55 i/o timeout session.bucket 0 stream.bucket 0 stream.empflag 1 stream.fulflag 0

session.bucket 0 << session的buffer用完了導致全部卡死 stream.sendPause()已發送但是對面的stream.pauseWrite()還未執行 而stream.Write()把buffer寫爆造成的 通常發生在高RTT或是發送方的recvLoop()執行比較慢/無法同時執行的情況 (-race好像會影響調度, 至少我測試的情況下buffer都要開比較大) 把MaxReceiveBuffer加大即可解決

我好像又發現原版的一個race問題 recvLoop() stream.pushBytes(f.data)之後session.bucket剛好爆掉 進入<-s.bucketNotify卡住 而同時stream.Read()又剛好把stream.buffer讀空卡在case <-s.chReadEvent: 由於recvLoop()卡住 <-s.chReadEvent不可能被觸發 直接等到timeout

此問題容易發生在session.bucket很小 幾個frame就會用光 而且一次Read()/Write()的量大於單個frame大小

cs8425 avatar Mar 13 '19 12:03 cs8425

关于这一点："我好像又發現原版的一個race問題"——好像没问题。 recvLoop stream.pushBytes 之后，bucket 空了，但也给 stream.chReadEvent 事件了，所以 stream.Read 总能读一次，并且 returnTokens，从而让 <-s.bucketNotify 得以释放。

我把 MaxReceiveBuffer: 16 * 1024 * 1024, MaxStreamBuffer: 4 * 1024 * 1024, 设置得很大了，但返回这样： *** Test killed with quit: ran too long (10m0s). 是不是表示测试通过了？因为没有 stream 超时了。

jannson avatar Mar 13 '19 13:03 jannson

关于这一点："我好像又發現原版的一個race問題"——好像没问题。 recvLoop stream.pushBytes 之后，bucket 空了，但也给 stream.chReadEvent 事件了，所以 stream.Read 总能读一次，并且 returnTokens，从而让 <-s.bucketNotify 得以释放。

不對 我這邊有個test可以複現了 雖然要多跑幾次才會碰到 4個Read()都卡在<-s.chReadEvent 但是recvLoop()卡在<-s.bucketNotify直接deadlock 造成Read() timeout 我這邊測試一次大約5秒 總共大概20~60秒左右就會複現

應該是不算... 是跑太慢沒跑完 我記得有參數能調整test的時間長度

補個卡住時候的輸出: 少的read()應該是在dump的時候因為timeout return了

================ echo server
        goroutine 236 [select]:
        _/home/cs8425/code/smux.(*Session).AcceptStream(0xc0000964d0, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/session.go:135 +0x187
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func1(0xc000018340, 0x888180, 0xc00000e038)
        	/home/cs8425/code/smux/session_test.go:1383 +0xaa
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite
        	/home/cs8425/code/smux/session_test.go:1380 +0x113

        goroutine 246 [select]:
        _/home/cs8425/code/smux.(*Session).keepalive.func1(0x0, 0xc0000e9400)
        	/home/cs8425/code/smux/session.go:331 +0x1b7
        _/home/cs8425/code/smux.(*Session).keepalive(0xc0000964d0)
        	/home/cs8425/code/smux/session.go:346 +0xa9
        created by _/home/cs8425/code/smux.newSession
        	/home/cs8425/code/smux/session.go:88 +0x261

        goroutine 245 [IO wait]:
        internal/poll.runtime_pollWait(0x7f1414bedf00, 0x77, 0xc000182c78)
        	/opt/go/src/runtime/netpoll.go:173 +0x66
        internal/poll.(*pollDesc).wait(0xc00012c598, 0x77, 0xffffffffffffff00, 0x883d40, 0xae5618)
        	/opt/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
        internal/poll.(*pollDesc).waitWrite(0xc00012c598, 0xc000906200, 0x1ff, 0xfdff)
        	/opt/go/src/internal/poll/fd_poll_runtime.go:94 +0x3d
        internal/poll.(*FD).Write(0xc00012c580, 0xc000906000, 0x408, 0x10008, 0x0, 0x0, 0x0)
        	/opt/go/src/internal/poll/fd_unix.go:276 +0x254
        net.(*netFD).Write(0xc00012c580, 0xc000906000, 0x408, 0x10008, 0xc00049f9e0, 0xc000182fa0, 0xc0001363c0)
        	/opt/go/src/net/fd_unix.go:220 +0x4f
        net.(*conn).Write(0xc00000e038, 0xc000906000, 0x408, 0x10008, 0x0, 0x0, 0x0)
        	/opt/go/src/net/net.go:189 +0x68
        _/home/cs8425/code/smux.(*Session).sendLoop.func1(0x300000201, 0xc0002b8000, 0x400, 0x100000, 0xc0008c7b00)
        	/home/cs8425/code/smux/session.go:388 +0x15a
        _/home/cs8425/code/smux.(*Session).sendLoop(0xc0000964d0)
        	/home/cs8425/code/smux/session.go:416 +0x103
        created by _/home/cs8425/code/smux.newSession
        	/home/cs8425/code/smux/session.go:87 +0x23f

        goroutine 244 [chan receive]: `<-s.bucketNotify`
        _/home/cs8425/code/smux.(*Session).recvLoop(0xc0000964d0)
        	/home/cs8425/code/smux/session.go:248 +0xa0
        created by _/home/cs8425/code/smux.newSession
        	/home/cs8425/code/smux/session.go:86 +0x21d
================

================ echo read/write
        goroutine 252 [select]: `<-s.chReadEvent`
        _/home/cs8425/code/smux.(*Stream).Read(0xc0000e8000, 0xc0001b8000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:100 +0x24b
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func1.1(0x885f60, 0xc0000e8000)
        	/home/cs8425/code/smux/session_test.go:1388 +0xeb
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite.func1
        	/home/cs8425/code/smux/session_test.go:1384 +0x9c

        goroutine 254 [select]: `<-s.chReadEvent`
        _/home/cs8425/code/smux.(*Stream).Read(0xc0000e83c0, 0xc00070e000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:100 +0x24b
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func1.1(0x885f60, 0xc0000e83c0)
        	/home/cs8425/code/smux/session_test.go:1388 +0xeb
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite.func1
        	/home/cs8425/code/smux/session_test.go:1384 +0x9c
        
        goroutine 251 [select]:
        _/home/cs8425/code/smux.(*Stream).Write(0xc0000e8b40, 0xc0002b8000, 0x400, 0x100000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:153 +0x48b
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func1.1(0x885f60, 0xc0000e8b40)
        	/home/cs8425/code/smux/session_test.go:1392 +0xb9
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite.func1
        	/home/cs8425/code/smux/session_test.go:1384 +0x9c
        
        goroutine 253 [select]:
        _/home/cs8425/code/smux.(*Stream).Write(0xc0000e8280, 0xc000506000, 0x800, 0x100000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:145 +0x3a0
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func1.1(0x885f60, 0xc0000e8280)
        	/home/cs8425/code/smux/session_test.go:1392 +0xb9
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite.func1
        	/home/cs8425/code/smux/session_test.go:1384 +0x9c
================

================ test session
        goroutine 239 [select]:
        _/home/cs8425/code/smux.(*Session).keepalive.func1(0x0, 0xc000032700)
        	/home/cs8425/code/smux/session.go:331 +0x1b7
        _/home/cs8425/code/smux.(*Session).keepalive(0xc000096420)
        	/home/cs8425/code/smux/session.go:346 +0xa9
        created by _/home/cs8425/code/smux.newSession
        	/home/cs8425/code/smux/session.go:88 +0x261

        goroutine 238 [IO wait]:
        internal/poll.runtime_pollWait(0x7f1414bede30, 0x77, 0xc000038478)
        	/opt/go/src/runtime/netpoll.go:173 +0x66
        internal/poll.(*pollDesc).wait(0xc00012c518, 0x77, 0xffffffffffffff00, 0x883d40, 0xae5618)
        	/opt/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
        internal/poll.(*pollDesc).waitWrite(0xc00012c518, 0xc000868200, 0x16f, 0xfd6f)
        	/opt/go/src/internal/poll/fd_poll_runtime.go:94 +0x3d
        internal/poll.(*FD).Write(0xc00012c500, 0xc000868000, 0x408, 0x10008, 0x0, 0x0, 0x0)
        	/opt/go/src/internal/poll/fd_unix.go:276 +0x254
        net.(*netFD).Write(0xc00012c500, 0xc000868000, 0x408, 0x10008, 0xc00049f8c0, 0xc0000387a0, 0xc0001363c0)
        	/opt/go/src/net/fd_unix.go:220 +0x4f
        net.(*conn).Write(0xc00000e050, 0xc000868000, 0x408, 0x10008, 0x0, 0x0, 0x0)
        	/opt/go/src/net/net.go:189 +0x68
        _/home/cs8425/code/smux.(*Session).sendLoop.func1(0x500000201, 0xc00087cc00, 0x400, 0x1400, 0xc00066c420)
        	/home/cs8425/code/smux/session.go:388 +0x15a
        _/home/cs8425/code/smux.(*Session).sendLoop(0xc000096420)
        	/home/cs8425/code/smux/session.go:416 +0x103
        created by _/home/cs8425/code/smux.newSession
        	/home/cs8425/code/smux/session.go:87 +0x23f

        goroutine 237 [chan receive]: `<-s.bucketNotify`
        _/home/cs8425/code/smux.(*Session).recvLoop(0xc000096420)
        	/home/cs8425/code/smux/session.go:248 +0xa0
        created by _/home/cs8425/code/smux.newSession
        	/home/cs8425/code/smux/session.go:86 +0x21d

    session_test.go:1405: ================
    session_test.go:1406: session.bucket 0 session.streams.len 4
    session_test.go:1408: id: 3, addr: 0xc0000e8500, bucket: 0, empflag: 1, fulflag: 0
    session_test.go:1408: id: 5, addr: 0xc0000e8640, bucket: 0, empflag: 1, fulflag: 0
    session_test.go:1408: id: 7, addr: 0xc0000e8780, bucket: 0, empflag: 1, fulflag: 0
    session_test.go:1408: id: 9, addr: 0xc0000e88c0, bucket: 0, empflag: 1, fulflag: 0
    session_test.go:1411: ================

================ test write
        goroutine 241 [select]: sid = 7
        _/home/cs8425/code/smux.(*Stream).Write(0xc0000e8780, 0xc000880000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:145 +0x3a0
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func3(0xc000096420)
        	/home/cs8425/code/smux/session_test.go:1458 +0x2d2
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite
        	/home/cs8425/code/smux/session_test.go:1478 +0x23a
        
        goroutine 240 [select]: sid = 5
        _/home/cs8425/code/smux.(*Stream).Write(0xc0000e8640, 0xc00087c000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:153 +0x48b
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func3(0xc000096420)
        	/home/cs8425/code/smux/session_test.go:1458 +0x2d2
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite
        	/home/cs8425/code/smux/session_test.go:1478 +0x23a
        
        goroutine 243 [select]: sid = 3
        _/home/cs8425/code/smux.(*Stream).Write(0xc0000e8500, 0xc00087a000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:145 +0x3a0
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func3(0xc000096420)
        	/home/cs8425/code/smux/session_test.go:1458 +0x2d2
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite
        	/home/cs8425/code/smux/session_test.go:1478 +0x23a

        goroutine 242 [select]: sid = 9
        _/home/cs8425/code/smux.(*Stream).Write(0xc0000e88c0, 0xc000884000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:145 +0x3a0
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func3(0xc000096420)
        	/home/cs8425/code/smux/session_test.go:1458 +0x2d2
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite
        	/home/cs8425/code/smux/session_test.go:1478 +0x23a
================

================ test read
        goroutine 247 [select]: sid = 3,  `<-s.chReadEvent`
        _/home/cs8425/code/smux.(*Stream).Read(0xc0000e8500, 0xc000855f78, 0x2000, 0x2000, 0x0, 0x0, 0x0)
        	/home/cs8425/code/smux/stream.go:100 +0x24b
        _/home/cs8425/code/smux.testSmallBufferReadWrite.func3.2(0xc000488ce0, 0xc000488cb0, 0xc0000e8500, 0xc000104500, 0x835d48, 0xc000096420)
        	/home/cs8425/code/smux/session_test.go:1441 +0x114
        created by _/home/cs8425/code/smux.testSmallBufferReadWrite.func3
        	/home/cs8425/code/smux/session_test.go:1436 +0x1f4

cs8425 avatar Mar 13 '19 15:03 cs8425