Golang 의 HTTP server 502 문제 분석

16432 단어 golang
문제 도입
『 8195 』 생산 환경 Golang 서 비 스 는 가끔 502 신고 가 발생 할 수 있 습 니 다. 조사 결과 대부분이 다음 과 같은 세 가지 원인 으로 인해 발생 한 것 입 니 다.
  • http. server 는 Write Timeout 을 설정 하여 시간 초과 처 리 를 요청 하고 Golang 은 연결 을 끊 습 니 다.
  • http. server 는 IdleTimeout 을 설정 하고 게 이 트 웨 이와 Golang 사이 에 긴 연결 을 사용 하 며 Golang 은 연결 을 끊 습 니 다.
  • Golang 서비스 에 패 닉 이 나 타 났 다.

  • 『 8195 』 세 번 째 케이스 는 매우 간단 하 므 로 본 고 는 앞의 두 가지 케이스 뒤의 심층 원인 을 중점적으로 분석 할 것 이다.
    요청 링크 는 클 라 이언 트 = = > Nginx = = > Golang
    WriteTimeout
        Golang sdk 의 주석 은 "Write Timeout is the maximum duration before timing out writes of the response" 라 고 설명 합 니 다.http. server 는 클 라 이언 트 요청 을 읽 을 때 시간 초과 시간 을 설정 합 니 다.
    func (c *conn) readRequest(ctx context.Context) (w *response, err error) {
        if d := c.server.WriteTimeout; d != 0 {
            defer func() {
                c.rwc.SetWriteDeadline(time.Now().Add(d))
            }()
        }
    }

        분명히 요청 처리 시간 이 Write Timeout 을 초과 하면 시간 초과 현상 이 발생 할 수 있다.왜 시간 을 초과 하면 502 가 나 옵 니까?
    작은 실험
    『 8195 』 우 리 는 먼저 다음 과 같은 요청 처리 시간 초과 현상 을 모 의 한다.
    package main
    
    import (
        "net/http"
        "time"
    )
    
    type GinHandler struct {
    }
    
    func (* GinHandler) ServeHTTP(w http.ResponseWriter, r *http.Request){
        time.Sleep(time.Duration(5) * time.Second)
        w.Write([]byte("hello golang"))
    
    }
    
    
    func main() {
        server := &http.Server{
            Addr:"0.0.0.0:8080",
            Handler: &GinHandler{},
            ReadTimeout: time.Second * 3,
            WriteTimeout: time.Second *3,
        }
    
        server.ListenAndServe()
    }

    요청 결 과 는 다음 과 같 습 니 다.
    time  curl http://127.0.0.1/test -H "Host:test.xueersi.com"
    
    502 Bad Gateway
    
    real    0m5.011s

        Nginx 의 오류 로 그 를 보면 상류 에서 주동 적 으로 연결 을 닫 아서 생 긴 것 을 볼 수 있 습 니 다.
    2020/08/12 21:18:07 [error] 30217#0: *8105 upstream prematurely closed connection while reading response header from upstream, client: 127.0.0.1, server: test.xueersi.com, request: "GET /test HTTP/1.1", upstream: "http://127.0.0.1:8080/test", host: "test.xueersi.com"

    예.curl 명령 실행 시간 은 5 초 입 니 다. 이 는 5 초 후에 Golang 서비스 가 연결 을 끊 었 다 는 뜻 입 니 다. Write Timeout = 3 초 를 설정 하지 않 았 습 니까?왜 3 초 초과 시간 에 끊 기지 않 고 5 초 후에 끊 어 집 니까?
    Write Timeout 뭐 했 어 요?
        우 리 는 이 줄 의 프로그램 에서 답 을 찾 습 니 다. c. rwc. SetWrite Deadline.이곳 의 rwc 유형 은 net. Conn 으로 인터페이스 입 니 다.진정한 대상 은 l. Accept () 에서 돌아 오고 l 은 대상 TCPListener 입 니 다.아래 를 추적 해 보면 net. TCPConn 대상 을 만 들 었 고 이 대상 은 net. conn 을 계승 하 였 으 며, net. conn 은 net. Conn 인터페이스 (대소 문자 주의) 를 실현 하 였 습 니 다.
    type TCPConn struct {
        conn
    }
    
    type conn struct {
        fd *netFD
    }
    
    func (c *conn) SetReadDeadline(t time.Time) error {
        
        if err := c.fd.SetReadDeadline(t); err != nil {
            
        }
    }

        다시 아래로 추적 하면 호출 체인 은 다음 과 같 습 니 다.
    net.(c *conn).SetWriteDeadline()
        net.(fd *netFD).SetWriteDeadline()
            poll.(fd *FD).SetWriteDeadline()
                poll.setDeadlineImpl()
                    poll.runtime_pollSetDeadline()

        여기까지 쫓 아 오 면 쫓 아 갈 수 없다 는 걸 알 게 될 거 야, runtimepollSetDeadline 의 실현 논 리 는 무엇 입 니까?전역 검색 소 pollSetDeadline, runtime / netpoll. go 파일 을 찾 을 수 있 습 니 다.
    //go:linkname poll_runtime_pollSetDeadline internal/poll.runtime_pollSetDeadline
    func poll_runtime_pollSetDeadline(pd *pollDesc, d int64, mode int) {
    }

    네트워크 설명 자 를 봉인 하 는 데 사 용 됩 니 다. 주로 이 몇 개의 필드 에 관심 을 가 져 야 합 니 다.
    type pollDesc struct {
        fd      uintptr
    
        rg      uintptr // pdReady, pdWait, G waiting for read or nil
        rt      timer   // read deadline timer (set if rt.f != nil)
        rd      int64   // read deadline
        
        wg      uintptr // pdReady, pdWait, G waiting for write or nil
        wt      timer   // write deadline timer
        wd      int64   // write deadline
    }

    * 8195 ° rt 는 현재 설명자 의 읽 기 타이머 입 니 다. rt 는 현재 설명자 에 읽 기 타이머 의 시간 초과 시간 을 설정 하 였 습 니 다.rg 는 세 개의 값 을 취 할 수 있 습 니 다. 1) pdReady 는 이 설명 자 를 읽 을 수 있 는 상태 에 있 음 을 표시 합 니 다.2) pdWait 는 이 설명자 가 막 혀 서 바 꿀 준비 가 되 어 있 음 을 나타 낸다.3) G, 포인터, 막 힌 협 정 대상 을 가리킨다.
        함수 pollruntime_pollSetDeadline 은 읽 기 / 쓰기 시간 초과 에 따라 타 이 머 를 추가 하고 리 셋 함 수 를 설정 합 니 다.
    //       
    pd.wt.f = netpollWriteDeadline
    //      ,           
    pd.wt.arg = pd

    『 8195 』 우리 의 문 제 는 곧 밝 혀 질 것 입 니 다. 리 셋 함수 netpoll Write Deadline (통일 은 netpolldeadlineimpl 로 이 루어 집 니 다) 가 무엇 을 했 는 지 분석 하면 Write Timeout 이 무엇 인지 알 수 있 습 니 다.
    func netpolldeadlineimpl(pd *pollDesc, seq uintptr, read, write bool) {
        if write {
            pd.wd = -1
            atomic.StorepNoWB(unsafe.Pointer(&pd.wt.f), nil) 
            wg = netpollunblock(pd, 'w', false)
        }
        
        if wg != nil {
            netpollgoready(wg, 0)
        }
    }

    * 8195 에서 볼 수 있 습 니 다. pd. wd = - 1 을 설정 하고 이 설명자 의 타이머 가 만 료 되 었 는 지 여 부 를 판단 합 니 다.netpollunblock 과 netpollgoready 는 현재 설명자 가 막 혀 있 는 지 여 부 를 판단 하 는 데 사 용 됩 니 다. 이 상 태 를 실행 가능 한 상태 로 설정 하고 실행 가능 한 대기 열 에 추가 합 니 다.안 그러면 아무것도 안 해.
        이제 모든 것 을 알 게 되 었 습 니 다. Write Timeout 은 읽 기와 쓰기 시간 초과 타이머 만 추 가 했 을 뿐 타이머 가 만 료 되 었 을 때 도 이 설명 자 를 설정 하여 읽 기와 쓰기 시간 초 과 를 설정 할 뿐 입 니 다.따라서 요청 처리 시간 이 Write Timeout 설정 의 시간 초과 시간 보다 5 초 라 도 이 요청 은 중단 되 지 않 고 끝 날 때 까지 정상적으로 실 행 됩 니 다. 클 라 이언 트 에 결 과 를 되 돌려 줄 때 이상 이 발생 합 니 다.
    마지막 으로 dlv 디 버 깅 을 통 해 Write Timeout 을 설정 한 함수 호출 체인 을 인쇄 합 니 다.
    0  0x0000000001034c23 in internal/poll.runtime_pollSetDeadline
       at /usr/local/go/src/runtime/netpoll.go:224
    1  0x00000000010ee3a0 in internal/poll.setDeadlineImpl
       at /usr/local/go/src/internal/poll/fd_poll_runtime.go:155
    2  0x00000000010ee14a in internal/poll.(*FD).SetReadDeadline
       at /usr/local/go/src/internal/poll/fd_poll_runtime.go:132
    3  0x00000000011cc868 in net.(*netFD).SetReadDeadline
       at /usr/local/go/src/net/fd_unix.go:276
    4  0x00000000011dffca in net.(*conn).SetReadDeadline
       at /usr/local/go/src/net/net.go:251
    5  0x000000000131491f in net/http.(*conn).readRequest
       at /usr/local/go/src/net/http/server.go:953
    6  0x000000000131bd5a in net/http.(*conn).serve
       at /usr/local/go/src/net/http/server.go:1822

    작은 사고: 바 텀 설명자 의 읽 기와 쓰기 시간 초과 사건 이 발생 한 후에 왜 이 설명 자 를 직접 닫 지 않 고 표시 만 합 니까?
    502 이렇게 왔어요.
    이번 에는 간단하게 추적 할 필요 가 없어 요.방금 시간 초과 설정 은 poll. (fd FD). setWrite Deadline 을 호출 합 니 다. FD 는 바 텀 설명자 pollDesc 를 추가 로 봉 인 했 습 니 다. 읽 기와 쓰기 처리 함 수 를 제공 합 니 다.우 리 는 poll. (fd FD). Write 중단 점:
    (dlv) b poll.Write
    Breakpoint 1 set at 0x10ef40b for internal/poll.(*FD).Write() /usr/local/go/src/internal/poll/fd_unix.go:254
    
    (dlv) bt
    0  0x00000000010ef40b in internal/poll.(*FD).Write
       at /usr/local/go/src/internal/poll/fd_unix.go:254
    1  0x00000000011cc0ac in net.(*netFD).Write
       at /usr/local/go/src/net/fd_unix.go:220
    2  0x00000000011df765 in net.(*conn).Write
       at /usr/local/go/src/net/net.go:196
    3  0x000000000132276c in net/http.checkConnErrorWriter.Write
       at /usr/local/go/src/net/http/server.go:3434
    4  0x0000000001177e91 in bufio.(*Writer).Flush
       at /usr/local/go/src/bufio/bufio.go:591
    5  0x000000000131a329 in net/http.(*response).finishRequest
       at /usr/local/go/src/net/http/server.go:1594
    6  0x000000000131c7c5 in net/http.(*conn).serve
       at /usr/local/go/src/net/http/server.go:1900

        지난 절 에서 말 한 바 와 같이 요청 처리 가 완 료 된 후에 시간 이 초과 되 더 라 도 상부 업 무 는 응답 결 과 를 쓰 려 고 시도 하고 최종 적 으로 pollDesc 가 시간 을 초과 하여 오 류 를 되 돌려 주 고 상부 업 무 는 연결 을 닫 는 것 으로 판단 합 니 다.
    poll.(fd *FD).Write
        poll.(pd *pollDesc).prepareWrite
            poll.(pd *pollDesc).prepare
                poll.runtime_pollReset

        함수 runtimepollReset 의 실현 논 리 는 runtime / netpoll. go 파일 에 있 습 니 다.netpollchecker 를 통 해 검사 논 리 를 실현 합 니 다:
    //go:linkname poll_runtime_pollReset internal/poll.runtime_pollReset
    func poll_runtime_pollReset(pd *pollDesc, mode int) int {
    }
    
    func netpollcheckerr(pd *pollDesc, mode int32) int {
        if pd.closing {
            return 1 // ErrFileClosing or ErrNetClosing
        }
        if (mode == 'r' && pd.rd < 0) || (mode == 'w' && pd.wd < 0) {
            return 2 // ErrTimeout
        }
        ……
        return 0
    }

          하부 쓰기 데이터 반환 오류, 상부 http. (c * conn). serve 방법 은 직접 되 돌아 가 고 돌아 가기 전에 defer 를 실행 하여 마무리 작업 을 합 니 다. 예 를 들 어 연결 을 닫 는 것 입 니 다.
    시간 을 초과 하면 어떻게 제어 합 니까?
        위의 분석 을 참조 하여 Write Timeout 을 통 해 요청 한 시간 초과 시간 을 제어 하고 두 가지 문제 가 존재 합 니 다. 1) 요청 처리 시간 초과 후 Golang 은 연결 을 끊 고 Nginx 는 502 가 나타 납 니 다.2) 요청 은 Write Timeout 시간 초과 로 중단 되 지 않 습 니 다. 요청 이 완 료 될 때 까지 기 다 려 야 합 니 다. 클 라 이언 트 가 응답 을 기다 리 는 시간 이 비교적 깁 니 다.느 린 요청 이 많 을 때 Golang 서비스 자원 의 점용 이 급 격 히 증가 합 니 다.
        그렇다면 시간 초과 상황 을 어떻게 우아 하 게 통제 할 수 있 을 까?시간 이 지나 면 Golang 은 현재 요청 을 종료 하고 클 라 이언 트 에 게 기본 결 과 를 되 돌려 줍 니 다.context. context 를 이용 하여 구현 할 수 있 습 니 다. 이것 은 인터페이스 입 니 다. cancelCtx 가 취소 할 수 있 는 컨 텍스트, timerCtx 가 정시 에 취소 할 수 있 는 컨 텍스트, valueCtx 는 컨 텍스트 를 기반 으로 변 수 를 전달 할 수 있 습 니 다.
    * 8195 ° context. context 정 의 는 다음 과 같 습 니 다.
    type Context interface {
    
        Deadline() (deadline time.Time, ok bool)
    
        Done() 
  • Deadline: 현재 context 에 연 결 된 작업 이 취 소 된 마감 시간 을 되 돌려 줍 니 다.설정 이 없 으 면 ok = false 로 돌아 갑 니 다.
  • Done: 현재 context 를 연결 하 는 작업 이 취소 되면 닫 힌 channel 로 돌아 갑 니 다.그렇지 않 으 면 nil 로 돌아 가기;
  • Err: Done 이 되 돌아 오 는 channel 이 닫 혔 을 때 비 어 있 는 값 으로 돌아 가 작업 이 끝 난 이 유 를 표시 합 니 다.
  • Value 는 context 에 저 장 된 키 값 이 현재 key 에 대응 하 는 값 을 되 돌려 주 고 해당 하 는 key 가 없 으 면 nil 로 되 돌려 줍 니 다.

  • 『 8195 』 다음 에 작은 예 를 들 어 보 겠 습 니 다.
    ctx := context.Background()
    ctx, cancel := context.WithCancel(ctx)
    
    go Proc()
    
    time.Sleep(time.Second)
    cancel()
    
    
    func Proc(ctx context.Context)  {
        for {
            select {
            case 

    더 많은 context. context 의 소 개 는 이 두 편의 글 을 참고 합 니 다.
  • Golang 의 context 를 깊이 이해: https://zhuanlan.zhihu.com/p/...
  • 오늘 톱기사 Go 건 천 억 급 마이크로 서비스의 실천: https://36kr.com/p/1721518997505
  • 작은 확장
    『 8195 』 Write Timeout 으로 인 한 502 에 대해 우 리 는 이미 명확 하 게 분석 했다. 마지막 으로 우 리 는 협 정 이 읽 기와 쓰기 가 막 혀 서 발생 하 는 전환 절 차 를 다시 확대 했다.
    for {
            n, err := syscall.Read(fd.Sysfd, p)
            if err != nil {
                n = 0
                if err == syscall.EAGAIN && fd.pd.pollable() {
                    if err = fd.pd.waitRead(fd.isFile); 
                }
                ……
            }
        }
        
        
    poll.(fd *FD).Read
        poll.(pd *pollDesc).waitRead
            poll.(pd *pollDesc).wait
                poll.runtime_pollWait

        함수 runtimepollWait 의 실현 논 리 는 runtime / netpoll. go 파일 에 있 습 니 다.netpollblock 을 통 해 협 정 차단 논 리 를 실현 합 니 다.
    //go:linkname poll_runtime_pollWait internal/poll.runtime_pollWait
    func poll_runtime_pollWait(pd *pollDesc, mode int) int {
    }
    
    func netpollblock(pd *pollDesc, mode int32, waitio bool) bool {
        ……
        if waitio || netpollcheckerr(pd, mode) == 0 {
            gopark(netpollblockcommit, unsafe.Pointer(gpp), waitReasonIOWait, traceEvGoBlockNet, 5)
        }
    }

    IdleTimeout + 긴 연결
    * 8195: Golang sdk 의 설명 은 다음 과 같 습 니 다.
      "IdleTimeout is the maximum amount of time to wait for the next request when keep-alives are enabled. If IdleTimeout is zero, the value of ReadTimeout is used. If both are zero, there is no timeout"。
    * 8195: 게 이 트 웨 이 Nginx 와 상류 Golang 서비스 간 에 keep - alive 긴 연결 을 사용 할 때 만 이 설정 이 적 용 됩 니 다.특히 주의해 야 할 것 은 IdleTimeout 이 0 이면 ReadTimeout 의 값 을 기본 값 으로 가 져 옵 니 다.
        주의: Nginx 는 proxy 를 통과 하고 있 습 니 다.pass 에서 리 트 윗 을 설정 할 때 기본적으로 HTTP 1.0 을 사용 하고 'Connection: close' 를 사용 합 니 다.따라서 다음 설정 을 추가 해 야 긴 연결 을 사용 할 수 있 습 니 다.
    proxy_http_version 1.1;
    proxy_set_header Connection "";

    작은 실험
        이 장면 에서 502 에 확률 문제 가 존재 하 는데 상류 Golang 서비스 가 연결 을 닫 고 새로운 요청 과 거의 동시에 발생 할 때 만 나타 날 수 있 습 니 다.따라서 결국 tcpdump 스냅 백 을 통 해 Golang 서버 가 연결 을 닫 는 것 을 관찰 합 니 다.
    『 8195 』 주의: 이런 장면 은 뚜렷 한 특징 이 있 습 니 다. upstreamresponse_time 은 0 에 가깝다.
    * 8195: 게 이 트 웨 이 Nginx 에서 Golang 서비스 사이 에 긴 연결 을 사용 하고 IdleTimeout = 5 초 를 설정 하 는 것 을 기억 합 니 다.한 번 만 요청 합 니 다. tcpdump 패키지 관찰 현상 은 다음 과 같 습 니 다.
    15:15:03.155362 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [S], seq 3293818352, win 43690, length 0
    01:50:36.801131 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [S.], seq 901857004, ack 3293818353, win 43690, length 0
    15:15:03.155385 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [.], ack 1, win 86, length 0
    15:15:03.155406 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [P.], seq 1:135, ack 1, win 86, length 134: HTTP: GET /test HTTP/1.1
    15:15:03.155411 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [.], ack 135, win 88, length 0
    15:15:03.155886 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [P.], seq 1:130, ack 135, win 88, length 129: HTTP: HTTP/1.1 200 OK
    15:15:03.155894 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [.], ack 130, win 88, length 0
    
    //IdleTimeout 5    ,Golang        
    15:15:08.156130 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [F.], seq 130, ack 135, win 88, length 0
    15:15:08.156234 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [F.], seq 135, ack 131, win 88, length 0
    15:15:08.156249 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [.], ack 136, win 88, length 0

        Golang 서비스 가 자발적으로 연결 을 끊 으 면 게 이 트 웨 이 Nginx 가 502 가 발생 할 가능성 이 있 습 니 다.이 문 제 를 어떻게 해결 합 니까?매번 게 이 트 웨 이 Nginx 가 자발적으로 연결 을 끊 는 다 는 보장 만 있 으 면 됩 니 다.
      ngx_http_upstream_module 모듈 은 새 버 전에 설정 파 라 메 터 를 추가 하 였 습 니 다. keepalivetimeout。이것 은 ngx 가 아 닙 니 다.http_core_module 모듈 에 있 는 두 매개 변수 이름 은 같 지만 용 도 는 다 릅 니 다.
    Syntax:    keepalive_timeout timeout;
    Default:    
    keepalive_timeout 60s;
    Context:    upstream
    This directive appeared in version 1.15.3.
    
    Sets a timeout during which an idle keepalive connection to an upstream server will stay open.

        Golang 서비스 가 설정 한 IdleTimeout 이 이곳 의 keepalive 보다 크 면timeout 하면 됩 니 다.
    소스 코드 분석
    전체 처리 과정 은 http. (c * conn). serve 방법 이 고 논 리 는 다음 과 같다.
    func (c *conn) serve(ctx context.Context) {
        defer func() {
            //         
            c.close()
        }()
        
        //    
        for {
            //   
            w, err := c.readRequest(ctx)
            //    
            serverHandler{c.server}.ServeHTTP(w, w.req)
            //  
            w.finishRequest()
            
            //    keepalive,     
            if !w.conn.server.doKeepAlives() {
                return
            }
            
            if d := c.server.idleTimeout(); d != 0 {
                //        idleTimeout
                c.rwc.SetReadDeadline(time.Now().Add(d))
                
                //   , idleTimeout   ,    
                if _, err := c.bufr.Peek(4); err != nil {
                    return
                }
            }
        
            //       ,  ReadTimeout
            c.rwc.SetReadDeadline(time.Time{})
        }
    
    }

        읽 기 시간 초과 가 idleTimeout 으로 설 정 된 후에 다시 연결 에서 데 이 터 를 읽 는 것 을 볼 수 있 습 니 다. 이때 현재 협 정 을 막 을 수 있 습 니 다.시간 이 초과 되면 읽 기 동작 이 오 류 를 되 돌려 줍 니 다. 이 때 serve 방법 은 되 돌아 오기 전에 이 연결 을 닫 습 니 다.
    panic
        panic 은 프로그램의 이상 종 료 를 초래 하고 Golang 서비스 가 모두 종료 되 며 Nginx 는 순간 대량의 502 가 발생 할 것 입 니 다.대응 하 는 것 은 recover 를 통 해 이상 을 포착 하고 프로그램의 실행 을 회복 할 수 있 습 니 다.
    『 8195 』 생산 환경 은 요청 입구 에 recover 를 더 하 는 것 이 좋 습 니 다.
    defer func() {
        if err := recover(); err != nil {
            //     
            stack := stack(3)
            //      
            httprequest, _ := httputil.DumpRequest(c.Request, false)
            logger.E("[Recovery]", " %s panic recovered:
    %s
    %s
    %s", time.Now().Format("2006/01/02 - 15:04:05"), string(httprequest), err, stack) c.AbortWithStatus(500) } }()

    또한 HTTP 처리 handler 의 경우 패 닉 이 나타 나 고 recover 가 없 을 때 Golang sdk 는 recover 논 리 를 제공 합 니 다. Golang sdk 는 연결 을 간단하게 닫 을 뿐 이 고 이 처리 역시 Nginx 를 502 로 되 돌려 줍 니 다.
    func (c *conn) serve(ctx context.Context) {
        defer func() {
            if err := recover(); err != nil && err != ErrAbortHandler {
                const size = 64 << 10
                buf := make([]byte, size)
                buf = buf[:runtime.Stack(buf, false)]
                c.server.logf("http: panic serving %v: %v
    %s", c.remoteAddr, err, buf) } if !c.hijacked() { c.close() c.setState(c.rwc, StateClosed) } }() }

    좋은 웹페이지 즐겨찾기