From 3dc4c6fb3f2d27aa6695154c7368291101a3e01c Mon Sep 17 00:00:00 2001 From: Qian Wang Date: Tue, 6 Aug 2019 11:19:47 +0100 Subject: [PATCH] Add more trace logs --- cmd/ck-client/ck-client.go | 3 +++ cmd/ck-server/ck-server.go | 1 + internal/multiplex/session.go | 5 ++++- internal/multiplex/stream.go | 18 ++++++++++++------ 4 files changed, 20 insertions(+), 7 deletions(-) diff --git a/cmd/ck-client/ck-client.go b/cmd/ck-client/ck-client.go index b680d2d..afad156 100644 --- a/cmd/ck-client/ck-client.go +++ b/cmd/ck-client/ck-client.go @@ -45,8 +45,10 @@ func makeRemoteConn(sta *client.State) (net.Conn, []byte, error) { log.WithField("error", err).Error("Failed to send ClientHello") return nil, nil, err } + log.Trace("client hello sent successfully") buf := make([]byte, 1024) + log.Trace("waiting for ServerHello") _, err = util.ReadTLS(remoteConn, buf) if err != nil { log.WithField("error", err).Error("Failed to read ServerHello") @@ -93,6 +95,7 @@ func makeSession(sta *client.State) *mux.Session { }() } wg.Wait() + log.Debug("All underlying connections established") sessionKey := _sessionKey.Load().([]byte) obfuscator, err := mux.GenerateObfs(sta.EncryptionMethod, sessionKey) diff --git a/cmd/ck-server/ck-server.go b/cmd/ck-server/ck-server.go index 0a18f71..004a167 100644 --- a/cmd/ck-server/ck-server.go +++ b/cmd/ck-server/ck-server.go @@ -85,6 +85,7 @@ func dispatchConnection(conn net.Conn, sta *server.State) { go conn.Close() return err } + log.Trace("finished handshake") return nil } diff --git a/internal/multiplex/session.go b/internal/multiplex/session.go index 802b50a..ee729fa 100644 --- a/internal/multiplex/session.go +++ b/internal/multiplex/session.go @@ -87,7 +87,7 @@ func (sesh *Session) OpenStream() (*Stream, error) { sesh.streamsM.Lock() sesh.streams[id] = stream sesh.streamsM.Unlock() - //log.Printf("Opening stream %v\n", id) + log.Tracef("stream %v of session %v opened", id, sesh.id) return stream, nil } @@ -99,6 +99,7 @@ func (sesh *Session) Accept() (net.Conn, error) { if stream == nil { return nil, ErrBrokenSession } + log.Tracef("stream %v of session %v accepted", stream.id, sesh.id) return stream, nil } @@ -106,6 +107,7 @@ func (sesh *Session) delStream(id uint32) { sesh.streamsM.Lock() delete(sesh.streams, id) if len(sesh.streams) == 0 { + log.Tracef("session %v has no active stream left", sesh.id) go sesh.timeoutAfter(30 * time.Second) } sesh.streamsM.Unlock() @@ -157,6 +159,7 @@ func (sesh *Session) TerminalMsg() string { } func (sesh *Session) Close() error { + log.Debugf("attempting to close session %v", sesh.id) atomic.StoreUint32(&sesh.closed, 1) sesh.streamsM.Lock() sesh.acceptCh <- nil diff --git a/internal/multiplex/stream.go b/internal/multiplex/stream.go index 8f3a380..74313e9 100644 --- a/internal/multiplex/stream.go +++ b/internal/multiplex/stream.go @@ -50,7 +50,6 @@ func makeStream(sesh *Session, id uint32, assignedConnId uint32) *Stream { assignedConnId: assignedConnId, } - log.Tracef("stream %v opened", id) return stream } @@ -61,6 +60,7 @@ func (s *Stream) isClosed() bool { return atomic.LoadUint32(&s.closed) == 1 } func (s *Stream) writeFrame(frame *Frame) { s.sorter.writeNewFrame(frame) } func (s *Stream) Read(buf []byte) (n int, err error) { + //log.Tracef("attempting to read from stream %v", s.id) if len(buf) == 0 { if s.isClosed() { return 0, ErrBrokenStream @@ -72,10 +72,14 @@ func (s *Stream) Read(buf []byte) (n int, err error) { if s.sortedBuf.Len() == 0 { return 0, ErrBrokenStream } else { - return s.sortedBuf.Read(buf) + n, err = s.sortedBuf.Read(buf) + //log.Tracef("%v read from stream %v with err %v",n, s.id,err) + return } } else { - return s.sortedBuf.Read(buf) + n, err = s.sortedBuf.Read(buf) + //log.Tracef("%v read from stream %v with err %v",n, s.id,err) + return } } @@ -86,6 +90,7 @@ func (s *Stream) Write(in []byte) (n int, err error) { // The use of RWMutex is so that the stream will not actively close // in the middle of the execution of Write. This may cause the closing frame // to be sent before the data frame and cause loss of packet. + //log.Tracef("attempting to write %v bytes to stream %v",len(in),s.id) s.writingM.RLock() defer s.writingM.RUnlock() if s.isClosed() { @@ -104,6 +109,7 @@ func (s *Stream) Write(in []byte) (n int, err error) { return i, err } n, err = s.session.sb.send(s.obfsBuf[:i], &s.assignedConnId) + //log.Tracef("%v sent to remote through stream %v with err %v",n, s.id,err) return } @@ -119,7 +125,7 @@ func (s *Stream) _close() { func (s *Stream) passiveClose() { s._close() s.session.delStream(s.id) - log.WithField("streamId", s.id).Trace("stream passively closed") + log.Tracef("stream %v passively closed", s.id) } // active close. Close locally and tell the remote that this stream is being closed @@ -153,7 +159,7 @@ func (s *Stream) Close() error { s._close() s.session.delStream(s.id) - log.WithField("streamId", s.id).Trace("stream actively closed") + log.Tracef("stream %v actively closed", s.id) return nil } @@ -162,7 +168,7 @@ func (s *Stream) Close() error { // We don't notify the remote because session.Close() is always // called when the session is passively closed func (s *Stream) closeNoDelMap() { - log.WithField("streamId", s.id).Trace("stream closed by session") + log.Tracef("stream %v closed by session", s.id) s._close() }