Revert the unified debug logger.

service/logger.go

@@ -17,16 +17,3 @@ package service
 import logging "github.com/op/go-logging"
 
 var logger = logging.MustGetLogger("shadowsocks")
-
-type DebugLoggerFunc func(tag string, template string, val interface{})
-
-// NewDebugLogger creates a wrapper for logger.Debugf during proxying.
-func NewDebugLogger(protocol string) DebugLoggerFunc {
- return func(tag string, template string, val interface{}) {
- // This is an optimization to reduce unnecessary allocations due to an interaction
- // between Go's inlining/escape analysis and varargs functions like logger.Debugf.
- if logger.IsEnabledFor(logging.DEBUG) {
- logger.Debugf("%s(%s): "+template, protocol, tag, val)
- }
- }
-}

service/shadowsocks.go

@@ -22,8 +22,10 @@ import (
  "github.com/Jigsaw-Code/outline-sdk/transport/shadowsocks"
 )
 
-// findAccessKey implements a trial decryption search. This assumes that all ciphers are AEAD.
-func findAccessKey(clientIP netip.Addr, bufferSize int, src []byte, cipherList CipherList, logDebug DebugLoggerFunc) (*CipherEntry, []byte, time.Duration, error) {
+type DebugLoggerFunc func(tag string, template string, val interface{})
+
+// findShadowsocksAccessKey implements a trial decryption search. This assumes that all ciphers are AEAD.
+func findShadowsocksAccessKey(clientIP netip.Addr, bufferSize int, src []byte, cipherList CipherList, logDebug DebugLoggerFunc) (*CipherEntry, []byte, time.Duration, error) {
  // We snapshot the list because it may be modified while we use it.
  ciphers := cipherList.SnapshotForClientIP(clientIP)
 

service/shadowsocks_test.go

@@ -37,7 +37,7 @@ func BenchmarkTCPFindCipherFail(b *testing.B) {
  testPayload := makeTestPayload(50)
  for n := 0; n < b.N; n++ {
  b.StartTimer()
- findAccessKey(clientIP, 2, testPayload, cipherList, NewDebugLogger("TCP"))
+ findShadowsocksAccessKey(clientIP, 2, testPayload, cipherList, func(tag string, template string, val interface{}) {})
  b.StopTimer()
  }
 }
@@ -68,7 +68,7 @@ func BenchmarkTCPFindCipherRepeat(b *testing.B) {
  cipher := cipherEntries[cipherNumber].CryptoKey
  go shadowsocks.NewWriter(writer, cipher).Write(makeTestPayload(50))
  b.StartTimer()
- _, _, _, err := findAccessKey(clientIP, 2, testPayload, cipherList, NewDebugLogger("TCP"))
+ _, _, _, err := findShadowsocksAccessKey(clientIP, 2, testPayload, cipherList, nil)
  b.StopTimer()
  if err != nil {
  b.Error(err)
@@ -87,7 +87,7 @@ func BenchmarkUDPUnpackFail(b *testing.B) {
  testIP := netip.MustParseAddr("192.0.2.1")
  b.ResetTimer()
  for n := 0; n < b.N; n++ {
- findAccessKey(testIP, serverUDPBufferSize, testPayload, cipherList, NewDebugLogger("UDP"))
+ findShadowsocksAccessKey(testIP, serverUDPBufferSize, testPayload, cipherList, nil)
  }
 }
 
@@ -116,7 +116,7 @@ func BenchmarkUDPUnpackRepeat(b *testing.B) {
  cipherNumber := n % numCiphers
  ip := ips[cipherNumber]
  packet := packets[cipherNumber]
- _, _, _, err := findAccessKey(ip, serverUDPBufferSize, packet, cipherList, NewDebugLogger("UDP"))
+ _, _, _, err := findShadowsocksAccessKey(ip, serverUDPBufferSize, packet, cipherList, nil)
  if err != nil {
  b.Error(err)
  }
@@ -144,7 +144,7 @@ func BenchmarkUDPUnpackSharedKey(b *testing.B) {
  b.ResetTimer()
  for n := 0; n < b.N; n++ {
  ip := ips[n%numIPs]
- _, _, _, err := findAccessKey(ip, serverUDPBufferSize, packet, cipherList, NewDebugLogger("UDP"))
+ _, _, _, err := findShadowsocksAccessKey(ip, serverUDPBufferSize, packet, cipherList, nil)
  if err != nil {
  b.Error(err)
  }

service/tcp.go

@@ -31,6 +31,7 @@ import (
  "github.com/Jigsaw-Code/outline-ss-server/ipinfo"
  onet "github.com/Jigsaw-Code/outline-ss-server/net"
  "github.com/Jigsaw-Code/outline-ss-server/service/metrics"
+ logging "github.com/op/go-logging"
  "github.com/shadowsocks/go-shadowsocks2/socks"
 )
 
@@ -60,6 +61,15 @@ func remoteIP(conn net.Conn) netip.Addr {
  return netip.Addr{}
 }
 
+// Wrapper for logger.Debugf during TCP access key searches.
+func debugTCP(cipherID, template string, val interface{}) {
+ // This is an optimization to reduce unnecessary allocations due to an interaction
+ // between Go's inlining/escape analysis and varargs functions like logger.Debugf.
+ if logger.IsEnabledFor(logging.DEBUG) {
+ logger.Debugf("TCP(%s): "+template, cipherID, val)
+ }
+}
+
 type StreamAuthenticateFunc func(clientConn transport.StreamConn) (string, transport.StreamConn, *onet.ConnectionError)
 
 // ShadowsocksTCPMetrics is used to report Shadowsocks metrics on TCP connections.
@@ -86,7 +96,7 @@ func NewShadowsocksStreamAuthenticator(ciphers CipherList, replayCache *ReplayCa
 
  // Find the cipher and acess key id.
  bufferSize := 2
- cipherEntry, _, timeToCipher, keyErr := findAccessKey(remoteIP(clientConn), bufferSize, firstBytes, ciphers, NewDebugLogger("TCP"))
+ cipherEntry, _, timeToCipher, keyErr := findShadowsocksAccessKey(remoteIP(clientConn), bufferSize, firstBytes, ciphers, debugTCP)
  metrics.AddTCPCipherSearch(keyErr == nil, timeToCipher)
  if keyErr != nil {
  // TODO: Ban and log client IPs with too many failures too quick to protect against DoS.

service/udp.go

@@ -117,13 +117,14 @@ func (h *packetHandler) authenticate(clientConn net.PacketConn) (net.Addr, *Ciph
  return nil, nil, nil, 0, onet.NewConnectionError("ERR_READ", "Failed to read from client", err)
  }
 
- logDebug := NewDebugLogger("UDP")
- defer logDebug(clientAddr.String(), "done%s", "")
- logDebug(clientAddr.String(), "Outbound packet has %d bytes", clientProxyBytes)
+ if logger.IsEnabledFor(logging.DEBUG) {
+ defer logger.Debugf("UDP(%v): done", clientAddr)
+ logger.Debugf("UDP(%v): Outbound packet has %d bytes", clientAddr, clientProxyBytes)
+ }
 
  remoteIP := clientAddr.(*net.UDPAddr).AddrPort().Addr()
 
- cipherEntry, textData, timeToCipher, keyErr := findAccessKey(remoteIP, serverUDPBufferSize, cipherBuf[:clientProxyBytes], h.ciphers, logDebug)
+ cipherEntry, textData, timeToCipher, keyErr := findShadowsocksAccessKey(remoteIP, serverUDPBufferSize, cipherBuf[:clientProxyBytes], h.ciphers, debugUDP)
  h.m.AddUDPCipherSearch(err == nil, timeToCipher)
  if keyErr != nil {
  return nil, nil, nil, 0, onet.NewConnectionError("ERR_CIPHER", "Failed to find a valid cipher", keyErr)