레이블이 websocket인 게시물을 표시합니다. 모든 게시물 표시
레이블이 websocket인 게시물을 표시합니다. 모든 게시물 표시

nginx https websocket newline error

# 현상
# k8s pod 접근시 nginx https 를 경유 exec 로 접속 후 엔터를 치면 다음 처럼 prompt가 보이고
root@ysoftman-123:/aaa#
(커서) 여기서 멈춰있다., 엔터를 치면 다시 prompt가 뜨고 다시 똑같이 prompt가 보이고 커서 다음줄에 위치하는 문제가 있다.
nginx http 를 통하면 문제가 없다.

# k8s client python 를 사용 중이고
# websocket 이 연결되어 있는 동안 stdout, sterr 를 받아 출력하도록 했다.
while websocket_client.is_open():
    websocket_client.update(timeout=1)
    if websocket_client.peek_stdout():
        print(websocket_client.read_stdout(), file=sys.stdout, flush=True, end='')
    if websocket_client.peek_stderr():
        print(websocket_client.read_stderr(), file=sys.stderr, flush=True, end='')

# 테스트 환경
# nginx 가 --with-debug 로 빌드되었는지 확인
nginx -V | grep -i with-debug

# ngnix.config 에러 로그에 debug 레벨을 추가하자.
error_log  /usr/local/var/log/nginx/error.log debug;

# nginx 를 리로딩하기
sudo nginx -s reload

# 디버깅 로깅을 보면
tail -F /usr/local/var/log/nginx/error.log

# pod 접속 후 키를 입력할때마다 nginx debug 다음과 같은 로그가 찍한다.
# (엔터) 친 경우 prompt 가 출력되어야 한다.

# newline 에 커서가 가있지만 prompt 가 안뜨는 경우
2023/05/10 13:24:33 [debug] 40385#0: *58 http upstream process upgraded, fu:1
2023/05/10 13:24:33 [debug] 40385#0: *58 recv: eof:0, avail:150, err:0
2023/05/10 13:24:33 [debug] 40385#0: *58 recv: fd:15 150 of 4096
2023/05/10 13:24:33 [debug] 40385#0: *58 SSL to write: 150
2023/05/10 13:24:33 [debug] 40385#0: *58 SSL_write: 150
2023/05/10 13:24:33 [debug] 40385#0: *58 event timer: 15, old: 17342356, new: 17342362
2023/05/10 13:24:33 [debug] 40385#0: timer delta: 6
2023/05/10 13:24:33 [debug] 40385#0: worker cycle

# newline 에 prompt 정상적으로 뜨는 경우도 가끔 발생했다.
2023/05/10 13:24:50 [debug] 40385#0: *58 http upstream process upgraded, fu:1
2023/05/10 13:24:50 [debug] 40385#0: *58 recv: eof:0, avail:147, err:0
2023/05/10 13:24:50 [debug] 40385#0: *58 recv: fd:15 147 of 4096
2023/05/10 13:24:50 [debug] 40385#0: *58 SSL to write: 147
2023/05/10 13:24:50 [debug] 40385#0: *58 SSL_write: 147
2023/05/10 13:24:50 [debug] 40385#0: *58 event timer: 15, old: 17359466, new: 17359540
2023/05/10 13:24:50 [debug] 40385#0: timer delta: 2

# http 로 연결한 경우 recv 150 인데도, prompt 가 잘뜬다.
2023/05/11 13:44:27 [debug] 41253#0: *48 http upstream process upgraded, fu:1
2023/05/11 13:44:27 [debug] 41253#0: *48 recv: eof:0, avail:150, err:0
2023/05/11 13:44:27 [debug] 41253#0: *48 recv: fd:13 150 of 4096
2023/05/11 13:44:27 [debug] 41253#0: *48 send: fd:12 150 of 150
2023/05/11 13:44:27 [debug] 41253#0: *48 event timer: 13, old: 104937207, new: 104937220
2023/05/11 13:44:27 [debug] 41253#0: timer delta: 12

# 그냥 엔터만 친 경우 150(비정상), 147(정상) 의 데이터 크기 차이를 보인다.
# http 에서도 150, 147 둘다 나오는데, 둘다 prompt 가 정상적으로 출력된다.
# 데이터가 프롬프트 길이 뒤에 값이 추가되는데 https 연결상에서는 이것이 newline 으로 취급되는것으로 보인다.
# update() -> print(data) 로 추가해서
# 엔터를 쳤을대 받는 데이터를 출력해보면 
150 -> 비정상인 경우 b'\x01\r\n'
147 -> 정상인 경우 b'\x01\r\n\x1b]0;프롬프트 스트링'

# 0x1(SOH, start of heading)
# \r\n(CR:carriage-return, LF:linefeed) newline
# 0x1b]0;로 x1b(escape) 가 포함되어 있음
# http 에서는 b'\x01\r\n' 인 경우에도 b'\x01\x1b]0; 로 시작하는 prompt 응답이 온다.

# websocket python 트레이싱 해보면
enableTrace(True)

# update() -> polling 을 해서 recv 데이터를 보여주는데 여기에 b'\x01\r\n' 만 있고 prompt 데이터는 나오지 않는다.
# nginx 는 150(byte) 으로 응답했다고 하는것 같은데, ws client 는 3바이트의 newline(b'\x01\r\n')만 받고 
# 그 뒤로는 recv 데이터를 받은 것이 없다고 트레이싱 된다.
# (http 에서는 newline 이후에도 prompt 데이터를 받았다고 트레이싱 된다.)

# ws_client 소스에서 update() 부분에서 응답 패킷을 받는데
# r 체크 조건을 제거하면 https 상태에서도 prompt 데이터를 받는다.
# if r:
op_code, frame = self.sock.recv_data_frame(True)

# 결국 websocket client 데이터를 받는 r(polling)이 제대로 되지않는게 문제로 보인다.
# update() 에서 polling 없이 sock.recv_data_frame(True) 를 받을 수 있도록 하고
# peek_channel() 에서는 self.updat(timeout=timout)을 제거하니
# http, https 둘다 newline 후 prompt 가 잘 표시되었다.