Skip to content

Unreliable TurboTunnel Test 2024 Q3

During the processing of unrelated dependency version upgrade merge request, some complex error emitted from Turbotunnel part of the code base.

1

I was unable to instantly locate root cause of issues, however, here are some guess:

FAIL: TestQueuePacketConnWriteToKCP 
--- FAIL: TestQueuePacketConnWriteToKCP (0.68s)
panic: empty transcript [recovered]
	panic: empty transcript

goroutine 41 [running]:
testing.tRunner.func1.2({0x763e60, 0x814510})
	/usr/local/go/src/testing/testing.go:1632 +0x3fc
testing.tRunner.func1()
	/usr/local/go/src/testing/testing.go:1635 +0x6b6
panic({0x763e60?, 0x814510?})
	/usr/local/go/src/runtime/panic.go:785 +0x132
gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP(0xc0000bed00)
	/builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:222 +0x790
testing.tRunner(0xc0000bed00, 0x7d1ae8)
	/usr/local/go/src/testing/testing.go:1690 +0x227
created by testing.(*T).Run in goroutine 1
	/usr/local/go/src/testing/testing.go:1743 +0x826
FAIL	gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel	0.803s
This could caused by 4497d68d unable to fully absorb the change on KCP side. Full log: https://gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/-/jobs/685434/raw = job.log

2

The race detection is also showing error:

WARNING: DATA RACE 
=== RUN   TestQueuePacketConnWriteToKCP
==================
WARNING: DATA RACE
Read at 0x00c002c08060 by goroutine 42:
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:221 +0x467
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /usr/local/go/src/testing/testing.go:1743 +0x44

Previous write at 0x00c002c08060 by goroutine 4178:
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.(*TranscriptPacketConn).WriteTo()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:148 +0x1f5
  github.com/xtaci/kcp-go/v5.(*UDPSession).defaultTx()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/tx.go:37 +0x161
  github.com/xtaci/kcp-go/v5.(*UDPSession).tx()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/tx_linux.go:40 +0xc4
  github.com/xtaci/kcp-go/v5.(*UDPSession).postProcess()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:677 +0x1ed
  github.com/xtaci/kcp-go/v5.newUDPSession.gowrap1()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:233 +0x33

Goroutine 42 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1743 +0x825
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:2168 +0x85
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1690 +0x226
  testing.runTests()
      /usr/local/go/src/testing/testing.go:2166 +0x8be
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:2034 +0xf17
  main.main()
      _testmain.go:59 +0x164

Goroutine 4178 (running) created at:
  github.com/xtaci/kcp-go/v5.newUDPSession()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:233 +0xc6d
  github.com/xtaci/kcp-go/v5.NewConn3()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:1192 +0xed
  github.com/xtaci/kcp-go/v5.NewConn2()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:1199 +0x12
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:202 +0x38f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /usr/local/go/src/testing/testing.go:1743 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c002efc0a8 by goroutine 42:
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:225 +0x504
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /usr/local/go/src/testing/testing.go:1743 +0x44

Previous write at 0x00c002efc0a8 by goroutine 4178:
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.(*TranscriptPacketConn).WriteTo()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:148 +0x19a
  github.com/xtaci/kcp-go/v5.(*UDPSession).defaultTx()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/tx.go:37 +0x161
  github.com/xtaci/kcp-go/v5.(*UDPSession).tx()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/tx_linux.go:40 +0xc4
  github.com/xtaci/kcp-go/v5.(*UDPSession).postProcess()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:677 +0x1ed
  github.com/xtaci/kcp-go/v5.newUDPSession.gowrap1()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:233 +0x33

Goroutine 42 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1743 +0x825
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:2168 +0x85
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1690 +0x226
  testing.runTests()
      /usr/local/go/src/testing/testing.go:2166 +0x8be
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:2034 +0xf17
  main.main()
      _testmain.go:59 +0x164

Goroutine 4178 (finished) created at:
  github.com/xtaci/kcp-go/v5.newUDPSession()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:233 +0xc6d
  github.com/xtaci/kcp-go/v5.NewConn3()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:1192 +0xed
  github.com/xtaci/kcp-go/v5.NewConn2()
      /go/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:1199 +0x12
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:202 +0x38f
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /usr/local/go/src/testing/testing.go:1743 +0x44
==================
    testing.go:1399: race detected during execution of test
--- FAIL: TestQueuePacketConnWriteToKCP (1.71s)
FAIL
FAIL	gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel	1.872s

I was unable to immeditely detect a root cause of this issue.

Full log: https://gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/-/jobs/684468/raw = job2.log

3

There is another error showing up on commit 4497d68d, 60c89648.

WARNING: DATA RACE 
=== RUN   TestQueuePacketConnWriteToKCP
==================
WARNING: DATA RACE
Write at 0x00c0000ba060 by goroutine 543:
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.(*TranscriptPacketConn).WriteTo()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:148 +0x1f5
  github.com/xtaci/kcp-go/v5.(*UDPSession).defaultTx()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/tx.go:37 +0x161
  github.com/xtaci/kcp-go/v5.(*UDPSession).tx()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/tx_linux.go:40 +0xc4
  github.com/xtaci/kcp-go/v5.(*UDPSession).postProcess()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:677 +0x1ed
  github.com/xtaci/kcp-go/v5.newUDPSession.gowrap1()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:233 +0x33

Previous read at 0x00c0000ba060 by goroutine 42:
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:221 +0x467
  testing.tRunner()
      /usr/lib/go-1.23/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /usr/lib/go-1.23/src/testing/testing.go:1743 +0x44

Goroutine 543 (running) created at:
  github.com/xtaci/kcp-go/v5.newUDPSession()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:233 +0xc6d
  github.com/xtaci/kcp-go/v5.NewConn3()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:1192 +0xed
  github.com/xtaci/kcp-go/v5.NewConn2()
      /usr/share/gocode/pkg/mod/github.com/xtaci/kcp-go/v5@v5.6.17/sess.go:1199 +0x12
  gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/v2/common/turbotunnel.TestQueuePacketConnWriteToKCP()
      /builds/tpo/anti-censorship/pluggable-transports/snowflake/common/turbotunnel/queuepacketconn_test.go:202 +0x38f
  testing.tRunner()
      /usr/lib/go-1.23/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /usr/lib/go-1.23/src/testing/testing.go:1743 +0x44

Goroutine 42 (running) created at:
  testing.(*T).Run()
      /usr/lib/go-1.23/src/testing/testing.go:1743 +0x825
  testing.runTests.func1()
      /usr/lib/go-1.23/src/testing/testing.go:2168 +0x85
  testing.tRunner()
      /usr/lib/go-1.23/src/testing/testing.go:1690 +0x226
  testing.runTests()
      /usr/lib/go-1.23/src/testing/testing.go:2166 +0x8be
  testing.(*M).Run()
      /usr/lib/go-1.23/src/testing/testing.go:2034 +0xf17
  main.main()
      _testmain.go:59 +0x164
==================
    queuepacketconn_test.go:232: 2 0 packet changed between send and recv
        send: "kec\xb9Q\x00 \x00\xc8\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\v\x00\x00\x00hello world"
        recv: "\xcd\xe9WvQ\x00 \x00\xc0\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\v\x00\x00\x00hello world"
    testing.go:1399: race detected during execution of test
--- FAIL: TestQueuePacketConnWriteToKCP (0.55s)
FAIL

Full log: https://gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/-/jobs/684257/raw = job3.log

Edited by Cecylia Bocovich