Skip to content

Commit 76dbf0e

Browse files
cyfdecyfcyfdecyf
committed
Collect client&server connection count, better debug message.
Some debug messages now contain "client: <remote addr>", we can group debug message by client by grep and sorting on remote addr.
1 parent 8147afc commit 76dbf0e

File tree

4 files changed

+133
-50
lines changed

4 files changed

+133
-50
lines changed

‎http.go

+2-2
Original file line numberDiff line numberDiff line change
@@ -449,7 +449,7 @@ func parseRequest(c *clientConn, r *Request) (err error) {
449449
var s []byte
450450
reader := c.bufRd
451451
// make actual timeout a little longer than keep-alive value sent to client
452-
setConnReadTimeout(c,
452+
setConnReadTimeout(c.Conn,
453453
clientConnTimeout+time.Duration(c.timeoutCnt)*time.Second, "parseRequest")
454454
// parse request line
455455
if s, err = reader.ReadSlice('\n'); err != nil {
@@ -458,7 +458,7 @@ func parseRequest(c *clientConn, r *Request) (err error) {
458458
}
459459
return err
460460
}
461-
unsetConnReadTimeout(c, "parseRequest")
461+
unsetConnReadTimeout(c.Conn, "parseRequest")
462462
// debug.Printf("Request line %s", s)
463463

464464
r.reset()

‎main.go

+2
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,8 @@ func main() {
5050
initSiteStat()
5151
initPAC() // initPAC uses siteStat, so must init after site stat
5252

53+
initStat()
54+
5355
if len(parentProxy) == 0 {
5456
info.Println("no parent proxy server, can't handle blocked sites")
5557
} else {

‎proxy.go

+82-48
Original file line numberDiff line numberDiff line change
@@ -175,23 +175,24 @@ func (py *Proxy) Serve(done chan byte) {
175175
debug.Println("client connection:", err)
176176
continue
177177
}
178-
if debug {
179-
debug.Println("new client:", conn.RemoteAddr())
180-
}
181178
c := newClientConn(conn, py)
182179
go c.serve()
183180
}
184181
}
185182

186-
func newClientConn(rwc net.Conn, proxy *Proxy) *clientConn {
183+
func newClientConn(cli net.Conn, proxy *Proxy) *clientConn {
187184
buf := httpBuf.Get()
188185
c := &clientConn{
189-
Conn: rwc,
186+
Conn: cli,
190187
serverConn: map[string]*serverConn{},
191188
buf: buf,
192-
bufRd: bufio.NewReaderFromBuf(rwc, buf),
189+
bufRd: bufio.NewReaderFromBuf(cli, buf),
193190
proxy: proxy,
194191
}
192+
if debug {
193+
debug.Printf("cli(%s) connected, total %d clients\n",
194+
cli.RemoteAddr(), incCliCnt())
195+
}
195196
return c
196197
}
197198

@@ -204,15 +205,16 @@ func (c *clientConn) releaseBuf() {
204205
}
205206
}
206207

207-
func (c *clientConn) Close() error {
208+
func (c *clientConn) Close() {
208209
c.releaseBuf()
209210
for _, sv := range c.serverConn {
210-
sv.Close()
211+
sv.Close(c)
211212
}
212213
if debug {
213-
debug.Printf("Client %v connection closed\n", c.RemoteAddr())
214+
debug.Printf("cli(%s) closed, total %d clients\n",
215+
c.RemoteAddr(), decCliCnt())
214216
}
215-
return c.Conn.Close()
217+
c.Conn.Close()
216218
}
217219

218220
func isSelfURL(url string) bool {
@@ -269,6 +271,16 @@ func (c *clientConn) shouldRetry(r *Request, sv *serverConn, re error) bool {
269271
return true
270272
}
271273

274+
func dbgPrintRq(c *clientConn, r *Request) {
275+
if dbgRq {
276+
if verbose {
277+
dbgRq.Printf("cli(%s) request %s\n%s", c.RemoteAddr(), r, r.Verbose())
278+
} else {
279+
dbgRq.Printf("cli(%s) request %s\n", c.RemoteAddr(), r)
280+
}
281+
}
282+
}
283+
272284
func (c *clientConn) serve() {
273285
var r Request
274286
var rp Response
@@ -296,7 +308,7 @@ func (c *clientConn) serve() {
296308

297309
if err = parseRequest(c, &r); err != nil {
298310
if debug {
299-
debug.Printf("client: %s parse request %v\n", c.RemoteAddr(), err)
311+
debug.Printf("cli(%s) parse request %v\n", c.RemoteAddr(), err)
300312
}
301313
if err == io.EOF || isErrConnReset(err) {
302314
return
@@ -316,13 +328,7 @@ func (c *clientConn) serve() {
316328
}
317329
// next getRequest should start with timeout count 0
318330
c.timeoutCnt = 0
319-
if dbgRq {
320-
if verbose {
321-
dbgRq.Printf("request from client %s: %s\n%s", c.RemoteAddr(), &r, r.Verbose())
322-
} else {
323-
dbgRq.Printf("request from client %s: %s\n", c.RemoteAddr(), &r)
324-
}
325-
}
331+
dbgPrintRq(c, &r)
326332

327333
if isSelfURL(r.URL.HostPort) {
328334
if err = c.serveSelfURL(&r); err != nil {
@@ -359,7 +365,7 @@ func (c *clientConn) serve() {
359365
retry:
360366
r.tryOnce()
361367
if bool(debug) && r.isRetry() {
362-
errl.Printf("%s retry request tryCnt=%d %v\n", c.RemoteAddr(), r.tryCnt, &r)
368+
errl.Printf("cli(%s) retry request tryCnt=%d %v\n", c.RemoteAddr(), r.tryCnt, &r)
363369
}
364370
if sv, err = c.getServerConn(&r); err != nil {
365371
// debug.Printf("Failed to get serverConn for %s %v\n", c.RemoteAddr(), r)
@@ -374,7 +380,7 @@ func (c *clientConn) serve() {
374380

375381
if r.isConnect {
376382
err = sv.doConnect(&r, c)
377-
sv.Close()
383+
sv.Close(c)
378384
if c.shouldRetry(&r, sv, err) {
379385
// connection for CONNECT is not reused, no need to remove
380386
goto retry
@@ -394,7 +400,9 @@ func (c *clientConn) serve() {
394400
}
395401

396402
if !r.ConnectionKeepAlive {
397-
// debug.Println("close client connection because request has no keep-alive")
403+
if debug {
404+
debug.Println("cli(%s) close connection", c.RemoteAddr())
405+
}
398406
return
399407
}
400408
}
@@ -417,7 +425,7 @@ func (c *clientConn) handleServerReadError(r *Request, sv *serverConn, err error
417425
var errMsg string
418426
if err == io.EOF {
419427
if debug {
420-
debug.Printf("client %s; %s read from server EOF\n", c.RemoteAddr(), msg)
428+
debug.Printf("cli(%s) %s read from server EOF\n", c.RemoteAddr(), msg)
421429
}
422430
return RetryError{err}
423431
}
@@ -442,6 +450,18 @@ func (c *clientConn) handleServerWriteError(r *Request, sv *serverConn, err erro
442450
return RetryError{err}
443451
}
444452

453+
func dbgPrintRep(c *clientConn, r *Request, rp *Response) {
454+
if dbgRep {
455+
if verbose {
456+
dbgRep.Printf("cli(%s) response %s %s\n%s",
457+
c.RemoteAddr(), r, rp, rp.Verbose())
458+
} else {
459+
dbgRep.Printf("cli(%s) response %s %s\n",
460+
c.RemoteAddr(), r, rp)
461+
}
462+
}
463+
}
464+
445465
func (c *clientConn) readResponse(sv *serverConn, r *Request, rp *Response) (err error) {
446466
sv.initBuf()
447467
defer func() {
@@ -476,14 +496,8 @@ func (c *clientConn) readResponse(sv *serverConn, r *Request, rp *Response) (err
476496
if _, err = c.Write(rp.rawResponse()); err != nil {
477497
return err
478498
}
479-
if dbgRep {
480-
if verbose {
481-
// extra space after resposne to align with request debug message
482-
dbgRep.Printf("response to client %v: %s %s\n%s", c.RemoteAddr(), r, rp, rp.Verbose())
483-
} else {
484-
dbgRep.Printf("response to client %v: %s %s\n", c.RemoteAddr(), r, rp)
485-
}
486-
}
499+
dbgPrintRep(c, r, rp)
500+
487501
rp.releaseBuf()
488502

489503
if rp.hasBody(r.Method) {
@@ -513,13 +527,21 @@ func (c *clientConn) readResponse(sv *serverConn, r *Request, rp *Response) (err
513527
debug.Printf("[Finished] %v request %s %s\n", c.RemoteAddr(), r.Method, r.URL)
514528
}
515529
*/
530+
var remoteAddr string // avoid evaluating c.RemoteAddr() in the following debug call
531+
if debug {
532+
remoteAddr = c.RemoteAddr().String()
533+
}
516534
if rp.ConnectionKeepAlive {
517535
if rp.KeepAlive == time.Duration(0) {
518536
sv.willCloseOn = time.Now().Add(defaultServerConnTimeout)
519537
} else {
520-
sv.willCloseOn = time.Now().Add(rp.KeepAlive - time.Second)
538+
debug.Printf("cli(%s) server %s keep-alive %v\n",
539+
remoteAddr, sv.url.HostPort, rp.KeepAlive)
540+
sv.willCloseOn = time.Now().Add(rp.KeepAlive)
521541
}
522542
} else {
543+
debug.Printf("cli(%s) server %s close connection\n",
544+
remoteAddr, sv.url.HostPort)
523545
c.removeServerConn(sv)
524546
}
525547
return
@@ -532,16 +554,17 @@ func (c *clientConn) shouldCleanServerConn() bool {
532554

533555
// Remove all maybe closed server connection
534556
func (c *clientConn) cleanServerConn() {
535-
if debug {
536-
debug.Printf("%s client clean up idle server connection", c.RemoteAddr())
537-
}
538557
now := time.Now()
539558
c.cleanedOn = now
540559
for _, sv := range c.serverConn {
541560
if now.After(sv.willCloseOn) {
542561
c.removeServerConn(sv)
543562
}
544563
}
564+
if debug {
565+
debug.Printf("cli(%s) close idle connections, remains %d\n",
566+
c.RemoteAddr(), len(c.serverConn))
567+
}
545568
}
546569

547570
func (c *clientConn) getServerConn(r *Request) (sv *serverConn, err error) {
@@ -558,7 +581,7 @@ func (c *clientConn) getServerConn(r *Request) (sv *serverConn, err error) {
558581
}
559582

560583
func (c *clientConn) removeServerConn(sv *serverConn) {
561-
sv.Close()
584+
sv.Close(c)
562585
delete(c.serverConn, sv.url.HostPort)
563586
}
564587

@@ -573,7 +596,7 @@ func connectDirect(url *URL, siteInfo *VisitCnt) (conn, error) {
573596
debug.Printf("error direct connect to: %s %v\n", url.HostPort, err)
574597
return zeroConn, err
575598
}
576-
debug.Println("connected to", url.HostPort)
599+
// debug.Println("directly connected to", url.HostPort)
577600
return conn{ctDirectConn, c, nil}, nil
578601
}
579602

@@ -588,6 +611,8 @@ func maybeBlocked(err error) bool {
588611
return isErrTimeout(err) || isErrConnReset(err)
589612
}
590613

614+
// Connect to requested server according to whether it's visit count.
615+
// If direct connection fails, try parent proxies.
591616
func (c *clientConn) connect(r *Request, siteInfo *VisitCnt) (srvconn conn, err error) {
592617
var errMsg string
593618
if config.AlwaysProxy {
@@ -662,6 +687,10 @@ func (c *clientConn) createServerConn(r *Request) (*serverConn, error) {
662687
return sv, nil
663688
}
664689
c.serverConn[sv.url.HostPort] = sv
690+
if debug {
691+
debug.Printf("cli(%s) connected to %s %d concurrent connections\n",
692+
c.RemoteAddr(), sv.url.HostPort, incSrvConnCnt(sv.url.HostPort))
693+
}
665694
// client will connect to differnet servers in a single proxy connection
666695
// debug.Printf("serverConn to for client %v %v\n", c.RemoteAddr(), c.serverConn)
667696
return sv, nil
@@ -702,14 +731,17 @@ func (sv *serverConn) initBuf() {
702731
}
703732
}
704733

705-
func (sv *serverConn) Close() error {
706-
debug.Println("Closing server conn:", sv.url.HostPort)
734+
func (sv *serverConn) Close(c *clientConn) error {
707735
sv.bufRd = nil
708736
if sv.buf != nil {
709737
// debug.Println("release server buffer")
710738
httpBuf.Put(sv.buf)
711739
sv.buf = nil
712740
}
741+
if debug {
742+
debug.Printf("cli(%s) close connection to %s remains %d concurrent connections\n",
743+
c.RemoteAddr(), sv.url.HostPort, decSrvConnCnt(sv.url.HostPort))
744+
}
713745
return sv.Conn.Close()
714746
}
715747

@@ -736,11 +768,11 @@ func (sv *serverConn) setReadTimeout(msg string) {
736768
if sv.siteInfo.OnceBlocked() && to > defaultReadTimeout {
737769
to = minReadTimeout
738770
}
739-
setConnReadTimeout(sv, to, msg)
771+
setConnReadTimeout(sv.Conn, to, msg)
740772
}
741773

742774
func (sv *serverConn) unsetReadTimeout(msg string) {
743-
unsetConnReadTimeout(sv, msg)
775+
unsetConnReadTimeout(sv.Conn, msg)
744776
}
745777

746778
func (sv *serverConn) maybeSSLErr(cliStart time.Time) bool {
@@ -851,7 +883,7 @@ func copyClient2Server(c *clientConn, sv *serverConn, r *Request, srvStopped not
851883
defer func() {
852884
if deadlineIsSet {
853885
// maybe need to retry, should unset timeout here because
854-
unsetConnReadTimeout(c, "cli->srv after err")
886+
unsetConnReadTimeout(c.Conn, "cli->srv after err")
855887
}
856888
done <- 1
857889
}()
@@ -880,7 +912,8 @@ func copyClient2Server(c *clientConn, sv *serverConn, r *Request, srvStopped not
880912
}
881913
}
882914
if debug {
883-
debug.Printf("cli->srv client %s released read buffer\n", c.RemoteAddr())
915+
debug.Printf("cli(%s)->srv(%s) released read buffer\n",
916+
c.RemoteAddr(), r.URL.HostPort)
884917
}
885918
c.releaseBuf()
886919
}
@@ -896,11 +929,11 @@ func copyClient2Server(c *clientConn, sv *serverConn, r *Request, srvStopped not
896929
for {
897930
// debug.Println("cli->srv")
898931
if sv.maybeFake() {
899-
setConnReadTimeout(c, time.Second, "cli->srv")
932+
setConnReadTimeout(c.Conn, time.Second, "cli->srv")
900933
deadlineIsSet = true
901934
} else if deadlineIsSet {
902935
// maybeFake may trun to false after timeout, but timeout should be unset
903-
unsetConnReadTimeout(c, "cli->srv before read")
936+
unsetConnReadTimeout(c.Conn, "cli->srv before read")
904937
deadlineIsSet = false
905938
}
906939
if n, err = c.Read(buf); err != nil {
@@ -942,7 +975,7 @@ func (sv *serverConn) doConnect(r *Request, c *clientConn) (err error) {
942975
// debug.Printf("%s Sending CONNECT request to http proxy server\n", c.RemoteAddr())
943976
if err = sv.sendHTTPProxyRequest(r, c); err != nil {
944977
if debug {
945-
debug.Printf("%s error sending CONNECT request to http proxy server: %v\n",
978+
debug.Printf("cli(%s) error sending CONNECT request to http proxy server: %v\n",
946979
c.RemoteAddr(), err)
947980
}
948981
return err
@@ -951,7 +984,8 @@ func (sv *serverConn) doConnect(r *Request, c *clientConn) (err error) {
951984
// debug.Printf("send connection confirmation to %s->%s\n", c.RemoteAddr(), r.URL.HostPort)
952985
if _, err = c.Write(connEstablished); err != nil {
953986
if debug {
954-
debug.Printf("%s error sending 200 Connecion established: %v\n", c.RemoteAddr(), err)
987+
debug.Printf("cli(%s) error sending 200 Connecion established: %v\n",
988+
c.RemoteAddr(), err)
955989
}
956990
return err
957991
}
@@ -963,7 +997,7 @@ func (sv *serverConn) doConnect(r *Request, c *clientConn) (err error) {
963997
go func() {
964998
// debug.Printf("doConnect: cli(%s)->srv(%s)\n", c.RemoteAddr(), r.URL.HostPort)
965999
cli2srvErr = copyClient2Server(c, sv, r, srvStopped, done)
966-
sv.Close() // close sv to force read from server in copyServer2Client return
1000+
sv.Close(c) // close sv to force read from server in copyServer2Client return
9671001
}()
9681002

9691003
// debug.Printf("doConnect: srv(%s)->cli(%s)\n", r.URL.HostPort, c.RemoteAddr())
@@ -1049,7 +1083,7 @@ func (sv *serverConn) doRequest(c *clientConn, r *Request, rp *Response) (err er
10491083
return
10501084
}
10511085
if debug {
1052-
debug.Printf("%s %s body sent\n", c.RemoteAddr(), r)
1086+
debug.Printf("cli(%s) %s request body sent\n", c.RemoteAddr(), r)
10531087
}
10541088
}
10551089
r.state = rsSent

0 commit comments

Comments
 (0)